Coding Timing

Trying some writing to the MP3 smartcard. The following code took 10secs to execute. Not hugely fast … can you see if my rusty old C code is in any way optimal?

  Time_get_RTC( &time );
  TRACE("Started at hour: %d, minutes: %d, seconds: %d",
               time.hour,
               time.minute,
               time.second );
 
  ptr_file_output = (struct FileOutput*) malloc( sizeof *ptr_file_output );
 
  FileOutput_ctor_Ex( ptr_file_output, sz_full_file_name, TRUE );
 
  for( index = 0; index < 30; index++ )
  {
        memset( k1, index, 1024);
        FileOutput_write( ptr_file_output, k1, 1024);
  }
 
  FileOutput_dtor( ptr_file_output, FREE_MEMORY );
  TRACE("Done ...");
  Time_get_RTC( &time );
  TRACE("Stopped at hour: %d, minutes: %d, seconds: %d",
               time.hour,
               time.minute,
               time.second );

Well strictly speaking it didn't take 10sec to write to the device. You included the memory allocation, the file pointer constructor / destructor and a couple of debugs to the console in that 10sec.

Ok these things shouldn't take too long but I have seen a significant amount of time used in trying to allocate a file handle, memory etc.

You might consider the lightweight call clock() which returns a long in millisecond and use.

 long end, start;
 start = clock();
 ptr_file_output = (struct FileOutput*) malloc( sizeof *ptr_file_output );
 end = clock();
 TRACE("Malloc %ld ms", end-start);

The reason you would code it that way rather than:

 TRACE("Malloc %ld ms", clock()-start);

Is because you can't be sure at what point the clock() function is evaluated and in doing timing measurement you don't want to measure the time of the debug code itself.

Of course start would need to be reset for the next measurement.

You can setup some macro's to make this easier:

 #define TIME_VARS long end, start
 #define TIME_BEGIN start=clock()
 #define TIME_END(x) end = clock(); TRACE("%s: Time %ld ms", x, end-start)

So your code might now look like this:

 TIME_VARS;
 
 TIME_BEGIN;
  ptr_file_output = (struct FileOutput*) malloc( sizeof *ptr_file_output );
 TIME_END "Malloc";
 
 TIME_BEGIN;
  FileOutput_ctor_Ex( ptr_file_output, sz_full_file_name, TRUE );
 TIME_END "Constructor";
 
 TIME_BEGIN;
 for( index = 0; index < 30; index++ )
 {
        memset( k1, index, 1024);
        FileOutput_write( ptr_file_output, k1, 1024);
 }
 TIME_END "Loop";
 
 TIME_BEGIN;
  FileOutput_dtor( ptr_file_output, FREE_MEMORY );
 TIME_END "Destructor";

These macro's could be enchanced so that you can also have a total time without having to make major changes to the above code.

 #define TIME_VARS long end, start, total
 #define TIME_BEGIN start=clock()
 #define TIME_END(x) end = clock(); TRACE("%s: Time %ld ms", x, end-start); total += end-start
 #define TIME_TOTAL TRACE("Total time %ld ms", total)

Just some thought. :)