John -- "Davies, John" <john.davies@philips.com> writes:
I'm trying to time part of my program and coming up with something I can't explain. I don't expect great accuracy with the sample code here. But I'd like to understand what is happening.
I'm still looking at it, but for the unix-ish types that are following, here's the code that I got to compile (pardon the conversion from 20s to 10s). (Note that this is not the final working version -- see below for a URL to that.) // compile line: // g++ --std=gnu++0x -o millis-timer millis-timer.cpp -lboost_timer -lboost_date_time -lboost_thread-mt -lboost_system #include <iostream> #include <boost/chrono.hpp> #include <boost/date_time.hpp> #include <boost/timer/timer.hpp> #include <boost/thread.hpp> namespace bc = boost::chrono; namespace bt = boost::timer; namespace bpt = boost::posix_time; namespace btt = boost::this_thread; static bpt::ptime MillisecondsFromNow( int milliseconds ) { const bpt::ptime now( bpt::second_clock::universal_time() ); return now + bpt::milliseconds( milliseconds ); } int main( int argc, char * argv [] ) { bt::nanosecond_type const ten_seconds( 10LL * 1000 * 1000 * 1000 ); bt::cpu_timer timer; long count = 0; while ( true ) { btt::sleep( MillisecondsFromNow( 1000 ) ); bt::cpu_times const elapsed_times( timer.elapsed() ); bt::nanosecond_type const elapsed( elapsed_times.wall ); if ( elapsed >= ten_seconds ) break; count++; } std::cout << count << '\n'; } [John -- having a fully-compileable working example is a huge win; finding the correct libraries and namespaces took me some 5-10 min that could have been better spent doing analysis, and likely kept quite a few others from contributing at all.] And my typical output here is all over the place: $ for i in $( seq 1 10 ) ; do ./millis-timer ; done 101 101 100 100 100 101 154 273 273 278 For reference, this is a pretty fast system (Core i7 3770K @3.5GHz, up-to-date Fedora 18). My gut feeling is that you're mixing clock types, which will never end well. (But I was wrong! See below.)
So I'm running for 20 seconds and delaying each time for a second. So I would expect to get output of 19, maybe 20 or 18. Instead I'm getting around 38-40
I've tried .system and .user and get different values. But never something close to 20.
In my own project, I use clock_steady (within boost-aware bits) and CLOCK_MONOTONIC across the POSIX boundary. E.g., my condition variable class actually destroys the condition variable created by boost::thread, and replaces it with a posix condition variable that uses CLOCK_MONOTONIC. In your case, you're using: boost::this_thread::sleep( boost::system_time const & ). (Which is, by the way, deprecated...) If I modify the MillisecondsFromNow routine as such: static bpt::ptime MillisecondsFromNow( const int milliseconds ) { const bpt::ptime now( bpt::second_clock::universal_time() ); auto const offset = bpt::milliseconds( milliseconds ); std::clog << "now=" << now << ", offset=" << offset << std::endl; return now + offset; } With the corresponding change of compile line to: g++ --std=gnu++0x -o millis-timer millis-timer.cpp \ -lboost_timer -lboost_date_time -lboost_thread-mt -lboost_system $ ./millis-timer now=2013-Jun-05 08:00:12, offset=00:00:01 now=2013-Jun-05 08:00:12, offset=00:00:01 now=2013-Jun-05 08:00:12, offset=00:00:01 now=2013-Jun-05 08:00:12, offset=00:00:01 now=2013-Jun-05 08:00:13, offset=00:00:01 ... Note that it seems to show the same time for 3-4 lines, then actually pause for a full second. (It's easier to see this if you run it and watch the output -- there's a burst of 3-4 lines, then a pause, a burst, a pause...) Hm. The fact that you're using a second-resolution value is suspicious... and that does seem to have been the ultimate problem: changing MillisecondsFromNow to use "microsec_clock" instead of "second_clock" yields: static bpt::ptime MillisecondsFromNow( const int milliseconds ) { const bpt::ptime now( bpt::microsec_clock::universal_time() ); auto const offset = bpt::milliseconds( milliseconds ); std::clog << "now=" << now << ", offset=" << offset << std::endl; return now + offset; } And it works like a charm: $ ./millis-timer now=2013-Jun-06 02:57:12.140918, offset=00:00:01 now=2013-Jun-06 02:57:13.141050, offset=00:00:01 now=2013-Jun-06 02:57:14.141236, offset=00:00:01 now=2013-Jun-06 02:57:15.141331, offset=00:00:01 now=2013-Jun-06 02:57:16.141527, offset=00:00:01 now=2013-Jun-06 02:57:17.141746, offset=00:00:01 now=2013-Jun-06 02:57:18.141867, offset=00:00:01 now=2013-Jun-06 02:57:19.142047, offset=00:00:01 now=2013-Jun-06 02:57:20.142187, offset=00:00:01 now=2013-Jun-06 02:57:21.142399, offset=00:00:01 9 I also got it to work by using boost::chrono directly. Instead of calling your MillisecondsFromNow function, I did this: // btt::sleep( MillisecondsFromNow( 1000 ) ); btt::sleep_until( bc::system_clock::now() + bc::milliseconds( 1000 ) ); And that also gave me 9 iterations. Final version available at this url: http://scrye.com/~tkil/boost/millis-timer.cpp Best regards, Anthony Foiani