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
However occasionally things go haywire...
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
Cheers - Neil G
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 MATCHHere 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
