BIND 10 #924: Additional debugging for IntervalTimer test failure

[BIND 10 Development]

#924: Additional debugging for IntervalTimer test failure
-------------------------------------+-------------------------------------
                   Reporter:  shane  |                 Owner:  shane
                       Type:  task   |                Status:  new
                   Priority:  major  |             Milestone:
                  Component:         |  Sprint-20110517
  Unclassified                       |            Resolution:
                   Keywords:         |             Sensitive:  0
            Defect Severity:  N/A    |           Sub-Project:  DNS
Feature Depending on Ticket:         |  Estimated Difficulty:  1.0
        Add Hours to Ticket:  0      |           Total Hours:  0
                  Internal?:  0      |
-------------------------------------+-------------------------------------
Description changed by shane:

Old description:

> http://bind10.isc.org/~tester/builder//BIND10/20110512185001-NetBSD5-amd64/logs/unittests.out
>
> This appears to be a "real" timer failure:
>
> [ RUN      ] IntervalTimerTest.overwriteIntervalTimer
> interval_timer_unittest.cc:295: Failure
> Value of: delta < TIMER_MARGIN_MSEC
>   Actual: false
> Expected: true
> [  FAILED  ] IntervalTimerTest.overwriteIntervalTimer (640 ms)
>
> One thing is that we should change the test from this:
>
>     EXPECT_TRUE(delta < TIMER_MARGIN_MSEC);
>
> To this:
>
>     EXPECT_LT(delta, TIMER_MARGIN_MSEC);
>
> I think that would give us more information, like printing out the
> actual delta. Probably we should do this everywhere. Does that make some
> sense?
>
> Also, we could check for some clock skew, by replacing this:
>
>     boost::posix_time::time_duration delta =
>         (boost::posix_time::microsec_clock::universal_time() - start)
>          - boost::posix_time::millisec(400 + 100);
>
> With this:
>
>     boost::posix_time::time_duration test_runtime =
>         (boost::posix_time::microsec_clock::universal_time() - start);
>     EXPECT_GT(test_runtime, 0);
>
>     boost::posix_time::time_duration delta =
>         test_runtime - boost::posix_time::millisec(400 + 100);
>
> It won't catch cases where the clock jumps forward, but at least we can
> learn if the box has unstable time. (Note this may have nothing to do
> with this particular case... is this a virtual machine?)

New description:

 http://bind10.isc.org/~tester/builder//BIND10/20110512185001-NetBSD5-amd64/logs/unittests.out

 This appears to be a "real" timer failure:

 {{{
 [ RUN      ] IntervalTimerTest.overwriteIntervalTimer
 interval_timer_unittest.cc:295: Failure
 Value of: delta < TIMER_MARGIN_MSEC
   Actual: false
 Expected: true
 [  FAILED  ] IntervalTimerTest.overwriteIntervalTimer (640 ms)
 }}}

 One thing is that we should change the test from this:

     EXPECT_TRUE(delta < TIMER_MARGIN_MSEC);

 To this:

     EXPECT_LT(delta, TIMER_MARGIN_MSEC);

 I think that would give us more information, like printing out the
 actual delta. Probably we should do this everywhere. Does that make some
 sense?

 Also, we could check for some clock skew, by replacing this:

 {{{
     boost::posix_time::time_duration delta =
         (boost::posix_time::microsec_clock::universal_time() - start)
          - boost::posix_time::millisec(400 + 100);
 }}}

 With this:

 {{{
     boost::posix_time::time_duration test_runtime =
         (boost::posix_time::microsec_clock::universal_time() - start);
     EXPECT_GT(test_runtime, 0);

     boost::posix_time::time_duration delta =
         test_runtime - boost::posix_time::millisec(400 + 100);
 }}}

 It won't catch cases where the clock jumps forward, but at least we can
 learn if the box has unstable time. (Note this may have nothing to do
 with this particular case... is this a virtual machine?)

--

-- 
Ticket URL: <http://bind10.isc.org/ticket/924#comment:1>
BIND 10 Development <http://bind10.isc.org>
BIND 10 Development