Run-Time Side-Effects of Calling Sleep

[Stevens Miller]

I first brought this up in another thread, but I have since discovered the behavior I am investigating is not specific to Java. I am using Windows 10, and have written this C++ program, which uses either a call to Sleep or a spin delay that repeatedly looks at the Windows performance counter to create a 33 millisecond pause. Either way, it then calls a subroutine that counts the number of times it can query the performance counter in two milliseconds. I would expect the number of times to vary according to system load and other factors, but I would not expect to see anything significantly different using Sleep or the spin delay to create the 33 millisecond pauses between calls to the subroutine. However, I am seeing remarkable differences. Here's my code and the output:

#include "stdafx.h" #include "Windows.h" int runInPlace(int msDelay) { LARGE_INTEGER t0, t1; int n = 0; QueryPerformanceCounter(&t0); do { QueryPerformanceCounter(&t1); n++; } while (t1.QuadPart - t0.QuadPart < msDelay); return n; } int _tmain(int argc, _TCHAR* argv[]) { LARGE_INTEGER t0, t1; LARGE_INTEGER frequency; int n; QueryPerformanceFrequency(&frequency); int msDelay = 2 * frequency.QuadPart / 1000; int spinDelay = 33 * frequency.QuadPart / 1000; for (int i = 0; i < 100; i++) { if (argc > 1) Sleep(33); else { QueryPerformanceCounter(&t0); do { QueryPerformanceCounter(&t1); } while (t1.QuadPart - t0.QuadPart < spinDelay); } n = runInPlace(msDelay); printf("%d \n", n); } getchar(); return 0; }

After each pause, the program calls runInPlace, which returns the number of times it was able to query the performance counter in two milliseconds. The main program simply prints that value.

Here's some sample output when using a Sleep delay:

56116
248936
53659
34311
233488
54921
47904
45765
31454
55633
55870
55607
32363
219810
211400
216358
274039
244635
152282
151779
43057
37442
251658
53813
56237
259858
252275
251099

And here's some sample output when using a spin delay:

276461
280869
276215
280850
188066
280666
281139
280904
277886
279250
244671
240599
279697
280844
159246
271938
263632
260892
238902
255570
265652
274005
273604
150640
279153
281146
280845
248277

What could possibly be causing these two different behaviors?

[Karthik Shiraly]

QueryPerformanceCounter seems to have a lot of gotchas on multi-core and multi-processor systems - see https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx , http://www.virtualdub.org/blog/pivot/entry.php?id=106 and others.
Overall I found those sources more confusing than clarifying, and I'm not on Windows to investigate further. But it looks like each core maintains its own hardware tick counter and these are not always successfully synchronized at startup. It also looks like CPU power management and core frequency governing means that the tick frequency is not really a constant.

I'm guessing that in the sleep case - 33ms is a long time for a modern processor - the core that initiates the sleep is scheduled to execute something else and a different core picks up the thread when it wakes up. Given those gotchas on multi-core systems, this may explain why (t1 - t0) converges to 2ms much faster is not consistent with actual time, sometimes converging much faster, sometimes slower. Probably the processor thinks 2ms have elapsed because it's subtracting the tick counters of two different cores which were not synchronized to begin with. The frequency governing may also play a part - it's likely tick frequency reduces when a core is idly sleeping.

In the spin delay case, it's the same core running all the time. So (t1-t0) is consistent and matches actual time. It's also never idle, so I suppose frequency governing does not affect it.

I can't think of any good way to verify this. Perhaps measure the number of context switches or similar windows performance indicator in the two scenarios? The sleep scenario should show a larger number of them. Or use something better than windows perf counters at showing CPU core counters - like Intel's PCM or VTune.

[Stevens Miller]

Thanks, Karthik. That second link is to an article that is ten years old. The first one actually says that the problems addressed in the old have all been fixed and that QPC is reliable on multicore machines. Even if it weren't, that doesn't explain why I see two behaviors when I switch between sleeping and spinning.

In the spin delay case, it's the same core running all the time.

I'm not sure this is so. Compute-bound processes do get switched from one core to another. At least, my experiments indicate they do. I've run compute-bound processes that last indefinitely, yet the Task Manager shows all of my cores as being well below 100%. Whether something is spinning or not doesn't matter, I think, when the OS decides to do a context switch. It just stops the running process and, when that process gets its next turn to run, assigns it to a core. It might be a good idea to try to assign it to the same one it had before, to optimize the chances that cached addresses unique to that core are still in cache, but I have to wonder if the likelihood of that being true after a context switch makes it worth doing.

I'll give the filetime routine mentioned in that MSDN page a try. Thanks for the help.

[Steffe Wilson]

That's a very intriguing result! It would be interesting to see whether the degree of variation seen in the 'sleep version' of your program stabilises after a while.
How about upping your loop counter from 100 to say 1000 (more if necessary). To see if the values may become more uniform after a while.

EDIT: Actually no that wouldnt do what I intended. Instead after you do the sleep call RunInPlace say 20 times and see if the values stabilise.
I'm wondering about whether the system stabilises as you get further away from the sleep.

[Stevens Miller]

Steffe Wilson wrote:...after you do the sleep call RunInPlace say 20 times and see if the values stabilise.
I'm wondering about whether the system stabilises as you get further away from the sleep.

Great minds think alike, Steffe. I've been running experiments like that since last night (this is keeping me up). The results are somewhat inconsistent. I will post when I have something solid.

Thanks for your interest.

[Tim Holloway]

When the Commodore Amiga first arrived on the scene, one of the things that the manufacturers warned new developers about was not to use counting loops for delays or timing measurements.

There were 2 reasons for this:

1. Counting loops are dependent on CPU speed. If you coded a game that used a loop of "n" steps and an 8n processor model was released, the game would become essentially unplayable. A lot of IBM PC games learned this the hard way.

2. The Amiga - like most modern OS's, operated using pre-emptive multi-tasking. That meant that a counting loop could be interrupted while counting and the system would go off and do other things. Even if no peripheral event interrupts occurred, a time-slice expiration interrupt could put the process to sleep indefinitely. I think the default timeslice was something like 15ms, although it has been a long while.

Time slices can expire even when you are within system service code, and as a result, brute-force timing will vary.

The sleep function is even worse. The documentations should have in fact informed you that there are no warrantees express or implied about its exact duration. What the sleep function does is set up an expiration time, then yields to the dispatcher. The actual wakeup time will occur after the expiration time has passed AND the task dispatcher has determined that no other processes/threads should be scheduled ahead of the one that is sleeping.

[Steffe Wilson]

Tim Holloway wrote:Time slices can expire even when you are within system service code, and as a result, brute-force timing will vary.

The sleep function is even worse. The documentations should have in fact informed you that there are no warrantees express or implied about its exact duration. What the sleep function does is set up an expiration time, then yields to the dispatcher. The actual wakeup time will occur after the expiration time has passed AND the task dispatcher has determined that no other processes/threads should be scheduled ahead of the one that is sleeping.

Neither of these characteristics could account for the observed behaviour though could they?

[Stevens Miller]

Tim Holloway wrote:The sleep function is even worse. The documentations should have in fact informed you that there are no warrantees express or implied about its exact duration. What the sleep function does is set up an expiration time, then yields to the dispatcher. The actual wakeup time will occur after the expiration time has passed AND the task dispatcher has determined that no other processes/threads should be scheduled ahead of the one that is sleeping.

It's worse than that, Tim: because the granularity of the actual interval is that of the system clock, the documentation warns that the actual interval may even be less then what your code requests.

Now, I'm not using a counting loop in any of this. Both of my spinning loops spin on the system clock. The runInPlace method does count the number of times it spins, but that's to show that calling Sleep has the side-effect of, apparently, slowing that loop (at least for a while). Whether I spin before starting that loop or Sleep before starting that loop, I would have expected the behavior of the loop to be the same in both cases. It's not, and that's what puzzles me.

[Stevens Miller]

Steffe Wilson wrote:

Tim Holloway wrote:Time slices can expire even when you are within system service code, and as a result, brute-force timing will vary.

Neither of these characteristics could account for the observed behaviour though could they?

You are both correct. The per-call time consumed by runInPlace should vary, some, because of unpredictable additional system overhead. For the most part, though it ought to follow a consistent frequency distribution of times, hovering above and below some average. That's exactly what it does when I delay between each call by spinning on the system clock. But, as you can see, when I delay between calls by calling Sleep, the per-call time consumed by runInPlace varies wildly between a range of a numbers similar to (but, amazingly, consistently somewhat lower than) those exhibited when I delayed by spinning, and a completely different, much lower, range of values that are never exhibited when I delay by spinning.

Now, I have tried this on five different computers in our household, all running Windows 10. The behavior only appears on the two that are the highest-performance machines. The other three, all somewhat lower in overall computing power, don't show the behavior.

Still working on Steff's proposed experiment. More soon...

[Tim Holloway]

Well, as I mentioned, sleep actually yields the timeslice on the spot. A spin will not.

Incidentally, when doing stuff like that (and I have an Arduino project in the mill at the moment that does, my logic looks more like this:

TimeValue now, later;
now = getCurrentTime();
later = now + interval;

while (true) :
   now = getCurrentTime;
until now >= later:
  do stuff
  sleep_or_something
end while

Saves the overhead of repeated arithmetic and thereby tightens the loop. Not by much perhaps, by what the heck - I find it easier to read anyway.

[Stevens Miller]

Tim Holloway wrote:Well, as I mentioned, sleep actually yields the timeslice on the spot. A spin will not.

But why would that make any difference to subsequent behavior?

Incidentally, when doing stuff like that my logic looks more like this:

   now = getCurrentTime;
until now >= later:

That is superior, but this originated as a Java program relying on System.nanoTime(), and you can't be sure that a later nanoTime won't be less than an earlier one (because of rollover). The nanoTime javadoc specifically warns against testing for "now > later," while the MSDN pages are somewhat more casual about this issue:

nanoTime javadoc wrote:one should use t1 - t0 < 0, not t1 < t0, because of the possibility of numerical overflow.

whereas:

The QueryPerformanceCounter FAQ wrote:How often does QPC roll over?
Not less than 100 years from the most recent system boot, and potentially longer based on the underlying hardware timer used. For most applications, rollover isn't a concern.

If you are sure that getCurrentTime() never rolls over, that won't affect you.

In any case, that's really not the issue I'm working on. I'm trying to find out why my inner loop behaves differently depending upon whether or not delays between calls are implemented as Sleeps or spins. It shouldn't make a difference, but it does.

[Stevens Miller]

Steffe Wilson wrote:...after you do the sleep call RunInPlace say 20 times and see if the values stabilise.
I'm wondering about whether the system stabilises as you get further away from the sleep.

Okay, the results are going to surprise you. (Well, they surprised me, anyway.)

Just as you suggested, I ran runInPlace 20 times after each sleep. Here are (some of) the results:

57215
57044
57545
57283
57539
56100
56805
57240
56737
56594
56275
91059
249056
271784
248195
265789
269397
257470
276305
256229
--------
269689
273877
265058
270281
176452
221806
251230
243384
268416
256720
248325
237009
265630
239970
271048
216254
238356
232281
244769
220913
--------
190619
29097
39504
53021
50374
55703
42308
34617
35856
37879
50446
48824
37429
254903
231191
239087
234680
239531
260947
231620
--------
256581
238321
237307
253356
252718
253646
251078
239553
242883
265436
252250
248308
250493
243745
238069
241443
270461
240001
257302
241498
--------
247983
259641
272962
256766
204245
240985
265858
271180
205950
160617
44724
33019
47117
47451
54936
48505
42369
38114
51425
41294
--------

That last one's somewhat mind-boggling. (And, again, when I switch from Sleep to a spin, this never happens.)

[Steffe Wilson]

Wow, the plot thickens. I was expecting an increase from the 5nnnn to the 2nnnnn in each batch. But that last one bucks the trend (if there is any trend).

[Stevens Miller]

Ah, but wait! I rewrote it to run runInPlace 100 times after each pause, not 20, and to track the last appearance of a run that returned less than 100000 passes through the inner loop. Care to guess which was the highest numbered run with a return of less than 100000 in any set of 100?

20.

No, seriously, here's the output:

-1
-1
-1
-1
-1
11
14
-1
-1
-1
12
16
19
-1
-1
13
17
-1
-1
11
14
-1
-1
-1
12
16
-1
-1
-1
14
17
20
8
11
-1
18
-1
-1
13
-1
-1
-1
10
-1
-1
-1
-1
12
-1
-1
-1
-1
14
-1
-1
-1
-1
15
-1
-1
-1
13
-1
-1
-1
-1
-1
17
-1
-1
13
-1
-1
-1
-1
14
-1
20
-1
12
16
-1
-1
10
13
17
-1
-1
-1
14
17
-1
-1
12
15
-1
-1
10
13
17

"-1" means that all 100 runs executed their inner loop at least 100000 times. Any other number is the run of the last of that set of 100 that executed its inner loop fewer than 100000 times. Your theory appears to be correct. Whatever it is about Sleep that causes subsequent code to run slow, it "wears off" after a while.

[Paul Clapham]

There's maybe some underlying regularity there but you'd need to get the statisticians from CERN involved to identify which bosons are in action.

[Steffe Wilson]

Stevens Miller wrote:Your theory appears to be correct. Whatever it is about Sleep that causes subsequent code to run slow, it "wears off" after a while.

Very interesting. Well the reason I was thinking along those lines was because I wondered whether the sleeps could be having an effect on the CPU scheduling.

The non-sleep variant of your program has quite a uniform CPU profile, ie a CPU-intensive wait loop followed by a CPU-intensive runInPlace(), and these keep repeating, so its all very uniform.

Whereas the sleep variant has a distinct down-up-down-up 'square wave' CPU-usage profile; it does nothing during sleep, then intensive-CPU runInPlace(), then nothing, then intensive-CPU runInPlace(), etc.

[Stevens Miller]

Paul Clapham wrote:There's maybe some underlying regularity there but you'd need to get the statisticians from CERN involved to identify which bosons are in action.

Those frauds? Weren't they the ones who mistook a loose fiber-optic connection for proof they'd broken the light-speed barrier? I'd be better off getting my math done for me by one of those kids you seeing playing with a multi-colored abacus toy in the children's corner at Starbuck's.

[Stevens Miller]

Steffe Wilson wrote:

Stevens Miller wrote:Your theory appears to be correct. Whatever it is about Sleep that causes subsequent code to run slow, it "wears off" after a while.

Very interesting. Well the reason I was thinking along those lines was because I wondered whether the sleeps could be having an effect on the CPU scheduling.

That's a reasonable idea, though I did implement this earlier (in Java) as two completely separate processes, using Sockets so one could "trigger" the other. Amazingly, I continued to see the same behavior. You'd think two process couldn't affect each other.

Now, it's possible, I suppose, that Sleep has some affect on the system clock, and that the times I'm getting from the performance counter aren't reliable. I wrote some code to see if they were jumping forward at any point during the runInPlace inner loop, to correct for maybe a slow-down. That would certainly be capable of reducing the number of iterations, without having a lasting influence on overall operations. Alas, although I did detect some jumps, they were of the kind I think you can best explain via the things we've already discussed: one form or another of general system overhead. Never any single big leap that looked like a correction for a slow-down.

Continuing with your prior suggestion, I changed the time spent in runInPlace's inner loop from 2ms to 4ms. Indeed, the highest number of runs reported in any set of 100 before the problem just goes away shrank from 20 to 8. Doubling the time spent in each call to the routine basically halved the number of calls necessary to get the system back to "normal." Whatever it is that I'm dealing with, it only lasts about 40ms or so. On a computer, that's a long time. But, considering that I am not seeing it on anything but my fastest machines, it may simply not have enough effect in the world at large for anyone to have noticed it before. (And, I think it is fair to say, that calling Sleep is usually a sign of inferior code. People in a position to care about this may actually not be calling Sleep, much less in a way that exhibits this bizarre effect.)

Any other ideas on how else to investigate this?

[Tim Holloway]

In all fairness, I'm projecting backwards from best practices - I'm too lazy to actually scrutinize the code and data in-depth!

In practical terms, if you want a 1-off time delay, sleep is the best bet. If you want repeated "ticks", use a repeating timer, since it will attempt to keep to schedule and not drift the way that repeatedly issuing sleep calls would. If you need microsecond timing, hooking directly to system microsecond timing interrupts is necessary - the normal OS clock ticks are usually done in millisecond-level intervals.

The pseudo-code example I gave is to give an approximation of regular polling intervals for a service that doesn't support such things itself. Most systems will have something cleaner.

To measure intervals, again, you have to be careful what resources you call on, because the granularity of the timer being queried will influence the results you calculate. And in Java, the Date/time classes don't always hook up to services that match the granularity of the classes themselves. I think that java.sql.Date has millisecond granularity but the normal "Date" type in the Oracle database is actually only resolvable to the second.

AND, just to complicate things, some time functions may be set up to return different values each time they are called, no matter how frequently, for the benefit of services that formulate database keys etc. that must be unique. So many calls in a short period would advance the "time" unnaturally, then the clock would be allowed to drift back to the proper time when no one was calling for more values.

Time in computers isn't simple. Lots of things can skew it, starting with basic time-slicing intervals, working its way through interrupts, how long low-level locks are held, and undoubtedly more things that don't come to mind at the moment.

[Stevens Miller]

A little more data: I realized that, when I lengthened the run time of runInPlace from 2ms to 4ms, I should have been tracking any reports of it running less than 200000 times, not 100000. Making that adjustment did, in fact, show a ceiling of ten runs before the system goes back to normal.

In the other direction, reducing the run time of runInPlace to 1ms, and tracking runs of less than 50000 times, it reports a ceiling of 41 runs before returning to normal. The ~40ms duration of the anomalous effect is consistent across all three tests.

[Stevens Miller]

Tim Holloway wrote:To measure intervals, again, you have to be careful what resources you call on, because the granularity of the timer being queried...

I'm actually pretty familiar with most of those issues, but thanks.

In this case, it's not timing I'm interested in. I'm trying to find out why calling Sleep affects the performance of code that executes in the next 40ms after Sleep returns.

[Steffe Wilson]

stevens: no other ideas at this minute but I'll keep pondering.

[Stevens Miller]

We've tried a couple of worthwhile things, but coderanch.com is still mostly a Java community, and this might call for someone more focused on Windows and C++. I understand it's bad form to scatter the same question across multiple forums, but would people object if I tried this at StackOverflow?

[Tim Holloway]

Might as well. I'm well-experienced in C, but too lazy to analyze it. Maybe better luck there.

Before you go, though - how's your physical/virtual memory set up? When a task switches page faults often follow. Even when they don't, the CPU instruction caches may be depleted.

[Stevens Miller]

Tim Holloway wrote:how's your physical/virtual memory set up? When a task switches page faults often follow. Even when they don't, the CPU instruction caches may be depleted.

Thoughts along those lines have crossed my mind, but it's hard to understand how any such thing could inconsistently affect the behavior of a tight loop for as long as 40ms.

[Stevens Miller]

I have posted this at StackOverflow. Let's see if their nerd-fu is stronger than our nerd-fu.

[Stevens Miller]

Well, hoodly-doo, they cracked it! After some of the typically obnoxious comments one gets at StackOverflow (and, gawd, I am so grateful to JavaRanch for creating an atmosphere of respect and encouragement in this place), particularly from some folks who clearly hadn't read my actual question (and immediately started telling me I must not have read the documentation because I clearly didn't know how Sleep() works, and so on), one kind soul came through. Here's what he said:

1201ProgramAlavm wrote:This sounds like it is due to the reduced clock speed that the CPU will run at when the computer is not busy (SpeedStep). When the computer is idle (like in a sleep) the clock speed will drop to reduce power consumption. On newer CPUs this can be 35% or less of the listed clock speed. Once the computer gets busy again there is a small delay before the CPU will speed up again.

You can turn off this feature (either in the BIOS or by changing the "Minimum processor state" setting under "Processor power management" in the advanced settings of your power plan to 100%.

I tried what 1201ProgramAlarm said and the behavior instantly vanished. I restored my original minimum processor state (to 5%!) and the behavior instantly returned.

I'm pretty sure I would never have thought of that, but there it is.

Now, that would have gone well with Steffe's guess that something needed time to get back up to speed, but, as we saw, it's erratic. Before that 40ms elapses, some calls to runInPlace ran fast, other didn't, and in no particular order. My guess (just a guess) is that maybe not all of my four cores come up to speed at the same time, and my process got moved from one core to another during that 40ms. Anyone know if that might be the case?

Anyway, tip o' the hat to StackOverflow, and thanks to you guys for showing an interest.

[Steffe Wilson]

Stevens Miller wrote:Well, hoodly-doo, they cracked it!

That's great.

Stevens Miller wrote:After some of the typically obnoxious comments one gets at StackOverflow (and, gawd, I am so grateful to JavaRanch for creating an atmosphere of respect and encouragement in this place),

Amen to that.