Performance of TinyFAT with Arduino Ethernet Shield - FYI

I've been experiencing some unexpected "performance" problems with writing to an SDCard (on the Arduino ethernet shield with microSD slot) for logging.

Just in case anybody else is interested in knowing how logging (on an UNO) with an SDCard behaves, here's a start...

Out of curiosity I started digging a little and generated the following graph :

https://docs.google.com/file/d/0B16BxEDVqDYsQnNxajFZdlp3T0k/edit?usp=sharing&pli=1

You'll see that, regular as clock work, the write times to append 1Kb to a log file suddenly jump from around 240ms, to around 560ms, and then peak for one instance at around 900ms before falling back to 240ms for several more writes.

Instinctively I guessed that (with the test code in a tight loop) perhaps the SDCard controller was being overwhelmed. Adding in an expanding delay (starting at 0ms and proceeding to 100ms, marked in red) however, the timings look like this :

Identical!!!

Perhaps the timings are still too tight? Here's a graph with the delay increment increasing in 100ms steps from 0 - 1000ms :

Still the same! Perhaps these sudden spikes are related to the cluster size on the SDCard? It might be worth following up on that.

The Code used to generate this data is based on a TinyFat example :

#include <tinyFAT.h>

// Demo_writeLn (C)2011 Henning Karlsen
// web: http://www.henningkarlsen.com/electronics
//
// This program is a demo of the writeLn()-function.
//
// This demo will create a textfile, and fill it with 1MB
// of text. The file will be named 'BIGFILE3.TXT'. If the
// file already exists it will first be deleted.
//
// SD card must be connected to the SPI port of your Arduino.
//
// Remember to select 115200 baud in the Serial Monitor.
//
// Modified 2013 to test file writing performance by Ben Senior
// Write 1Mb of 1Kb data segments, opening and closing the file before and after each write to simulate logging.
// The addition of setSSPin(4) seems necessary for an arduino microSD ethernet shield.

#include <tinyFAT.h>
#include <avr/pgmspace.h>

byte res;

char *verboseError(byte err)
{
	switch (err)
	{
	case ERROR_MBR_READ_ERROR:
		return "Error reading MBR";
		break;
	case ERROR_MBR_SIGNATURE:
		return "MBR Signature error";
		break;
	case ERROR_MBR_INVALID_FS:
		return "Unsupported filesystem";
		break;
	case ERROR_BOOTSEC_READ_ERROR:
		return "Error reading Boot Sector";
		break;
	case ERROR_BOOTSEC_SIGNATURE:
		return "Boot Sector Signature error";
		break;
	default:
		return "Unknown error";
		break;
	}
}

unsigned long time;
int totalCounter = 0;
int delayTime;

void setup() {
  // Initialize serial communication at 115200 baud
  Serial.begin(115200);
  Serial.println();
  // Initialize tinyFAT 
  // You might need to select a lower speed than the default SPISPEED_HIGH
  file.setSSpin(4);
  res=file.initFAT(); 
  if (res!=NO_ERROR)
  {
    Serial.print("***** ERROR: ");
    Serial.println(verboseError(res));
    while (true) {};
  }

  Serial.println("This demo will create a textfile, and fill it with 1MB of text.");
  Serial.println("The file will be named 'BIGFILE3.TXT'. If the file already exists it will first be deleted.");
  Serial.println();
  Serial.println("***** Send any character to start *****");
  while (!Serial.available()) {};
  Serial.flush();
  
  if (file.exists("BIGFILE3.TXT"))
    file.delFile("BIGFILE3.TXT");
    
  file.create("BIGFILE3.TXT");

  Serial.println("Kb,DelayTime,OpenFile,Write1Kb,CloseFile");
  for (int d=0;d<10;d++)
  {
    delayTime=d*10; //Multiples of 10millis
    //Test opening, appending 1Kb of data, 512 times.
    for (int l=1; l<128; l++)
     {
      totalCounter += 1;
      Serial.print(totalCounter);
      Serial.print(",");
      Serial.print(delayTime);
      Serial.print(",");
      //Start counter
      time = millis();    
      res=file.openFile("BIGFILE3.TXT", FILEMODE_TEXT_WRITE);
      Serial.print(millis() - time);
      Serial.print(",");
  
      if (res==NO_ERROR)
      {
        time = millis();
        for (int cc=0; cc<1; cc++)
        {
          for (int i=0; i<8; i++)
          {
            file.writeLn("012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345");          
          }
        }
        Serial.print(millis() - time);
        Serial.print(",");
        
        time = millis();
        file.closeFile();
        Serial.println(millis() - time);
        //End counter
        delay(delayTime);
        //Print time (for spread sheet).
      }
      else
      {
        switch(res)
        {
          case ERROR_ANOTHER_FILE_OPEN:
            Serial.println("** ERROR: Another file is already open...");
            break;
          default:
            Serial.print("** ERROR: ");
            Serial.println(res, HEX);
            break;
        }
      }
     }
   }
  Serial.println("***** All done... *****");
  
}  

void loop() 
{
}
  Serial.flush();

Block until all pending output has been sent. How the f**k is that useful?

Each time through the inner loop, you are writing 128 characters to the file. On the first three passes, the data is buffered. On the 4th, the data is actually written to the card. That happens twice during your loop - once in the middle and once at the end.

Looking at just the first graph, there appear to be three data points per x location, with no clue what each location means, or what each dot, all using the same symbol are supposed to mean,

I suspect that your time variation has more to do with buffering serial data than actually writing to the file. However, since I can't see what the first graph is supposedly telling me, I can't be sure.

Thanks for the response...

The Serial.flush(); is just boilerplate code from the modified TinyFat. I don't know why it's there either, although sometimes similar code has a comment next to it saying it's needed for compatibility with the Deumilanove).

A sample of the data from the first graph (the third column is the time taken for the write):
320,17,871,0
321,16,284,0
322,17,282,0
323,17,287,0
324,17,284,0
325,17,283,0
326,17,283,0
327,16,281,0
328,17,281,0
329,17,281,0
330,17,281,0
331,16,288,0
332,16,283,0
333,15,283,0
334,15,283,0
335,16,541,0
336,16,871,0

That makes 16 writes between peaks (well, 15 writes to the "pre-peak" of 541 ms.

That does indeed look like a buffered write (I'm new to this Arduino/microcontroller stuff) ... but doesn't that imply that the buffer is 1Kb? Why do you say it's written twice (once in the middle and once at the end)?

So this is perfectly normal behaviour then? Great. :slight_smile:

Thanks.

but doesn't that imply that the buffer is 1Kb?

The buffer is 512 bytes.

So this is perfectly normal behaviour then?

I didn't say that. I said that three points on a graph, at each x location, with no indication of which point is which, or what the X and Y scales mean, is useless information. A meaningful frame for reference for the x axis, a meaningful frame of reference for the Y axis, and an explanation of what is being plotted (and distinguishing symbols for each item) is necessary to see what the graph is supposed to be telling us.

For now, I'll assume that it is Joe Namath's batting average, Babe Ruth's yards per carry, and the temperature of my oven being plotted, and that X is in parsecs and Y is in degrees Kelvin.

That hardly makes sense, does it?