Re: [Boost-users] Trouble with posix_time

Subject: Re: [Boost-users] Trouble with posix_time
From: Anthony Foiani (tkil_at_[hidden])
Date: 2013-06-05 23:04:03

John --

"Davies, John" <john.davies_at_[hidden]> 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