Forum Rule: Always post complete source code & details to reproduce any issue!
Results 1 to 5 of 5

Thread: Teensy 4.1 SD logging (SDfat) occasional huge spikes in time.

  1. #1

    Teensy 4.1 SD logging (SDfat) occasional huge spikes in time.

    Hi all, I have an application that writes out a logfile entry every time a button is pressed (essentially) and I have noticed that I was getting odd delays and timers out of sync occasionally so I added a few basic tests for time taken for various parts of the code and seem to have found that occasionally the logentry() is taking many orders of magnitude more than usual (which is causing issues). I pulled the example code which functionally worked but now I wonder if I am using a really suboptimal SD solution for the T4.1. The card is a Sandisk 16G extreme.

    Here's a little bit of the output, and the (hopefully appropriate) code snippet is below.

    This is normal, expected operation - output from Serial monitor with timestamps. each write is separated by around 20 seconds and takes about 3.5ms

    Code:
    07:10:09.056 -> START PRESSED : 07:10:11.386777 Mon 26 Jul 2021 NZST
    07:10:09.056 -> Updating CStime log file : 20210726-062133-cstimer.txt - Took 3400us
    07:10:29.039 -> FINISH PRESSED : 07:10:31.386998 Mon 26 Jul 2021 NZST
    07:10:29.039 -> Updating CStime log file : 20210726-062133-cstimer.txt - Took 3418us
    07:10:29.039 -> Car#   0  - Time: 0:20.000 (221)
    07:10:49.046 -> START PRESSED : 07:10:51.387219 Mon 26 Jul 2021 NZST
    07:10:49.046 -> Updating CStime log file : 20210726-062133-cstimer.txt - Took 3458us
    07:11:09.029 -> FINISH PRESSED : 07:11:11.387439 Mon 26 Jul 2021 NZST
    07:11:09.076 -> Updating CStime log file : 20210726-062133-cstimer.txt - Took 3456us
    07:11:09.076 -> Car#   0  - Time: 0:20.000 (220)
    However occasionally things go haywire...

    Code:
    07:12:09.049 -> START PRESSED : 07:12:08.388102 Mon 26 Jul 2021 NZST
    07:12:13.124 -> Updating CStime log file : Updating CStime log file : 20210726-062133-cstimer.txt - Took 4068583us
    07:12:29.059 -> FINISH PRESSED : 07:12:25.388323 Mon 26 Jul 2021 NZST
    07:12:33.133 -> Updating CStime log file : Updating CStime log file : 20210726-062133-cstimer.txt - Took 4068599us
    07:12:33.133 -> Car#   0  - Time: 0:17.000 (221)
    07:12:33.133 -> TIME DOES NOT MATCH
    07:12:49.059 -> START PRESSED : 07:12:42.388544 Mon 26 Jul 2021 NZST
    07:12:53.137 -> Updating CStime log file : Updating CStime log file : 20210726-062133-cstimer.txt - Took 4068642us
    07:13:09.017 -> FINISH PRESSED : 07:12:59.388765 Mon 26 Jul 2021 NZST
    07:13:13.094 -> Updating CStime log file : Updating CStime log file : 20210726-062133-cstimer.txt - Took 4068630us
    07:13:13.094 -> Car#   0  - Time: 0:17.000 (221)
    07:13:13.094 -> TIME DOES NOT MATCH
    Here the function is taking over 4 seconds to complete(!)

    This is breaking my timing unfortunately - at least I have found a likely cause for the problem though.

    Questions:
    - Is there a higher performance option for SD support on the T4.1?
    - Is the method I am using likely to be blocking execution of interrupt driven functions?
    - Am I missing a best practice for logging to avoid this sort of issue?

    Hopefully the code below is enough to give context - the entire program is 3000 lines so pasting it is not appropriate. If necessary I will try and create a small program to replicate the issue but I am hoping this is a known (to others) issue and this might be enough

    Code:
    SdFs sd;
    FsFile logFile;
    
    [snip - now in setup]
      // Init SD card
      timelogging = false;
      if (!sd.begin(SdioConfig(FIFO_SDIO))) {
        DEBUG_CS.println("SD card begin failed");
        sdlogging = false;
        testlogging = false;
      } else {
        DEBUG_CS.println("FIFO SDIO mode for SD card enabled.");
        sdlogging = true;
      }
    [snip - next is the function]
    
    void logentry() {
      if (logFile.open(filename, O_WRITE | O_APPEND )) {
        int logtimestart = micros();
        logFile.print(timestampcount);
        logFile.print(", ");
        logFile.print( timestamps[timestampcount].pulsetime );
        logFile.print(", ");
        logFile.print( timestamps[timestampcount].pulsems );
        logFile.print(", ");
        logFile.print( timestamps[timestampcount].sats );
        logFile.print(", ");
        logFile.print(mv);
        logFile.print(", ");
        logFile.print(err);
        logFile.print(", ");
        logFile.print(period);
        logFile.println();
        logFile.close();
        DEBUG_CS.print("Updating CStime log file : ");
        DEBUG_CS.print(filename);
        DEBUG_CS.print(" - Took ");
        DEBUG_CS.print(micros() - logtimestart);
        DEBUG_CS.println("us");
      } else {
        DEBUG_CS.print("Error opening LOGENTRY ");
        DEBUG_CS.print(filename);
        DEBUG_CS.println(" for updating");
        sdlogging = false;
      }
    }
    Cheers - Neil G

  2. #2
    Edit - have just found reference in further searching to SD changes in TD1.53 vs 1.54 and I am using 1.53. Will upgrade now and see if the issue persists.
    Cheers - N

  3. #3
    Senior Member
    Join Date
    Jul 2014
    Posts
    3,318
    upgrading to TD1.54 will indeed improve SD write performance, especially when formatted with exFAT.
    However, according to uSD specifications, you must expect (infrequent) delays up to well over 150 ms.
    this is due to the time the uSD internal processor needs for bad-block management and wear-levelling.

    Using a small FAT32 formatted uSD card, you can find additional significant delays due to FAT operations (searching for free clusters etc).
    using always freshly formatted uSD cards, preferable formatted with exFAT, is therefor a must.

  4. #4
    Thankyou for confirming that... I am fine with 150, 200, even 250ms on occasion, it's just my code wasn't taking into consideration 4 seconds of blocked execution!

    Since switching to TD1.54 I haven't seen the same issue occur - the times are all still around 3.5ms with maybe 1 in 50 being 7ms... I haven't seen anything above 10ms yet (although I am real world testing it in my code and trials only occur every 20 seconds so haven't thrashed it)

    I have since found a very odd situation which I think was related to my downstream issue where a time_t variable changes during execution despite REMOVING all of the assignment commands from the loop! That has been 'fixed' by allocating 3 time_t variables and using only the middle one so I am looking for how I am stamping on the memory now. I wish for a debugger that could show me where the variable actually changes!

    Thanks for the response - TD1.54 seems to have addressed my stated issue.

    Cheers - N

  5. #5
    Senior Member BriComp's Avatar
    Join Date
    Apr 2014
    Location
    Cheltenham, UK
    Posts
    416
    Quote Originally Posted by Talkiet View Post
    ....I wish for a debugger that could show me where the variable actually changes!
    Try Visual Micro.
    I use it all the time...and it's possible to switch seamlessly between Visual Micro/Visual Studio and the Arduino IDE

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •