Bug in standard C++ <chrono> library

moogtrain · 2012-12-07 05:16:33

Hi guys.

There seems to be a bug when performing arithmetric operations on system clock time points in the standard C++11 <chrono> library. This bug has been present for a few months already and I haven't found any reports on this anywhere on the net. Can someone check and confirm this bug?

GCC version: 4.7.2 on x86_64, the same package from base-devel. Affects multilib versions of GCC, libgcc and libstdc++ as well.

This is the code. If you don't like <cstdio>, there's an <iostream> version on post #5. The time point arithmetric code is in TClock::update().

#include <thread>
#include <chrono>
#include <cstdio>
#include <cstdlib>

typedef std::chrono::system_clock           sysClock; // System clock
typedef std::chrono::time_point<sysClock>   sysTimeP; // Time point from system clock
typedef std::chrono::milliseconds           TimeUnit; // Time point unit in milliseconds

struct TTime
{
    unsigned tick; // Tick
    unsigned beat; // Beat
    unsigned measure; // Measure

    TTime (unsigned _tick = 0, unsigned _beat = 0, unsigned _measure = 0) : tick(_tick), beat(_beat), measure(_measure) {}
};

class TClock
{
private:
    sysTimeP    tpt_Game;       // Game start time stamp; updated on every boot.
    sysTimeP    tpt_LastRun;    // Last update time stamp; updated on every game tick.

    unsigned    tsg_tpb;        // Tick per beat
    unsigned    tsg_bpm;        // Beat per measure
    unsigned    tsg_tpm;        // Tick per measure
    double      tsg_tempo;      // Signature pacing to tempo ratio

    double      tmp_bpm;        // Tempo in beats per minute
    double      tmp_mspt;       // Tempo in milliseconds per tick
    
    double      tct_mstt;       // Milliseconds left to next tick
    unsigned    tct_tick;       // Total tick count

    TTime       currTTime;      // Current TTime
public:
    TClock (double BPM = 0.0)
    {
        tpt_Game = tpt_LastRun = sysClock::now();
        
        tsg_tpb = 48;
        tsg_bpm = 4;
        tsg_tpm = tsg_tpb * tsg_bpm;
        
        tsg_tempo = 60000.0 / tsg_tpb;
        
        tmp_bpm  = (BPM < 0.0) ? 120.0 : BPM;
        tmp_mspt = tsg_tempo / tmp_bpm;
        
        tct_tick = 0;
        
        currTTime = TTime();
        
        tct_mstt = tmp_mspt;
    }

    // Update clock.
    void update () {
        const sysTimeP tpt_now = sysClock::now();

        // This works
        // tct_mstt -= std::chrono::duration_cast<std::chrono::microseconds>(tpt_now - tpt_LastRun).count() / 1000.0;
        
        // .. but this does not
        tct_mstt -= std::chrono::duration_cast<TimeUnit>(tpt_now - tpt_LastRun).count();
        
        tpt_LastRun = tpt_now;
           
        while (tct_mstt < tmp_mspt)
        {
            // increment tick
            currTTime.tick++;
            tct_tick++;
            tct_mstt += tmp_mspt;

            // Process beat and measure
            if (currTTime.tick >= tsg_tpb) {
                currTTime.tick -= tsg_tpb;
                currTTime.beat++;
            }
            
            if (currTTime.beat >= tsg_bpm) {
                currTTime.beat -= tsg_bpm;
                currTTime.measure++;
            }
        }
    }

    
    inline void dumpStatus ()
    {
        printf("\ntsg: %u * %u = %u [%lf]", tsg_tpb, tsg_bpm, tsg_tpm, tsg_tempo);
        printf("\ntmp: %lf >> %lf", tmp_bpm , tmp_mspt);
        printf("\ntct: %lf >> %u" , tct_mstt, tct_tick);
    }

    inline TTime* getTTime () { return &currTTime; }
    
    inline unsigned long long getGameTimeStamp () { 
        return std::chrono::duration_cast<TimeUnit>(
            tpt_Game .time_since_epoch()
        ).count();
    }
    
    inline unsigned long long getSystemTime () { 
        return std::chrono::duration_cast<TimeUnit>(
            sysClock::now().time_since_epoch()
        ).count();
    }
};


int main (int __argc, char** __argv)
{
    if (__argc != 2) {
        printf("Insert tempo in beats per minute.\n");
        return EXIT_FAILURE;
    }

    double  bpm = strtod(__argv[1], NULL);

    TClock* clk = new TClock(bpm);
    TTime * tpt = clk->getTTime();
    unsigned long long lt = 0;
    unsigned lb = 0;

    for (;;)
    {
        clk->update();

        std::this_thread::sleep_for(std::chrono::milliseconds(1));
        
        if (lb != tpt->beat) {
            lb  = tpt->beat;
            clk->dumpStatus();
            printf("\n[%llu(%llu)] %u:%u:%u\n",
                clk->getSystemTime() - clk->getGameTimeStamp(),
                clk->getSystemTime() - lt,
                tpt->measure, tpt->beat, tpt->tick
            );
            
            lt  = clk->getSystemTime();

            fflush(stdout);
        }
    }
    
    return EXIT_SUCCESS;
}

This is the program output when running in 60BPM:

$ g++ --std=c++11 ChronoTest.cpp -o CT2
$ ./CT2 60

tsg: 48 * 4 = 192 [1250.000000]
tmp: 60.000000 >> 20.833333
tmp: 40.833333 >> 48
[1081(1354855594073)] 0:1:0

tsg: 48 * 4 = 192 [1250.000000]
tmp: 60.000000 >> 20.833333
tmp: 40.833333 >> 96
[2184(1103)] 0:2:0
      ^^^^ This should be 1000ms since 60 beats per minute means one beat per second.
tsg: 48 * 4 = 192 [1250.000000]
tmp: 60.000000 >> 20.833333
tmp: 40.833333 >> 144
[3286(1102)] 0:3:0

tsg: 48 * 4 = 192 [1250.000000]
tmp: 60.000000 >> 20.833333
tmp: 40.833333 >> 192
[4389(1103)] 1:0:0

tsg: 48 * 4 = 192 [1250.000000]
tmp: 60.000000 >> 20.833333
tmp: 40.833333 >> 240
[5491(1102)] 1:1:0

tsg: 48 * 4 = 192 [1250.000000]
tmp: 60.000000 >> 20.833333
tmp: 40.833333 >> 288
[6593(1102)] 1:2:0

This is the manual BPM counter I used to test the timing to verify: http://www.all8.com/tools/bpm.htm

EDIT: Changed title. No one seems to be taking attention.

Last edited by moogtrain (2012-12-22 15:35:11)

_voidStar · 2012-12-10 23:41:41

I tried to test your code but I get this ultra annoying error.

1 firestorm code $ gcc -std=c++11 -o CT helloworldchrono.cpp
2 helloworldchrono.cpp: In function ‘int main()’:
3 helloworldchrono.cpp:8:2: error: ‘sleep_for’ is not a member of ‘std::this_thread’

I've also tried "g++ -std=c++11 -o CT helloworldchrono.cpp" and "g++ -std=c++0x -o CT helloworldchrono.cpp"

My /usr/include/ && /usr/include/c++/4.7.2/ folders have served me well up till now. This is wracking my brain.

I've checked for thread and it exists. Line 3 is utterly disturbing me.
I've tried to reinstall gcc, gcc-libs, libstdc++5, and lib32-libstdc++5, no dice.
I've also tried building from source. I don't get it.

moogtrain · 2012-12-13 05:44:54

That's weird. It works fine for me with the vanilla gcc package on base-devel (no libstdc++; just gcc-libs). I switched to gcc-multilib and it also compiles without any warnings to both i686 and x86_64 platforms. The time unit bug is also present on those versions as well. Can someone explain why?

$ g++ -std=c++11 ChronoTest.cpp -o Test
$ g++ -v
Using built-in specs.
COLLECT_GCC=g++
COLLECT_LTO_WRAPPER=/usr/lib/gcc/x86_64-unknown-linux-gnu/4.7.2/lto-wrapper
Target: x86_64-unknown-linux-gnu
Configured with: /build/src/gcc-4.7.2/configure --prefix=/usr --libdir=/usr/lib --libexecdir=/usr/lib --mandir=/usr/share/man --infodir=/usr/share/info --with-bugurl=https://bugs.archlinux.org/ --enable-languages=c,c++,ada,fortran,go,lto,objc,obj-c++ --enable-shared --enable-threads=posix --with-system-zlib --enable-__cxa_atexit --disable-libunwind-exceptions --enable-clocale=gnu --disable-libstdcxx-pch --enable-libstdcxx-time --enable-gnu-unique-object --enable-linker-build-id --with-ppl --enable-cloog-backend=isl --disable-ppl-version-check --disable-cloog-version-check --enable-lto --enable-gold --enable-ld=default --enable-plugin --with-plugin-ld=ld.gold --with-linker-hash-style=gnu --disable-multilib --disable-libssp --disable-build-with-cxx --disable-build-poststage1-with-cxx --enable-checking=release
Thread model: posix
gcc version 4.7.2 (GCC)
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Last edited by moogtrain (2012-12-13 05:50:11)

_voidStar · 2012-12-20 00:09:05

I managed to fix my issue and I have successfully compiled your code with no warning messages.

I've ran it a few times "./CT 60" and your program will execute that "for (;;)" statement forever.

Needs a "break" or "goto" to escape a "for" loop like that.
I think when your program runs the "sleep_for" 1 millisecond is caught in an infinite loop.
So, maybe work on that -- DEFINITELY -- I should say.

On my end, there is no output either. How are you getting output like in the topic post?

I'll examine it some more, but those are the main things I saw.

moogtrain · 2012-12-22 15:18:18

It should be going in an infinite loop. Just hit Ctrl+C to send a SIGINT, which terminates the program. The sleep is only there to keep your CPU cool. If for some weird reason 1ms doesn't work use a larger value, like 5 or 13; or just remove it altogether.

Try removing the "if (lb != tpt->beat)" check to see if the clock is even ticking or not.

Okay, here's another version using <iostream> instead of <cstdio>, that still has the bug.

#include <thread>
#include <chrono>
#include <iostream>

typedef std::chrono::system_clock           sysClock; // System clock
typedef std::chrono::time_point<sysClock>   sysTimeP; // Time point from system clock
typedef std::chrono::milliseconds           TimeUnit; // Time point unit in milliseconds

/* Tempo time point type. Consists of a measure(hour), beat(minute), and tick(second). */
struct TTime
{
    unsigned tick; // Tick
    unsigned beat; // Beat
    unsigned measure; // Measure

    TTime (unsigned _tick = 0, unsigned _beat = 0, unsigned _measure = 0) : tick(_tick), beat(_beat), measure(_measure) {}
};

class TClock
{
private:
    sysTimeP    tpt_Start;      // Clock start time stamp; updated on every boot.
    sysTimeP    tpt_LastRun;    // Last update time stamp; updated on every game tick.

    unsigned    tsg_tpb;        // Ticks per beat
    unsigned    tsg_bpm;        // Beats per measure
    unsigned    tsg_tpm;        // Ticks per measure
    double      tsg_tempo;      // Signature pacing to tempo ratio

    double      tmp_bpm;        // Tempo in beats per minute
    double      tmp_mspt;       // Tempo in milliseconds per tick
    
    double      tct_mstt;       // Milliseconds left to next tick
    unsigned    tct_tick;       // Total tick count

    TTime       currTTime;      // Current TTime

public:
    TClock (double BPM = 0.0)
    {
        tpt_Start = tpt_LastRun = sysClock::now();
        
        tsg_tpb = 48;
        tsg_bpm = 4;
        tsg_tpm = tsg_tpb * tsg_bpm;
        
        tsg_tempo = 60000.0 / tsg_tpb;
        
        tmp_bpm  = (BPM < 0.0) ? 120.0 : BPM;
        tmp_mspt = tsg_tempo / tmp_bpm;
        
        tct_tick = 0;
        
        currTTime = TTime();
        
        tct_mstt = tmp_mspt;

        std::cout
            << "Starting clock at " << tmp_bpm << " Beats Per Minute."
            << std::endl;
        std::cout
            << tsg_tpb << " ticks per beat * "
            << tsg_bpm << " beats per measure = "
            << tsg_tpm << " ticks per measure"
            << std::endl;
        std::cout
            << "The clock ticks every " << tmp_mspt << " milliseconds."
            << std::endl;
    }

    // Update clock.
    void update ()
    {
        const sysTimeP tpt_now = sysClock::now();

        /* Decrement 'time left till next tick' by amount of time passed since last update. */
        // This works perfectly
        // tct_mstt -= std::chrono::duration_cast<std::chrono::microseconds>(tpt_now - tpt_LastRun).count() / 1000.0;
        
        // .. but this is 10% off sync. WHY?
        tct_mstt -= std::chrono::duration_cast<TimeUnit>(tpt_now - tpt_LastRun).count();
        
        tpt_LastRun = tpt_now;
        
        /* Update clock. */
        while (tct_mstt < tmp_mspt)
        {
            // increment tick
            currTTime.tick++;
            tct_tick++;
            tct_mstt += tmp_mspt;

            // Process beat and measure
            if (currTTime.tick >= tsg_tpb) {
                currTTime.tick -= tsg_tpb;
                currTTime.beat++;
            }
            
            if (currTTime.beat >= tsg_bpm) {
                currTTime.beat -= tsg_bpm;
                currTTime.measure++;
            }
        }
    }

    inline TTime* getTTime () { return &currTTime; }
    
    inline unsigned long long getStartTime () { 
        return std::chrono::duration_cast<TimeUnit>(
            tpt_Start.time_since_epoch()
        ).count();
    }
    
    inline unsigned long long getSystemTime () { 
        return std::chrono::duration_cast<TimeUnit>(
            sysClock::now().time_since_epoch()
        ).count();
    }
};


int main (int __argc, char** __argv)
{
    if (__argc != 2) {
        std::cout << "Insert tempo in beats per minute." << std::endl;
        return EXIT_FAILURE;
    }

    double  bpm = strtod(__argv[1], NULL);

    TClock* clk = new TClock(bpm);
    TTime * tpt = clk->getTTime();

    unsigned long long  lastUpdateTime  = 0;
    unsigned            lastBeat        = 1;

    for (;;)
    {
        clk->update();

        std::this_thread::sleep_for(std::chrono::milliseconds(1));
        
        if (lastBeat != tpt->beat) {
            lastBeat  = tpt->beat;
            std::cout << std::endl
                << "Time since start    : " << clk->getSystemTime() - clk->getStartTime() << "ms" << std::endl
                << "Time since last beat: " << clk->getSystemTime() - lastUpdateTime      << "ms" << std::endl
                << "Clock position: " << tpt->measure << "M : " << tpt->beat << "B : " << tpt->tick << "T"
                << std::endl;
            
            lastUpdateTime = clk->getSystemTime();
        }
    }
    
    return EXIT_SUCCESS;
}

Last edited by moogtrain (2012-12-22 15:45:32)

_voidStar · 2012-12-24 01:24:38

I just ran your new code... (output:)

1 $ ./"ChronoTest with iostream" 60
2 Starting clock at 60 Beats Per Minute.
3 48 ticks per beat * 4 beats per measure = 192 ticks per measure
4 The clock ticks every 20.8333 milliseconds.

5 Time since start : 0ms
6 Time since last beat: 1356281657ms
7 Clock position: 0M : 0B : 0T
8 ^C

The "^C" being a control-C and other than that I get no other output for over a minute.

Here's some output when removing "if (lastBeat != tpt->beat)":

1 Time since start : 8ms
2 Time since last beat: 0ms
3 Clock position: 0M : 0B : 0T
4
5 Time since start : 8ms
6 Time since last beat: 0ms
7 Clock position: 0M : 0B : 0T
8
9 Time since start : 8ms
10 Time since last beat: 0ms
11 Clock position: 0M : 0B : 0T
12
13 Time since start : 8ms
14 Time since last beat: 0ms
15 Clock position: 0M : 0B : 0T
16
17 Time since start : 8ms
18 Time since last beat: 0ms
19 Clock position: 0M : 0B : 0T
20
21 Time since start : 8ms
22 Time since last beat: 0ms
23 Clock position: 0M : 0B : 0T

I think what's most important are these lines:

1 /* Decrement 'time left till next tick' by amount of time passed since last update. */
2 // This works perfectly
3 // tct_mstt -= std::chrono::duration_cast<std::chrono::microseconds>(tpt_now - tpt_LastRun).count() / 1000.0;
4
5 // .. but this is 10% off sync. WHY?
6 tct_mstt -= std::chrono::duration_cast<TimeUnit>(tpt_now - tpt_LastRun).count();

All other things being equal, with TimeUnit just a mere renaming, I don't see why lines 3 and 6 should yield different results...

It's surely a bug, then.

moogtrain · 2012-12-24 15:03:27

It appears that under your system, the clock isn't updating at all. Try removing the "const" on the line "const sysTimeP tpt_now = sysClock::now();" in TClock::update().

Arch Linux

#1 2012-12-07 05:16:33

Bug in standard C++ <chrono> library

#2 2012-12-10 23:41:41

Re: Bug in standard C++ <chrono> library

#3 2012-12-13 05:44:54

Re: Bug in standard C++ <chrono> library

#4 2012-12-20 00:09:05

Re: Bug in standard C++ <chrono> library

#5 2012-12-22 15:18:18

Re: Bug in standard C++ <chrono> library

#6 2012-12-24 01:24:38

Re: Bug in standard C++ <chrono> library

#7 2012-12-24 15:03:27

Re: Bug in standard C++ <chrono> library

Board footer