• Post Reply Bookmark Topic Watch Topic
  • New Topic
programming forums Java Mobile Certification Databases Caching Books Engineering Micro Controllers OS Languages Paradigms IDEs Build Tools Frameworks Application Servers Open Source This Site Careers Other Pie Elite all forums
this forum made possible by our volunteer staff, including ...
Marshals:
  • Campbell Ritchie
  • Jeanne Boyarsky
  • Ron McLeod
  • Paul Clapham
  • Liutauras Vilda
Sheriffs:
  • paul wheaton
  • Rob Spoor
  • Devaka Cooray
Saloon Keepers:
  • Stephan van Hulst
  • Tim Holloway
  • Carey Brown
  • Frits Walraven
  • Tim Moores
Bartenders:
  • Mikalai Zaikin

Run-Time Side Effects of Thread.sleep()

 
Bartender
Posts: 1464
32
Netbeans IDE C++ Java Windows
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
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.
 
Ranch Hand
Posts: 76
3
IntelliJ IDE Java Windows
  • Likes 1
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Is it possible that this is connected to how the JVM might try to optimise on the fly during runtime? It might be worth running a tool that can see how the running machine code changes in this regard. I remember seeing a talk on this a week or so back. Here: https://vimeo.com/131394615

But this is all speculation on my end, of course. It's going to be interesting to see how this discussion turns out
 
Stevens Miller
Bartender
Posts: 1464
32
Netbeans IDE C++ Java Windows
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
Thanks, Ole. Looking at the compiled code for runInPlace might be a good idea.

Another thought that crossed my mind was that, just maybe, Thread.sleep temporarily affects the JVM's clock. There is a distant warning about something similar in the MSDN documentation on the Windows API Sleep function.. Thread.sleep()'s actual code is invisible to us, as it is implemented as a native method in the Thread class. It may be nothing more than a call to Windows's Sleep function. If so, there may be other ways to test this that go beyond Java. Meanwhile, I could test my clock idea if I knew of another way to get accurate time. Going to look into that now...
 
Stevens Miller
Bartender
Posts: 1464
32
Netbeans IDE C++ Java Windows
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
I wrote a similar program in C++. The behavior is the same, under Windows 10. Here's my code:



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 this?
 
Stevens Miller
Bartender
Posts: 1464
32
Netbeans IDE C++ Java Windows
  • Mark post as helpful
  • send pies
    Number of slices to send:
    Optional 'thank-you' note:
  • Quote
  • Report post to moderator
I haven't moved this thread because the Java side of this whole inquiry may not be relevant. Instead, I've started a new thread in the C/C++ forum. Hope someone will be able to unravel it there.
 
If a regular clown is funny, then a larger clown would be funnier. Math. Verified by this tiny ad:
a bit of art, as a gift, that will fit in a stocking
https://gardener-gift.com
reply
    Bookmark Topic Watch Topic
  • New Topic