boost::log::attributes:timer accuracy shift

[tib]

In the attached example, I have a timer and a clock attached to the log events. In the formatting function, I compute an estimated time value based on the timer and the timer creation datetime. I then compare that estimated time and the clock of the log event. It looks like there is a increasing shift (~25ms for 1 seconds of constant logging). In the example I wrote a timer that doesn't show this behavior and stays synchronized with the clock.

Output example:

clock: 2016-06-02T11:31:39.790105 timer1: 2016-06-02T11:31:39.765871 diff1: 24ms timer2: 2016-06-02T11:31:39.790219 diff2: 0ms 
clock: 2016-06-02T11:31:39.790105 timer1: 2016-06-02T11:31:39.765889 diff1: 24ms timer2: 2016-06-02T11:31:39.790238 diff2: 0ms 
clock: 2016-06-02T11:31:39.790105 timer1: 2016-06-02T11:31:39.765907 diff1: 24ms timer2: 2016-06-02T11:31:39.790257 diff2: 0ms 

[Andrey Semashev]

I believe your PreciseTimer is less precise than the timer the library offers. In particular, your code involves FP operations on the number of ticks since the timer construction:

double e = (nowCounter.QuadPart - m_startCounter.QuadPart) / (double) m_freq.QuadPart;

As the difference grows, the precision of double becomes insufficient.

The library code is also faster since it avoids division in the hot path. I admit, the implementation could be made more precise if 128-bit integer math was used instead of FP math, but I suspect it would be much slower yet.