SD Card Write Speed Patterns

B

Berollos

Member
I've been experimenting with the TeensySdioLogger example in the SdFat library on the suggestion of joepasquariello in a couple of threads e.g. Best Teensy for a datalogger, Fastest Way to Log to SD Card. Here are some details:
  • Teensy 4.1
  • using the in-built SD card with a 32GB SDSQXCG-032G-GN6MA
  • ring buffer of ~400 KB
  • maximum log file size of 600 MB
  • data logging interval of 100 us
  • approx. 1.8 KB bytes for each new data log line
  • performing rb.sync() approximately every 4KB (guessing this is the optimized equivalent to flush() which I have been using until now)
The rb.sync() operation therefore syncs the data every 3rd loop, and on average takes about 130 us to perform, which I am very happy with.

However I notice that after every 4 MB, I get a spike in sync() time to around 1-2 ms. Every 32 MB, I get a larger spike in sync() time to around 6-10 ms. Sometimes the 32 MB and 4 MB spikes line up with each other, other times not.

Here's an example of when the 4 MB and 32 MB spikes line up (this was a 588 MB total size):

1718599654087.png


And here is an example of when the 4 MB and 32 MB spikes don't line up (this was about 146 MB total size):

1718599564936.png


I am trying to work out why this is happening. I can't see anything in the TeensySdioLogger example that would cause this behavior. Perhaps something in another library?

I considered whether it is some SD card configuration thing that causes this behavior, like a boundary that the data is saved across. This is territory I am not familiar with. I tried to find numbers in the specs that would sort of line up with these boundaries. An SD card has a Cylinder/Head/Sector (CHS) code that I think is a throwback to hard drives, and I found this SD card has a CHS code of 3880, 255, 63 (found using Testdisk). If these numbers related to physical things, each cylinder would be ~8MB, track would be ~32 MB, and head ~125 MB. So maybe each track boundary are the 32 MB spikes, but still no idea what the 4 MB spikes are. I could very well be barking up the wrong tree here as I don't think the CHS means anything anymore, but that was my best attempt at finding something that lines up with these spikes.

The write speeds are more or less within the range found by joepasquariello (Fastest Way to Log to SD Card). I'm not trying to eliminate these spikes, but I definitely want consistency. If these are a fact of life, then that is fine, but I would like to know if they are consistent. A large part of that is knowing why they happen.

Any ideas?
 
Berollos said:
some SD card configuration thing
Click to expand...
Nothing concrete - but general observation from prior notes suggest indeed the SD hardware/controller system does housekeeping with some 'regularity' that takes a larger time period, and it seems this may be what is being recorded.

Was the file space pre-allocated? Some time may be used updating directory data records. Is the file left open for the duration or toggled open/close with some regularity?
 
Yes, the file space is pre-allocated. The file is left open for the duration, then truncated and closed at the end of logging.

Interesting about the housekeeping. Any clues where those kind of functions might be defined?
 
Berollos said:
I considered whether it is some SD card configuration thing that causes this behavior, like a boundary that the data is saved across.
Click to expand...
Flash memory has programmable blocks (the minimum amount of data that can be written in one operation) and erasable blocks (the minimum amount of data that can be erased in one operation, required before it can be written). So the rough "shape" of the peaks lines up as expected - where you are crossing/spanning a boundary, there will be a delay while the appropriate operation is done - but the values seem significantly off. The program size should only be around 4kb and the erase size is usually around 1MB, maybe 2MB at the most.
 
Thanks jmarsh. I did some googling based on that and found this reddit post: Minimizing microSD block rewrites and erasures when datalogging

They talk about erase blocks being 4 MB for a couple of SD cards, and 512-byte or 4 k write blocks. So the block erasure could conceivably account for the spikes every 4MB transfer. Not sure that either erasure or programming would account for the spikes every 32 MB though.

I wonder if it is possible to perform some sort of blanket erasure on the SD card first to avoid the 4MB spikes.
 
rb.sync() simply calls file.write() with however many bytes are in the RingBuf. The point of having the RingBuf is to allow your loop() to write in chunks of 512 bytes, and avoid writing when the SD is busy. If you always write in 512 byte chunks, you should never see these 1-2 ms delays, assuming you have preAllocated the file. From my perspective, rb.sync() should only be called when you're done logging and want to write any remaining bytes to the file, e.g. before closing the file.
 
joepasquariello said:
rb.sync() simply calls file.write() with however many bytes are in the RingBuf. The point of having the RingBuf is to allow your loop() to write in chunks of 512 bytes, and avoid writing when the SD is busy. If you always write in 512 byte chunks, you should never see these 1-2 ms delays, assuming you have preAllocated the file. From my perspective, rb.sync() should only be called when you're done logging and want to write any remaining bytes to the file, e.g. before closing the file.
Click to expand...
If you are doing any kind of long-term logging, you definitely want to do a sync() call at regular intervals. The time between sync() calls is based on the amount of data you are willing to lose if the batteries die or mechanical shock causes a power glitch and reboot. For long-term oceanographic loggers (2.5KB/second for six months) I would start a new file once per day and call sync() at 5-10 minute intervals. Thus, if ship schedules delayed a mooring pickup, we would lose only the last 5-10 minutes of data when the batteries died, not the whole last day. These loggers used primary lithium cells and monitoring battery pack voltages did not give a lot of warning of imminent battery failure.


4MB erase block sizes show up on a lot of uSD cards of 16GB or larger. Given these large blocks and longer erase times, our policy was to start each moored logging session with a new 64 or 128GB SD card.

The downside of a few hundred sync() operations per day is the added wear on the directory sectors. I don't know how the card controllers cope with the extra load on directory sectors. Perhaps they do something like the emulated EEPROM on the T4.X, where changes are written to a pool of allocation blocks in sequence.
 
You're talking about file.sync(). The OP is talking about rb.sync(), which is part of SdFat's RingBuf class. It's not a file system sync().
 
joepasquariello said:
You're talking about file.sync(). The OP is talking about rb.sync(), which is part of SdFat's RingBuf class. It's not a file system sync().
Click to expand...
I'm not familiar enough with the RingBuf class to know how often it does file system writes and/or file directory updates. The RingBuf class wasn't around for the code I was writing for the MSP430 in 2014 ;-) If rb.sync does write out the whole ring buffer, it does seem excessive. Writing a few KB at a time from the ring buffer as needed and doing a file system sync() at regular intervals should be sufficient for data integrity,

Of course, if the amount of data in the ring buffer is continuously increasing due to slow write performance, you have a problem!
 
I'll have a look at only printing 512 B from the ring buffer to the file. From a bit of playing around rb.sync seemed to me like it was performing a file.write followed by a file.flush? Agree it's a bit excessive doing a flush type operation every loop-rather do it every couple of seconds for my application-but am new to the ring buffer class and have only been using what was in the original logging example. I'll have a deeper look.
Thanks all for the help!
 
Berollos said:
I'll have a look at only printing 512 B from the ring buffer to the file. From a bit of playing around rb.sync seemed to me like it was performing a file.write followed by a file.flush? Agree it's a bit excessive doing a flush type operation every loop-rather do it every couple of seconds for my application-but am new to the ring buffer class and have only been using what was in the original logging example. I'll have a deeper look.
Thanks all for the help!
Click to expand...

Here is RingBuf::sync(). As you can see, it's very simple.

Code: 
  /**
   * Write all data in the RingBuf to the underlying file.
   * \return true for success.
   */
  bool sync() {
    size_t n = bytesUsed();
    return writeOut(n) == n;
  }

It's fine to use this function, but in terms of what the TeensySdioLogger example is trying to demonstrate, it sort of short-circuits the purpose of the ring buffer. To avoid blocking, you must do two things. One is to only extract/write 512 bytes at a time, and the other is to always check sd.busy() before writing. When you call rb.sync(), you disrupt that process, and as your test shows, you will periodically get blocking. There is no need to call rb.sync() unless you are done logging and you want to do a final write of whatever is in the ring buffer. In my own applications, I typically decide in advance how much data and how long I want to log, preAllocate the file, start logging, and only call rb.sync() as the final write.
 
Ah I should say I've been using rb.sync within an if statement checking sd.busy, so I don't think the periodic blocking is related to SD busyness. The rb.sync must also be performing a flush somewhere, I guess within writeOut
 
Berollos said:
Ah I should say I've been using rb.sync within an if statement checking sd.busy, so I don't think the periodic blocking is related to SD busyness. The rb.sync must also be performing a flush somewhere, I guess within writeOut
Click to expand...
The RingBuf class never calls flush(). It's important to ALWAYS and ONLY write in chunks of 512. Using rb.sync() any time except at the end of your data logging is not consistent with that requirement. Please just try it.
 
joepasquariello said:
One is to only extract/write 512 bytes at a time, and the other is to always check sd.busy()
Click to expand...

That worked like a charm, thank you!

Removed the sync and replaced with:
Code: 
    if ((n > 512) && !file.isBusy()) {
      rb.writeOut(512);
    }


No blocking now:

1718658419721.png


Just for interest, the 4MB and 32 MB spikes are still evident in the "bytes in buffer" :

1718658973504.png


I removed all instances of rb.sync and file.close from my script to convince myself there was no flushing involved, and it's true, it looks like it properly saves to the sd card every time rb.writeOut is called.

I also pulled the power during a log to see what would happen, and it saves right to the point of pulling the power (barring whatever is left in the buffer). The only oddity is when I pull the plug on a log halfway, the preallocated file is half new data, and the remainder looks like old data. I guess that when you preallocate, it doesn't actually delete what is inside the preallocation until you need it, and old data on the SD card is never really removed until it is rewritten?
 
Berollos said:
That worked like a charm, thank you! No blocking now. Just for interest, the 4MB and 32 MB spikes are still evident in the "bytes in buffer" :
Click to expand...

That makes sense. The number of bytes in the RingBuf is going to spike each time the SD reports "busy". I never recorded the intervals at which that occurs. It's interesting that it's periodic at 4MB, with a larger spike around 32MB. Someone who knows a lot about SD cards may be able to shed light on exactly why that is.

I also pulled the power during a log to see what would happen, and it saves right to the point of pulling the power (barring whatever is left in the buffer). The only oddity is when I pull the plug on a log halfway, the preallocated file is half new data, and the remainder looks like old data. I guess that when you preallocate, it doesn't actually delete what is inside the preallocation until you need it, and old data on the SD card is never really removed until it is rewritten?
Click to expand...

That's correct. preAllocate() does not erase or do anything except allocate sectors up to the specified size, which lets the SD avoid the delays of searching for sectors as the file grows. When I have real logging to do, I do a full erase on the SD before starting. If you have time, I'd be interested to see what happens to the 4MB and 32MB spikes if you start from a fully erased SD.
 
Here is the bytes in buffer for a brand new SD card. Same 4MB and 32 MB spikes.

1718662649531.png



I wonder if you have a recommendation for how to fully erase the preallocated file beforehand?
 
Berollos said:
Here is the bytes in buffer for a brand new SD card. Same 4MB and 32 MB spikes.

I wonder if you have a recommendation for how to fully erase the preallocated file beforehand?
Click to expand...
I'll do some testing one of these days and let you know if I can duplicate your results. If you don't mind sharing your sketch, that would probably be the best way for me to try to do that.

I don't know of any way to "erase" a file, certainly not a file that is open. I suppose you could preAllocate(), write the entire file with 00 or FF, then seek(0) before you start logging. That could take a while if it's a large file. If you do that, Paul often recommends writing in blocks of 4KB.
 
Bastardized from the teensysdiologger example:

Code: 
#include "SD.h"    
#include "RingBuf.h"    

// Use Teensy SDIO
#define SD_CONFIG SdioConfig(FIFO_SDIO)
#define LOG_FILE_SIZE 10 * 25000 * 600 * 4
#define RING_BUF_CAPACITY 300000      
#define LOG_FILENAME "SdioLogger23.csv"

SdFs sd;
FsFile file;

// RingBuf for File type FsFile.
RingBuf<FsFile, RING_BUF_CAPACITY> rb;

char headerChars[2000];
long unsigned prevLogTime;
long unsigned logIntervalMicros = 100;


void setup() {
  initSDCard();
  createHeaders();
}

void loop() {

  clearSerialInput();
  delay(5000);
  Serial.println("Type any character to start");
  while (!Serial.available()) {
  }
  clearSerialInput();
  logData();

}



void initSDCard(){
      // Initialize the SD.
  if (!sd.begin(SD_CONFIG)) {
    sd.initErrorHalt(&Serial);
  }
  // Open or create file - truncate existing file.
  if (!file.open(LOG_FILENAME, O_RDWR | O_CREAT | O_TRUNC)) {
    Serial.println("open failed\n");
    return;
  }
//   File must be pre-allocated to avoid huge
//   delays searching for free clusters.
  if (!file.preAllocate(LOG_FILE_SIZE)) {
    Serial.println("preAllocate failed\n");
    file.close();
    return;
  }
  // initialize the RingBuf.
  rb.begin(&file);
}



void logData() {
 
  Serial.println("Type any character to stop");

  // Max RingBuf used bytes. Useful to understand RingBuf overrun.
  size_t maxUsed = 0;

  // Log data until Serial input or file full.
  while (!Serial.available()) {
    // Amount of data in ringBuf.
    size_t n = rb.bytesUsed();
    if ((n + file.curPosition()) > (LOG_FILE_SIZE - 20)) {
      Serial.println("File full - quitting.");
      break;
    }
    if (n > maxUsed) {
      maxUsed = n;
    }

    if ((micros() - prevLogTime) > logIntervalMicros){
   
      rb.print(micros());
      rb.print(',');
      rb.print(n);
      rb.print(',');
      rb.println(headerChars);
      if (rb.getWriteError()) {
        // Error caused by too few free bytes in RingBuf.
        Serial.println("WriteError");
        break;
      }

      prevLogTime = micros();

    }

    if ((n > 512) && !file.isBusy()) {
      rb.writeOut(512);
    }
   
  }
  file.truncate();
    Serial.println("Logging Stopped.");
  while(1){
  }
// Write any RingBuf data to file.
//  rb.sync();
//  file.truncate();
//  file.rewind();

}


void createHeaders(){

    sprintf(headerChars,
       // Time Params

      "Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,"
      "Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,"
      "Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,"
      "Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,"
      "Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,Hello,"
   
      );
     
 
}

void clearSerialInput() {
  for (uint32_t m = micros(); micros() - m < 10000;) {
    if (Serial.read() >= 0) {
      m = micros();
    }
  }
}
 
Since you are saving 10,000 sample per second, it might be worthwhile to switch from saving your data as ascii character and save binary values, then converting them in post-processing of the file. It would probably cut your data storage requirements in half. If your analysis depends on low variation in the collection interval, you will have to do better than checking micros() from the loop. Whether these things are worth the work to implement depends a lot on what you are collecting and how the data will be used.
 
I modified initSDCard() so that it writes all zeros to the sectors to be written, so that in the event of a power outage it is obvious where the data stops:

Code: 
char zeros1[4096];
int filePosition;


void initSDCard(){

   Serial.println("Type any character to initialize file");
   while (!Serial.available()) {
   }
      // Initialize the SD.
  if (!sd.begin(SD_CONFIG)) {
    sd.initErrorHalt(&Serial);
  }
  // Open or create file - truncate existing file.
  if (!file.open(LOG_FILENAME, O_RDWR | O_CREAT | O_TRUNC)) {
    Serial.println("open failed\n");
    return;
  }
//   File must be pre-allocated to avoid huge
//   delays searching for free clusters.
  if (!file.preAllocate(LOG_FILE_SIZE)) {
    Serial.println("preAllocate failed\n");
    file.close();
    return;
  }

    sprintf(zeros1,"%04095i",0);
    Serial.println(zeros1);
    Serial.println(sizeof(zeros1));
 
    while (file.curPosition() < LOG_FILE_SIZE) {
      //Serial.print(zeros1);
      filePosition = file.curPosition();
      file.print(zeros1);
      Serial.print(100*(1.0*filePosition)/(1.0*LOG_FILE_SIZE));
      Serial.println("% Zeroing...");
    
    }
  
    Serial.println("All zeroed");
    file.truncate(LOG_FILE_SIZE);
    file.flush();
    file.contiguousRange(&bgnSector,&endSector);
  
    Serial.println(bgnSector);
    Serial.println(endSector);
    file.close();
    delay(1000);

    // Initialize the SD.
    if (!sd.begin(SD_CONFIG)) {
      sd.initErrorHalt(&Serial);
    }
 
    if (!file.open(LOG_FILENAME, O_RDWR | O_CREAT | O_TRUNC)) {
      Serial.println("open failed\n");
      return;
    }
     if (!file.preAllocate(LOG_FILE_SIZE)) {
      Serial.println("preAllocate failed\n");
      file.close();
      return;
     }

    file.contiguousRange(&bgnSector,&endSector);
  
    Serial.println(bgnSector);
    Serial.println(endSector);
  
    // initialize the RingBuf.

  rb.begin(&file);

}

It hasn't made an noticeable difference to the logging rate or bytes in buffer traces.

mborgerson said:
save binary values,
Click to expand...
Yes definitely, this code is me just playing around with the example and seeing if the bare bones work.
 
Last edited:
Berollos said:
I modified initSDCard() so that it writes all zeros to the sectors to be written, so that in the event of a power outage it is obvious where the data stops:
Click to expand...
You might want to use 0xFF instead of zeroes. It may not make a difference (depending on how the SD works internally) but 0xFF (all bits set) is the state of practically all flash memory after it is erased. Programming flash can only "take bits away", and the only way to get them back is via an erase cycle.
In other words all 0xFFs is what a blank slate looks like.
 
You must log in or register to reply here.
Back
Top