Re: [lmi] Sporadic error in 'timer_test'

[Vadim Zeitlin]

On Wed, 11 Nov 2015 16:08:51 +0000 Greg Chicares <address@hidden> wrote:

GC> A few weeks ago I saw this failure:
GC> 
GC> **** test failed:   '0.975153' < '0.032'
GC> [file /lmi/src/lmi/timer_test.cpp, line 126]
GC> 
GC> and something similar occurred just the other day:
GC> 
GC> **** test failed:   '0.974785' < '0.032'
GC> [file /lmi/src/lmi/timer_test.cpp, line 126]

 FWIW the test failure is perfectly reproducible under Linux where it fails
even "more", if we assume that there can be different degrees of failing:

        **** test failed:   '0.002119' < '2e-06'

i.e. here it's off by a factor of thousand.

GC> I made this local change, to get more information...
GC> 
GC> Index: timer_test.cpp
GC> ===================================================================
GC> --- timer_test.cpp  (revision 6402)
GC> +++ timer_test.cpp  (working copy)
GC> @@ -124,6 +124,15 @@
GC>      double relative_error = std::fabs(observed - interval) / interval;
GC> 
GC>      BOOST_TEST_RELATION(relative_error,<,2.0*clock_resolution);
GC> +
GC> +    std::cout
GC> +        << CLOCKS_PER_SEC << " CLOCKS_PER_SEC\n"
GC> +        << clock_resolution << " clock_resolution\n"
GC> +        << observed << " observed\n"
GC> +        << interval << " interval\n"
GC> +        << relative_error << " relative_error\n"
GC> +        << std::endl
GC> +        ;
GC>  }
GC> 
GC>  void TimerTest::TestExceptions()
GC> 
GC> ...and changing the code made the problem disappear.

 It still fails 100% reliably with this change under Linux.

GC> Now I see, e.g.:
GC> 
GC> 1000 CLOCKS_PER_SEC
GC> 0.015 clock_resolution
GC> 1.00005 observed
GC> 1 interval
GC> 4.94609e-05 relative_error

And the output is:

        1000000 CLOCKS_PER_SEC
        1e-06 clock_resolution
        1.00239 observed
        1 interval
        0.002387 relative_error

GC> As a last resort, I looked at the code, but it uses the C RTL, which
GC> I don't remember well. Now I'm staring at this and wondering how it
GC> can work:

 Yes, this is my main question as well, although for different reasons.
The fundamental problem I see is that clock() doesn't measure wall time at
all but rather CPU time which can be completely different, so I don't think
it makes sense to compare them at all. Even if we assume that, because the
code between the consecutive calls to clock() here is just executing a
tight loop, the CPU time is still not exactly the same as the wall time
during this test execution because there are other processes on the system
and it's perfectly possible that this one gets preempted for more than 2us
which would be enough to make the test fail as these 2us would count in the
wall time, as measured by Timer, but not in the CPU time, as measured by
std::clock(). And this is exactly what seems to happen, if I use shell time
built-in I can see that if I exit the test immediately after this check it
still runs for slightly (4-5ms) longer than 1 second. A couple of these ms
are probably due to the overhead of launching the process, but the rest of
them account for the context switches as can be also seen from the fact
that the process "only" consumes 99% CPU and not 100% of it. Granted, I ran
these tests on a system which is not quite idle, but it has load of 0.01
right now and this is still enough for the test to fail by 3 orders of
magnitude. So it just seems like a bad idea to compare Timer results with
std::clock() ones.

GC>     std::clock_t first = std::clock();
GC>     std::clock_t last;
GC>     double clock_resolution;
GC>     for(;;)
GC>         {
GC>         last = std::clock();
GC>         clock_resolution = double(last - first) / CLOCKS_PER_SEC;
GC>         if(0.0 != clock_resolution)
GC>             {
GC>             break;
GC>             }
GC>         }
GC> 
GC> The way I read that, it starts at a random moment between clock ticks,
GC> and measures the time until the next tick. But if that's correct,
GC> then 'clock_resolution' should vary randomly between 0 and .015625,
GC> whereas it always seems to return .015 or .016 . Vadim, help?

 This actually looks fine to me because there is no such thing as "between
clock ticks": clock_t is an integer type in all implementations known to me
(C99, C11 and C++ all disagree on whether it can be a floating point type,
AFAICS, but, again, in practice it is usually not). So the resolution here
should always end up as 1/CLOCKS_PER_SEC.

GC> Stepping back, I question whether this test is even useful in any way.
GC> I think TimerTest::TestResolution() should just be eliminated.

 I think it can be useful as a test that Timer is roughly reasonable and
doesn't return something wildly incorrect (e.g. confuses ms and us as I had
sometimes done in the past...). But its tolerance should definitely be much
higher than 1us, see e.g. wxWidgets tests for wxStopWatch (which is a near
equivalent of the lmi Timer class) which use 50ms tolerance and still had
to be disabled for the highly loaded automatic builds:

https://github.com/wxWidgets/wxWidgets/blob/6602eb3384c09902787ee0b047e609b1224f4e88/tests/events/stopwatch.cpp#L65

 So expecting Timer to track the CPU time is just completely unreasonable
IME, unless you're running the test as a high priority process on a RTOS.

 Regards,
VZ