Why is our refresh rate consistently decreasing in logging on SD card?

Question

The current code is used to gather the state of 12 infrared beams and log them to an SD card using the real time clock to mark the time. The code uses a switch to turn the device on and off and an LED to indicate if data is being written to the SD. When we later looked at the data on the SD card the refresh rate was slowly decreasing and we ended up with only 10 logs a second after a few hours. Why is this happening and how is it fixed?

#include <SD.h>   //For talking to SD Card
#include <Wire.h>  //For RTC
#include "RTClib.h" //For RTC
//Define pins
//SD card is on standard SPI pins
//RTC is on Standard I2C Pins
const int CS_PIN   = 53;
//Default rate of 25ms
int refresh_rate = 25;
//Define RTC object
RTC_DS1307 RTC;
//Initialize variables
String year, month, day, hour, minute, second, time, date;
#define SENSOR1 22
#define SENSOR2 23
#define SENSOR3 24
#define SENSOR4 25
#define SENSOR5 26
#define SENSOR6 27
#define SENSOR7 32
#define SENSOR8 33
#define SENSOR9 34
#define SENSOR10 35
#define SENSOR11 36
#define SENSOR12 37
#define LEDPIN 6
#define SWITCH 10
// variables will change:
int sensorState1 = 0, lastState1 = 0;
int sensorState2 = 0, lastState2 = 0;

int sensorState3 = 0, lastState3 = 0;
int sensorState4 = 0, lastState4 = 0;
int sensorState5 = 0, lastState5 = 0;
int sensorState6 = 0, lastState6 = 0;

int sensorState7 = 0, lastState7 = 0;
int sensorState8 = 0, lastState8 = 0; 
int sensorState9 = 0, lastState9 = 0;
int sensorState10 = 0, lastState10 = 0;

int sensorState11 = 0, lastState11 = 0;
int sensorState12 = 0, lastState12 = 0;
//Variable for reading the Switch Status
int SWITCHSTATE ;
//define integers for sensor change
int SensorChange1 = 0;
int SensorChange2 = 0;
int SensorChange3 = 0;
int SensorChange4 = 0;
int SensorChange5 = 0;
int SensorChange6 = 0;
int SensorChange7 = 0;
int SensorChange8 = 0;
int SensorChange9 = 0;
int SensorChange10 = 0;
int SensorChange11 = 0;
int SensorChange12 = 0;
void setup() 
{
  // initialize the sensor pin 24 as an input:
  pinMode(SENSOR1, INPUT);

  digitalWrite(SENSOR1, HIGH); // turn on the pullup  // initialize the sensor pin 25 as an input:
  pinMode(SENSOR2, INPUT);

  digitalWrite(SENSOR2, HIGH); // initialize the sensor pin 26 as an input:
  pinMode(SENSOR3, INPUT);

  digitalWrite(SENSOR3, HIGH); // initialize the sensor pin 27 as an input:
  pinMode(SENSOR4, INPUT);

  digitalWrite(SENSOR4, HIGH); // initialize the sensor pin 28 as an input:
  pinMode(SENSOR5, INPUT);

  digitalWrite(SENSOR5, HIGH); // initialize the sensor pin 29 as an input:
  pinMode(SENSOR6, INPUT);

  digitalWrite(SENSOR6, HIGH);  // initialize the sensor pin 30 as an input:
  pinMode(SENSOR7, INPUT);

  digitalWrite(SENSOR7, HIGH);  // initialize the sensor pin 31 as an input:
  pinMode(SENSOR8, INPUT);

  digitalWrite(SENSOR8, HIGH);  // initialize the sensor pin 32 as an input:
  pinMode(SENSOR9, INPUT);

  digitalWrite(SENSOR9, HIGH);  // initialize the sensor pin 33 as an input:
  pinMode(SENSOR10, INPUT);

  digitalWrite(SENSOR10, HIGH);  // initialize the sensor pin 34 as an input:
  pinMode(SENSOR11, INPUT);

  digitalWrite(SENSOR11, HIGH);  // initialize the sensor pin 35 as an input:
  pinMode(SENSOR12, INPUT);

  digitalWrite(SENSOR12, HIGH);   // initialize the LED pin as an output:
// initialize the LED pin as an output:
  pinMode (LEDPIN, OUTPUT);
// initialize the SWITCH pin as an output:
  pinMode (SWITCH, INPUT);
// setpin 19 as high (5V) and 18 as low 
  pinMode(19, OUTPUT);

  pinMode(18, OUTPUT);
  digitalWrite(19, HIGH);
  digitalWrite(18, LOW);
Serial.begin(9600);
  Serial.println(F("Initializing Card"));
//CS pin, and pwr/gnd pins are outputs
  pinMode(CS_PIN, OUTPUT);
//Initiate the I2C bus and the RTC library
  Wire.begin();
  RTC.begin();
//If RTC is not running, set it to the computer's compile time
  if (! RTC.isrunning())
  {
    Serial.println(F("RTC is NOT running!"));
    RTC.adjust(DateTime(DATE, TIME));
  }
//Initialize SD card
  if (!SD.begin(CS_PIN))
  {
    Serial.println(F("Card Failure"));
    return;
  }
  Serial.println(F("Card Ready"));
//Read the configuration information (speed.txt)
  File commandFile = SD.open("speed.txt");
  if (commandFile)
  {
    Serial.println(F("Reading Command File"));
while(commandFile.available())
{
  refresh_rate = commandFile.parseInt();
}
Serial.print(F(&quot;Refresh Rate = &quot;));
Serial.print(refresh_rate);
Serial.println(F(&quot;ms&quot;));
commandFile.close();

}
  else
  {
    Serial.println(F("Could not read command file."));
    return;
  }
}
void loop()
{
  SWITCHSTATE = digitalRead(SWITCH); //read input value
  if (SWITCHSTATE == LOW)
 {
   digitalWrite(LEDPIN, LOW);
 } 
  else 
 {
   digitalWrite(LEDPIN, HIGH);
// read the state of the sensor value:
  sensorState1 = digitalRead(SENSOR1);
  sensorState2 = digitalRead(SENSOR2);
  sensorState3 = digitalRead(SENSOR3);
  sensorState4 = digitalRead(SENSOR4);
  sensorState5 = digitalRead(SENSOR5);
  sensorState6 = digitalRead(SENSOR6);
  sensorState7 = digitalRead(SENSOR7);
  sensorState8 = digitalRead(SENSOR8);
  sensorState9 = digitalRead(SENSOR9);
  sensorState10 = digitalRead(SENSOR10);
  sensorState11 = digitalRead(SENSOR11);
  sensorState12 = digitalRead(SENSOR12);
//Get the current date and time info and store in strings
  DateTime datetime = RTC.now();
  year  = String(datetime.year(),  DEC);
  month = String(datetime.month(), DEC);
  day  = String(datetime.day(), DEC);
  hour  = String(datetime.hour(), DEC);
  minute = String(datetime.minute(), DEC);
  second = String(datetime.second(), DEC);
//Concatenate the strings into date and time
  date = year + "/" + month + "/" + day;
  time = hour + ":" + minute + ":" + second;
if (sensorState1 == HIGH)
  {
   SensorChange1 = 1;
  }
  else 
  {
   SensorChange1 = 0;
  }
  if (sensorState2 == HIGH)
  {
   SensorChange2 = 1;
  }
  else 
  {
   SensorChange2 = 0;
  }
  if (sensorState3 == HIGH)
  {
   SensorChange3 = 1;
  }
  else 
  {
   SensorChange3 = 0;
  }
  if (sensorState4 == HIGH)
  {
   SensorChange4 = 1;
  }
  else 
  {
   SensorChange4 = 0;
  }
  if (sensorState5 == HIGH)
  {
   SensorChange5 = 1;
  }
  else 
  {
   SensorChange5 = 0;
  }
  if (sensorState6 == HIGH)
  {
   SensorChange6 = 1;
  }
  else 
  {
   SensorChange6 = 0;
  }
  if (sensorState7 == HIGH)
  {
   SensorChange7 = 1;
  }
  else 
  {
   SensorChange7 = 0;
  }
  if (sensorState8 == HIGH)
  {
   SensorChange8 = 1;
  }
  else 
  {
   SensorChange8 = 0;
  }
  if (sensorState9 == HIGH)
  {
   SensorChange9 = 1;
  }
  else 
  {
   SensorChange9 = 0;
  }
  if (sensorState10 == HIGH)
  {
   SensorChange10 = 1;
  }
  else 
  {
   SensorChange10 = 0;
  }
  if (sensorState11 == HIGH)
  {
   SensorChange11 = 1;
  }
  else 
  {
   SensorChange11 = 0;
  }
  if (sensorState12 == HIGH)
  {
   SensorChange12 = 1;
  }
  else 
  {
   SensorChange12 = 0;
  }
File dataFile ;
  dataFile = SD.open("log1.csv", FILE_WRITE);
  if (dataFile)
    {
      dataFile.print(date);
      dataFile.print(F(","));
      dataFile.print(time);
      dataFile.print(F(","));
      dataFile.print(SensorChange1);
      dataFile.print(F(","));
      dataFile.print(SensorChange2);
      dataFile.print(F(","));
      dataFile.print(SensorChange3);
      dataFile.print(F(","));
      dataFile.print(SensorChange4);
      dataFile.print(F(","));
      dataFile.print(SensorChange5);
      dataFile.print(F(","));
      dataFile.print(SensorChange6);
      dataFile.print(F(","));
      dataFile.print(SensorChange7);
      dataFile.print(F(","));
      dataFile.print(SensorChange8);
      dataFile.print(F(","));
      dataFile.print(SensorChange9);
      dataFile.print(F(","));
      dataFile.print(SensorChange10);
      dataFile.print(F(","));
      dataFile.print(SensorChange11);
      dataFile.print(F(","));
      dataFile.print(SensorChange12);
      dataFile.println( );
      dataFile.close(); //Data isn't actually written until we close the connection!
  //Print same thing to the screen for debugging
  Serial.println();
  Serial.print(date);
  Serial.print(F(&quot;,&quot;));
  Serial.print(time);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange1);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange2);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange3);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange4);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange5);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange6);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange7);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange8);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange9);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange10);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange11);
  Serial.print(F(&quot;,&quot;));
  Serial.print(SensorChange12);

}
else
{ 
 Serial.println(F(&quot;Couldn't open log file&quot;));
}


lastState1 = sensorState1;
  lastState2 = sensorState2;
  lastState3 = sensorState3;
  lastState4 = sensorState4;
  lastState5 = sensorState5;
  lastState6 = sensorState6;
  lastState7 = sensorState7;
  lastState8 = sensorState8;
  lastState9 = sensorState9;
  lastState10 = sensorState10;
  lastState11 = sensorState11;
  lastState12 = sensorState12;
delay(refresh_rate);
  }
}

timemage · Accepted Answer · 2021-04-21T21:13:09.693

I don't have certain answer for you, but a deep suspicion. ~~If I get bored I'll confirm it.~~ Confirmed below.

In each pass of loop(), you have:

  dataFile = SD.open("log1.csv", FILE_WRITE);

In short, finding the end of the file is linear operation in a FAT filesystem. It must follow the allocation chain to find (or create), the last cluster of the file. The allocation chain is sort like a linked list with the links themselves being the only thing in linked list structure; their numbers are mapped onto the cluster numbers. So you're traversing a linked list, except you may be doing it across multiple sectors of an SD card, which is comparatively expensive.

So by reopening repeatedly in loop(), you're forcing it to perform this lengthening process each time, apparently because of:

dataFile.close(); //Data isn't actually written until we close the connection!

The part of .close(); that does this is made available to you as .flush();, without needing to close the file and forget where the current cluster is.

In other words, you should be able to open() the file once in setup() and replace your .close() in loop() with a .flush().

That said, you needn't and probably shouldn't flush on every record write. If you're doing this so that you can shut the device down, you might want to just add a push-button that does the closing or flushing and then waits in the tight loop until it's power cycled.

Confirmation Test Results

In short, yes, there's a measurable, file-size related cost to opening the file for write and seeking to the end. And it's just a fact about the FAT filesystem and noticeable because it's impractical to load the whole allocation table into memory on a small Arduino. It would normally (e.g on the desktop) be loaded into memory and you'd scarcely notice the difference in opening files of different sizes.

In my one tested scenario for my setup the numbers predict that when the file grows to approximately 155 Meg, it will take about a tenth of a second to open.

This test involved:

An Arduino UNO.
2 GB FAT16 formatted card.
Arduino AVR core version 1.8.3
SD card library version 1.2.4.

Your results will probably vary widely with MCU type and filesystem block size, but so long as you're using a Arduino with a SD library that minimizes memory footprint, you'll have a noticeable increasing open time with larger file sizes.

The below is going to be a bit nerdy, but since people seem to be interested in it, I'm giving some detail. Arduino code follows at the bottom for what was used to collect the data that produced the graph.

I emptied a 2 GByte SD card. This included removing the "System Volume Information" that windows (or perhaps the card maker) had put on there, and confirmed that were were no allocated clusters, no file chains. Under these conditions the file should just grow in consecutive sectors on the card; at least as presented by the card, as in: if we ignore anything the card might be doing for wear-leveling. The pattern used in the program makes it pretty easy to just look at a raw image of the card and see that this is what happened.

Anyway, with my setup these are some results:

The 98304 sector count on the right refers to a file of roughly 50 Meg.

This SD card is FAT16 formatted, something I hadn't noticed until I ran the numbers on that staircase pattern and found them defying expectations by a factor of 2.

Being FAT16, each FAT table sector, has 512/2 = 256 entries in it. Each entry number corresponds to one cluster (block), which for my SD card's filesystem happens to be 32 kByte, or 64 count of 512-byte sectors. So every FAT table sector (in my case) is responsible for locating 64 * 256 = 16,384 file sectors. In other words, the staircase pattern appears to reflect the fact that following the allocation chain for our consecutive file means reading another FAT table sector for every 16,384 sectors of the file, hence the jumps at those intervals.

If you used a fragmented file it would need to do this more often and the performance would look worse. I did inspect the SD card to confirm that it was written sequentially.
If you use FAT32, you can expect it to take longer because each FAT sector will store half as many cluster references.
If you use smaller cluster (block) size, then it will take longer because each enter in the FAT sector covers less file content.

Test code

//
// Tested on an UNO with Arduino Core version 1.8.3
// 2 GByte SDCard
//
#include <SD.h> // Version 1.2.4 as of test.
#include <SPI.h>
static constexpr int PIN_SDCARD_SHIELD_CHIP_SELECT = 10;
static constexpr int PIN_HALT_TEST                 =  2;
static const char test_filename[] = "testfile.txt";
struct test_state : Printable {
  uint32_t      sector_counter = -1;
  unsigned long open_duration  =  0;
size_t printTo(Print& p) const override {
    auto r = p.write('[');
    r     += p.print(sector_counter);
    r     += p.write(':');
    r     += p.print(open_duration);
    r     += p.write(']');
    return r;
  }
void update(unsigned long new_open_duration) {
    open_duration = new_open_duration;
    ++sector_counter;
  }
};
//
//
//
void write_numbered_sector(
  Print &p,
  const test_state &state
) {
  static constexpr size_t SECTOR_SIZE            = 512;
  static constexpr size_t CR_LF_SIZE             =   2;
const auto printed_test_state_len = p.print(state);
const auto xs_to_write = 
      SECTOR_SIZE
    - printed_test_state_len
    - CR_LF_SIZE;
for (size_t i = xs_to_write; i != 0; --i) {
    p.write('X');
  }
p.write('\r');
  p.write('\n');
}
//
//
//
void setup() {
  pinMode(PIN_HALT_TEST, INPUT_PULLUP);
Serial.begin(9600);
if (!SD.begin(PIN_SDCARD_SHIELD_CHIP_SELECT)) {
    Serial.println(F("Card initialization failed."));
    halt_test();
  }
SD.remove(test_filename);
}
//
//
//
void blink_forever() {
  pinMode(LED_BUILTIN, OUTPUT);
  while (true) {
    static bool led_state = false;
led_state = !led_state;
digitalWrite(LED_BUILTIN, led_state);
delay(100);

}
}
//
//
//
void halt_test() {
  SD.end();
  SPI.end();
  Serial.end();
blink_forever();
}
//
//
//
void loop() {
  static test_state state;
Serial.flush(); 
  const auto started_opening = micros();
  File testfile = SD.open(test_filename, FILE_WRITE);
  const auto done_opening = micros();
const auto open_duration = done_opening - started_opening;
state.update(open_duration);
write_numbered_sector(
    testfile,
    state
  );
  testfile.close();
  Serial.print(micros());
  Serial.print(' ');
  Serial.println(state);
const auto user_requested_halt = (digitalRead(PIN_HALT_TEST) == LOW);
  if (user_requested_halt) {
    Serial.println(F("Test halt requested."));
    halt_test();
  }
}
//  vim:sw=2:ts=2:et:nowrap:ft=cpp:

Why is our refresh rate consistently decreasing in logging on SD card?

1 Answers1

Confirmation Test Results

Test code

Linked