Well, this is making me crazy. I started this investigation by asking (what I now realize was)
the wrong question. I have, I believe, discovered that there is something very odd about Thread.sleep(), at least on my computer(s).
Here is a
SSCCE that sleeps for 33 milliseconds, then calls a method that counts the number of times in can call System.nanoTime() in two milliseconds:
The program reports how many microseconds it spent in the counting method (called "runInPlace"), and the number of times that method was able to call System.nanoTime() in that time. Its reports don't make a lot of sense. It pretty consistently reports that the method consumed a bit more than 2000 microseconds. That makes sense because the inner loop spins until two milliseconds have passed. But the number of times the inner loop spun varies incomprehensibly between (more or less) 170000 and (more or less) 37000.
Here's a sample of the output stream:
2001 171820
2002 176670
2006 29625
2002 154702
2003 38966
2004 33603
2001 170230
2001 169501
2003 39112
2001 175607
2001 165862
2147 21083
2001 169463
2005 31233
2004 37554
2002 175983
2121 37125
2005 34730
2001 176095
2001 170735
2003 36693
2001 172015
2005 38116
2005 25268
2069 169174
2005 30537
2004 37003
2002 172018
2001 174749
2006 34543
Apparently, something is competing with that inner loop for cycles,
some of the time, but not
always.
Now for the weird part. If I reduce that sleep interval down from 33 milliseconds to two milliseconds, the output looks more like this:
2001 173250
2001 160504
2002 165972
2058 36507
2002 38733
2003 35308
2004 38405
2006 36977
2002 39147
2005 36862
2001 161141
2001 176997
2003 170801
2001 189434
2004 179530
2001 170918
2001 184679
2001 174369
2009 170825
2002 164151
2001 172332
2001 171053
2002 170054
2000 169657
2011 100535
2003 31563
2003 38671
2006 34673
2005 36679
2004 38141
3723 28390
2002 172978
2002 174655
2002 168686
2001 171983
2001 169960
2002 137682
2001 169799
2002 166603
2001 166092
2002 154441
2002 167207
The evidence of competition for cycles is reduced and, bizarrely, appears
clumped together. Reducing the interval down from two milliseconds to just one changes things even more:
2000 173995
2000 191856
2001 174750
2001 169440
2030 46263
2002 155079
2001 168817
2002 179604
2010 184060
2000 180545
2000 156150
2001 169960
2008 175102
2000 177187
2000 176533
2000 157695
2001 176429
2000 176863
2000 175523
2011 172235
2000 172486
2000 175641
2000 166323
2000 168715
2006 170260
2005 171373
2001 179768
2011 171290
2000 168324
2000 170536
2012 167658
2000 168494
2000 169004
2000 166461
2000 169391
2000 172814
2000 172550
2000 173767
2000 176645
The evidence of competition nearly disappears (and, given that the method time was a bit longer for that one instance, maybe this could be written off to some infrequent system overhead).
Why would changing the interval spent in Thread.sleep() make any difference to the operation of code that runs later?
Now, if you change Lines 12 through 19 from being a call to Thread.sleep() to a spinning delay that lasts 33 milliseconds, like this:
The effect on the counter method vanishes:
2000 191868
2000 184147
2000 192227
2000 189815
2000 191530
2000 191909
2000 189713
2000 180404
2000 191293
2000 191520
2000 190819
2000 191891
2000 192143
2000 191756
2000 181665
2000 178947
2000 191945
2000 190592
2000 191910
2000 191463
2000 191174
2000 191274
2000 184063
2000 169940
2000 191352
2000 183522
2000 191550
2000 191642
2000 187369
2000 189795
2000 188144
2000 188273
2000 189898
2000 191272
2000 178875
2000 156015
2000 186361
Note also that, on average, the counter method manages to run its inner loop a few more times than when Thread.sleep() was called. Note also that the time spent in the counter method, runInPlace, is
always 2000 microseconds. In the prior runs, when Thread.sleep() was used, it frequently takes noticeably longer (2001, 2002, 2003, and so on; not
much longer, but noticeably longer).
This is enough on its own to make me crazy, but it gets worse: I've written variations on this code that puts the Thread.sleep() call and the call to runInPlace on different threads, and that makes no difference to the behavior I am observing. I've submitted those threads to different cores, and it makes no difference. I've used Sockets to have the Thread.sleep() call run in
a different process than the process running runInPlace, and
it makes no difference. Every single time I call Thread.sleep(), it has some side-effect on the subsequent behavior of runInPlace, while using a spinning delay loop has no effect.
To go on with this scintillating saga, I've run this code on four different computers. No two behave exactly alike. The erratic results returned from runInPlace can be seen on two other machines, but not on the third. All show different rates of looping, depending on whether or not Thread.sleep() is called or I use a spinning delay loop, but
one machine reports that using Thread.sleep() makes the counting loop run
faster than when the spinning delay is used (the other three all report that the spinning delay makes the loop faster).
None of this makes any sense to me. I just don't see how swapping a spinning delay for a call to Thread.sleep(), when both are delaying/sleeping for the same 33 milliseconds, can even be detectable in other code, much less have effects like this.
Winston? Stephan? Can anyone give me a possible reason, or even another line of investigation for this? I think I'm out of my league with this one and could really use some help.