Tuesday 4 December 2018

Measuring function time in linux using C


Measuring Time 

So in my job recently i had to time how long it took for a module to be plugged in before that module became "ready" ... the answer was 46 seconds.. but some careful polling changes and a change how firmware was loaded mean't that got chopped in half almost to 26 seconds!

But that's not the point, the point was how did i do such timing.

The original way i found was to use to use clock(). Clock returns an approximation of the processor time used by the program.
Using the following code..

#include <time.h>
#include <stdio.h> 
int main() 
{ 
   clock_t start, stop, length; 
   start = clock(); 
   
   function_to_be_time(parameters); 
   
   stop = clock(); 

   length = (double) stop - start / CLOCKS_PER_SEC; 

   printf("Time for your function was %ld\n", length); 
   
   return; 
} 

Now, this works mind you! but there's a gotchya here, oh yes, you saw that coming didn't you.. go on - admit it..
I probably didn't read the manual (RTFM!) for clock properly.... because the times i was getting back for my function calling didn't make sense compared to time stamped outputs!?
Clock() is returning time used by the program... i know - that didn't make sense, but it does if you mention the word threading.
See i was in a multi-threaded enviroment. So while this was timing my function in this "program" (ie thread!) my "program" had been running differently (in time) from other functions (ie threads!) that made up the entired module "ready" process.

Take 2. 

So instead, i used clock_gettime() with CLOCK_MONOTONIC.
This gave me a much better accuracy across my module insertion process, and started giving me numbers that made sense with other time stamped debug statements.

So.. using the following code,
#include <time.h>
#include <stdio.h>

/* Convert the timespec struct into a seconds value
static double TimeToSeconds(struct timespec* ts)
{
   return (double)ts->tv_sec + (double)ts->tv_nsec / 1000000000.0;
}

int main()
{
    struct timespec start, stop;
    double time_spent = 0;
    clock_gettime(CLOCK_MONOTONIC, &start);

    <YOUR FUNCTION GOES HERE>

    clock_gettime(CLOCK_MONOTONIC, &stop);
    time_spent = TimeToSeconds(&stop) - TimeToSeconds(&start);
    
    printf("your function time was %ld\n", time_spent);

    return;
}

Hopefully that helps someone with timing issues in threads etc.. lemme know if it works for you :)

Lastly - so i don't forget (possibly)... time stamping..
I'm just gonna post the code

time_t rawtime;
struct tm * timeinfo;
time ( &rawtime );
timeinfo = localtime ( &rawtime );
printf("Time Stamp is [%d:%d:%d]\n", 
        timeinfo->tm_hour, timeinfo->tm_min, timeinfo->tm_sec);

All good fun :)



No comments:

Post a Comment