Mismatch in timing

Question

struct timeval start, end, duration;
gettimeofday(&start, NULL);

res = curl_easy_perform(curl);

gettimeofday(&end, NULL);
timersub(&end, &start, &duration);

tm* startTime = localtime(&start.tv_sec);
tm* endTime = localtime(&end.tv_sec);
char buf[64];
strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", startTime);
char buf2[64];
strftime(buf2, sizeof(buf2), "%Y-%m-%d %H:%M:%S", endTime);

ofstream timeFile;
timeFile.open ("timingSheet.txt");
timeFile << fixed << showpoint;
timeFile << setprecision(6);
timeFile << "Duration: " << duration.tv_sec << "." << duration.tv_usec << " seconds \n";
timeFile << "Start time: " <<  buf <<"." << start.tv_usec << "\n";
timeFile << "End time: " <<  buf2 <<"." << end.tv_usec << "\n";
timeFile.close();

When I run this code I get this output:

Duration: 3.462243 seconds 
Start time: 2012-05-15 17:14:07.432613
End time: 2012-05-15 17:14:07.894856

What puzzles me is that the duration value doesn't match up with the Start and End times. The two dates only differ by the micro seconds. Is there a reason for this?

Thanks!

timersub() shouldn't affect either start or end. It is simply a function for getting the difference in two timevals and placing those values in duration. — Dave, May 16 '12 at 00:27
Please post the code. If it doesn't alter `start` or `end`, then it must calculate `duration` incorrectly. — Adam Liss, May 16 '12 at 00:27
http://linux.die.net/man/3/timersub I'm not sure where the code actually is. — Dave, May 16 '12 at 00:29
`# define timersub(a, b, result) \ do { \ (result)->tv_sec = (a)->tv_sec - (b)->tv_sec; \ (result)->tv_usec = (a)->tv_usec - (b)->tv_usec; \ if ((result)->tv_usec < 0) { \ --(result)->tv_sec; \ (result)->tv_usec += 1000000; \ } \ } while (0) #endif /* BSD */ ` — Dave, May 16 '12 at 00:29

engf-010 · Accepted Answer · 2012-05-16T17:10:20.327

2

localtime return a statically allocated buffer and you call it twice ,so StartTime and EndTime are the same. You need to copy it in another buffer directcly after each call.

tm* startTime = localtime(&start.tv_sec); 
char buf[64]; 
strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", startTime); 

tm* endTime = localtime(&end.tv_sec); 
char buf2[64]; 
strftime(buf2, sizeof(buf2), "%Y-%m-%d %H:%M:%S", endTime);

EDIT: you can also write this:

tm* pTimeBuf = localtime(&start.tv_sec); 
char buf[64]; 
strftime(buf, sizeof(buf), "%Y-%m-%d %H:%M:%S", pTimeBuf); 

localtime(&end.tv_sec); // NB. I don't store th return value (since I have it already)
char buf2[64]; 
strftime(buf2, sizeof(buf2), "%Y-%m-%d %H:%M:%S", pTimeBuf);

edited May 16 '12 at 17:10

answered May 16 '12 at 00:30

engf-010

3,980
1
14
25

the problem is not with strftime() ,it's with localtime(). localtime returns a pointer to an internal piece of memory. That memory is reused with every call to localtime. your variables starttime en endtime have the same pointervalue ,in fact you could get rid of one (I will update my answer so you can see what I mean). – engf-010 May 16 '12 at 17:06
the safer and undoubtly better variant of localtime() is the one pointed out by AwesomeNix's answer. – engf-010 May 16 '12 at 17:12
recently download this (don't remember from where) and currently reading it : The Linux Programming Interface - A Linux and UNIX System Programming Handbook (No Starch, 2010, 1593272200).pdf – engf-010 May 16 '12 at 17:15
Interesting that they would implement it like that. I'm using this and my answer makes much more sense, but still is off! I got these results: `Duration: 2.759294 seconds Start time: 2012-05-16 13:12:41.39434 End time: 2012-05-16 13:12:43.798728` I'm testing to see if I get more consistent results if I don't use timersub. – Dave May 16 '12 at 20:24
@Dave : I think the display of the tv_usecs is not correct. 41.39434 should be displayed as 41.039434 – engf-010 May 16 '12 at 21:34

score 2 · Answer 2 · answered May 16 '12 at 01:12

I agree with Edwin here, just a minor modification that its better to use the thread safe version localtime_r instead of localtime

struct tm startTime,endTime;
memset(&startTime,0,sizeof(struct tm)); //Advisable but not necessary
memset(&endTime,0,sizeof(struct tm)); //Advisable but not necessary
localtime_r(&start.tv_sec, &startTime);
localtime_r(&end.tv_sec, &endTime);

Mismatch in timing

2 Answers2