0

So I have been using a time profiler class (see bellow). It was working flawlessly untill some point (by not working I mean I suspected it was outputing weird values). I then created a new blank project from scratch and basically copy pasted the example from here: http://en.cppreference.com/w/cpp/chrono/duration/duration_cast. Instead, it now prints 1014 when its clearly supposed to be 1000, just like its been doibg untill yesterday! Once again, the same example from the link above used to work untill yesterday. I have no idea what happened. I restarted my machine but it did not work still.

Here's the time profiler class:

#pragma once #include <stdio.h> #include <time.h> #include <chrono> // C++11 #include <thread> #include <string> namespace profiler { // The time profiling class class Time { public: Time(const std::string& str) : m_str(str), m_start(std::chrono::system_clock::now()) { } virtual ~Time() { auto end = std::chrono::system_clock::now(); auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(end - m_start).count(); printf("%s took %lli milliseconds\n", m_str.empty() ? "Block" : m_str.c_str(), duration); } private: std::string m_str; std::chrono::system_clock::time_point m_start; }; } #ifdef _DEBUG // Profile only if debugging. This profiles the time spent to process the block that this macro was called within #ifndef TIME #define TIME(str) profiler::Time timer__(str) #endif // TIME #else // If not debugging, do nothing #ifndef TIME #define TIME(str) do { } while(0) // This avoids empty statements #endif // TIME #endif // _DEBUG #ifndef SLEEP #define SLEEP(ms) std::this_thread::sleep_for(std::chrono::milliseconds(ms)); #endif // A working example of this profiler. Call EXAMPLE() and it should print 16 milliseconds #ifndef EXAMPLE #define EXAMPLE() \ profiler::Time timer__("Example that takes 16 milliseconds (value should match)"); \ std::this_thread::sleep_for(std::chrono::milliseconds(1)); \ std::this_thread::sleep_for(std::chrono::milliseconds(2)); \ std::this_thread::sleep_for(std::chrono::milliseconds(3)); \ std::this_thread::sleep_for(std::chrono::milliseconds(10)); #endif

Here's the usage code:

#include <stdio.h> #include <chrono> #include <thread> int main() { auto start = std::chrono::system_clock::now(); std::this_thread::sleep_for(std::chrono::seconds(1)); auto end = std::chrono::system_clock::now(); auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(end - start).count(); printf("Block took %lli milliseconds\n", duration); return getchar(); }

I'm using Visual Studio Ultimate 2012 on Windows 7 Professional 64 bits, if that helps.

Improve this question
9
  • Screenshot: postimg.org/image/7otdsxhnh Commented Oct 20, 2015 at 17:30
  • 1
    It is running as expected. There's 2 things to consider here. First, the sleep_for will sleep for at least the specified sleep time. There's also the time consumed before and after the sleep method. Commented Oct 20, 2015 at 17:35
  • @wendelbsilva I'm aware that this sleep function might not extremely accurate and that the SO might interfere a bit but I highly believe something is wrong. I have been using it to measure the time spent to parse some file. The average used to be 10 to 15 milliseconds, however it NOW sometimes prints ZERO! There's no way this parsing is taking 0 milliseconds now. It is so weird that it even prints the 15 milliseconds like it used to be and sometimes 0. Commented Oct 20, 2015 at 17:57
  • Did another app on your computer call timeBeginPeriod temporarilt boosting yor time resolution? Games are particularily guilty of this (Note changing timer periods is generally a really bad idea) Commented Oct 20, 2015 at 18:07
  • @Mike I didn't understand Commented Oct 20, 2015 at 19:08

2 Answers 2

Reset to default
4

std::this_thread::sleep_for(std::chrono::seconds(1)); is in no way guaranteed to sleep for exactly 1 second.

Using 1.014 seconds, including the second call to now(), must be considered good enough.

Improve this answer
Sign up to request clarification or add additional context in comments.

3 Comments

I have been using it to measure the time spent to parse some file. The average used to be 10 to 15 ms, however it sometimes NOW prints ZERO! There's no way this parsing is taking 0 ms. I can assure you, based on stressing tests I made yesterday, that a call to now() doesn't take 14 ms. This can, however, be something related to the SO. What's really curious is that by the time I was replying to your comments, I ran the app again a few times and it now prints the correct value, even for really small sleeps, like 3 ms, for example
That's a TOTALLY different question. If a benchmark takes 0 time, it usually means that the optimizer removed all the code. Synthetic benchmarks are hard!
See my comment. The accuracy of system_clock on windows is about 15ms so you'll either see 0 or 15 if something is sufficiently quick
2

In all likelihood its another app calling timeBeginPeriod which is messing with your measurements. Heres an example:

Heres an app which measures 1000ms sleeping, then spawns another app which calls timeBeingPeriod(1) and timeEndPeriod(1). Note how a second app calling timeBeginPeriod affects this apps measurement of time:

#include <Windows.h> #include <chrono> #include <iostream> int main(int nArgs, char**args) { if (nArgs <= 1) { // if we're spawned normally measure sleeping for 1000ms 30 times for (int i = 0; i < 30; ++i) { auto timeBegin = std::chrono::system_clock::now(); Sleep(1000); auto timeEnd = std::chrono::system_clock::now(); auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(timeEnd - timeBegin); std::cout << "Iteration " << i << ", sleeping for 1000ms took " << duration.count() << "ms..." << std::endl; // On the 10th iteration spawn a bad app which calls timeBeginPeriod(1) if (i == 10) { std::cout << "Spawning bad process" << std::endl; PROCESS_INFORMATION pi = {}; STARTUPINFOA si = { sizeof(STARTUPINFOA) }; CreateProcessA("..\\Debug\\Timer.exe", "be a bad process", nullptr, nullptr, FALSE, 0, nullptr, nullptr, &si, &pi); } } } else { // If we're spawned with some arguments pretend to be a bad app that calls timeBeginPeriod(1) std::cout << "Bad process calling timeBeginPeriod(1)" << std::endl; timeBeginPeriod(1); Sleep(10 * 1000); std::cout << "Bad process calling timeEndPeriod(1)" << std::endl; timeEndPeriod(1); } }

Gives:

Iteration 0, sleeping for 1000ms took 1015ms... Iteration 1, sleeping for 1000ms took 1015ms... Iteration 2, sleeping for 1000ms took 1015ms... Iteration 3, sleeping for 1000ms took 1015ms... Iteration 4, sleeping for 1000ms took 1015ms... Iteration 5, sleeping for 1000ms took 1015ms... Iteration 6, sleeping for 1000ms took 1015ms... Iteration 7, sleeping for 1000ms took 1015ms... Iteration 8, sleeping for 1000ms took 1015ms... Iteration 9, sleeping for 1000ms took 1015ms... Iteration 10, sleeping for 1000ms took 1015ms... Spawning bad process Bad process calling timeBeginPeriod(1) Iteration 11, sleeping for 1000ms took 1011ms... Iteration 12, sleeping for 1000ms took 1001ms... Iteration 13, sleeping for 1000ms took 1001ms... Iteration 14, sleeping for 1000ms took 1001ms... Iteration 15, sleeping for 1000ms took 1000ms... Iteration 16, sleeping for 1000ms took 1000ms... Iteration 17, sleeping for 1000ms took 1001ms... Iteration 18, sleeping for 1000ms took 1001ms... Iteration 19, sleeping for 1000ms took 1001ms... Bad process calling timeEndPeriod(1) Iteration 20, sleeping for 1000ms took 1008ms... Iteration 21, sleeping for 1000ms took 1011ms... Iteration 22, sleeping for 1000ms took 1015ms... Iteration 23, sleeping for 1000ms took 1015ms... Iteration 24, sleeping for 1000ms took 1016ms... Iteration 25, sleeping for 1000ms took 1015ms... Iteration 26, sleeping for 1000ms took 1015ms... Iteration 27, sleeping for 1000ms took 1015ms... Iteration 28, sleeping for 1000ms took 1015ms... Iteration 29, sleeping for 1000ms took 1015ms...

Note in the general case we measure 15ms too long, but whilst the 'bad' app is running we're a lot more accurate.

You should use a more accurate clock to measure time. QueryPerformanceCounter/QueryPerformanceFrequency or GetSystemTimeAsFileTimePrecise or std::chrono::high_resolution_clock ONLY ON VS2015 will work. std::chrono::high_resolution_clock on vs2013 is a bit rubbish and still has this issue.

However, this only explains what you are seeing, in the general case sleep(xxx) will sleep for xxx and some extra - it'll only start up again when there's a spare CPU core to run it on or its next scheduled. Please do not user timeBeginPeriod yourself as its bad, just write your logic to handle the fact you're not running on a real time system so any measurement will have some error.

Improve this answer

4 Comments

It's not easily possible to tell which applications calling the timePeriods functions, right? Are there options to include that timePeriods functions without suffering portability issues to improve this profiling class? By the way, high_resolution_clock is just a system_clock typedef.
@Yves Henri If this is for a profiling class consider that firstly, you should use a recommended high quality timing function. None of the clocks in chrono are that (at least on VS2012). Secondly, that sleeping is notorious for being inaccurate - if you were actually measuring some real code your timing would be more accurate. But most importantly, you're not running on a real time OS so you threads will get pre-empted making reproducibility a problem. This is why you should use a profiler which is in cahoots with the scheduler as this can be accurate, or just live with the inaccuracy you get
And msdn.microsoft.com/en-gb/library/windows/desktop/… is a required read if you want to know which timers are good on windows.
I just thought that chrono (the one that comes with the 'C++11' compiler from VS2012) was the most precise clock I could use, so I found this class and made a few adjustments. It was running smooth and all, but at some point it started outputting 0ms for the same task that used to be 10~15ms (it wasn't a sleep call. For completeness, it was a file parsing function). Do you know any free precise time profiler I could use to test on my windows?

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.