boost chrono endTime - startTime returns negative in boost 1.51

Question

The boost chrono library vs1.51 on my macbook pro returns negative times when I substract endTime - startTime. If you print the timepoints you see that the end time is earlier than the startTime. How can this happen?

typedef boost::chrono::steady_clock clock_t;
clock_t clock;

// Start time measurement
boost::chrono::time_point<clock_t>  startTime = clock.now();
short test_times = 7;

// Spend some time...
for ( int i=0; i<test_times; ++i )
{
   xnodeptr spResultDoc=parser.parse(inputSrc);

  xstring sXmlResult = spResultDoc->str();
  const char16_t* szDbg = sXmlResult.c_str();

  BOOST_CHECK(spResultDoc->getNodeType()==xnode::DOCUMENT_NODE && sXmlResult == sXml);
}

// Stop time measurement
boost::chrono::time_point<clock_t> endTime = clock.now();
clock_t::duration elapsed( endTime - startTime);

std::cout << std::endl;
std::cout << "Now time: " << clock.now() << std::endl;
std::cout << "Start time: " << startTime << std::endl;
std::cout << "End time: " << endTime << std::endl;

std::cout << std::endl << "Total Parse time: " << elapsed << std::endl;
std::cout << "Avarage Parse time per iteration: " <<  (boost::chrono::duration_cast<boost::chrono::milliseconds>(elapsed) / test_times) << std::endl;

I tried different clocks but no difference.

Any help would be appreciated!

EDIT: Forgot to add the output:

Now time: 1 nanosecond since boot

Start time: 140734799802912 nanoseconds since boot

End time: 140734799802480 nanoseconds since boot

Total Parse time: -432 nanoseconds Avarage Parse time per iteration: 0 milliseconds

Can you include the output? Any chance of memory corruption? Does it only happen when you optimize compile? — Yakk - Adam Nevraumont, Nov 20 '12 at 17:28

score 5 · Accepted Answer · edited May 23 '17 at 12:14

Hyperthreading or just scheduling interference, the Boost implementation punts monotonic support to the OS:

POSIX: clock_gettime (CLOCK_MONOTONIC) although it still may fail due to kernel errors handling hyper-threading when calibrating the system.

WIN32: QueryPerformanceCounter() which on anything but Nehalem architecture or newer is not going to be monotonic across cores and threads.

OSX: mach_absolute_time(), i.e. the steady & high resolution clocks are the same. The source code shows that it uses RDTSC thus strict dependency upon hardware stability: i.e. no guarantees.

Disabling hyperthreading is a recommended way to go, but say on Windows you are really limited. Aside of dropping timer resolution the only available method is direct access to the underlying hardware timers whilst ensuring thread affinity.

It looks like a good time to submit a bug to Boost, I would recommend:

Win32: Use GetTick64Count(), as discussed here.

OSX: Use clock_get_time (SYSTEM_CLOCK) according to this question.

boost chrono endTime - startTime returns negative in boost 1.51

1 Answers1