Hi Ben, Are you saying that there is a problem with System.nanoTime() for this short and simple source code and that System.nanoTime() is not reliable to benchmark anything? I suspected that, but I've also measured using different native timers, clock_gettime and rdtsc, and the *exact same problem happens*. So I have to believe that I unequivocally demonstrated this problem and using JMH or other profiling tool won't change/solve anything.
Thanks! -JC On Saturday, April 29, 2017 at 10:02:11 AM UTC-5, Ben Evans wrote: > > You should start by rewriting this as a JMH benchmark. > > System.nanoTime based benchmarks are incredibly difficult to write without > error & it is far too easy to be misled or suffer from confirmation bias of > one form or another. > > As it stands, you haven't unequivocally demonstrated anything - sorry. > > Ben > > On 29 Apr 2017 15:56, "J Crawford" <latency...@mail.com <javascript:>> > wrote: > >> The mystery boils down to: >> >> "*The exact same block of code becomes slower after a busy spin >> pause.*" >> >> I posted a short source code that *unequivocally* proves and >> demonstrates the problem: >> http://stackoverflow.com/questions/43696948/why-does-the-jvm-show-more-latency-for-the-same-block-of-code-after-a-busy-spin >> >> Note that I'm not using Thread.sleep. Also note that there are no >> conditionals leading to a HotSpot/JIT de-optimization as I'm changing the >> pause using a math operation instead of an IF. >> >> The story told by the short source code is: >> >> - There is a block of math operations that I want to time. >> - First I time the block pausing 1 nanosecond before I start my >> measurement. I do that 20,000 times. >> - Then I change the pause from 1 nanosecond to 5 seconds and proceed to >> measure the latency as usual. I do that 15 times. >> - Then I print the last 30 measurements, so you can see 15 measurements >> with the pause of 1 nanosecond and 15 measurements with the pause of 5 >> seconds. >> >> As you can see below, *the discrepancy is big, *especially in the very >> first measurement after the pause change. *Why is that!?* >> >> $ java -server -cp . JvmPauseLatency >> Sat Apr 29 10:34:28 EDT 2017 => Please wait 75 seconds for the results... >> Sat Apr 29 10:35:43 EDT 2017 => Calculation: 4.0042328611017236E11 >> Results: >> 215 >> 214 >> 215 >> 214 >> 215 >> 214 >> 217 >> 215 >> 216 >> 214 >> 216 >> 213 >> 215 >> 214 >> 215 >> *2343* <----- FIRST MEASUREMENT AFTER PAUSE CHANGE >> 795 >> 727 >> 942 >> 778 >> 765 >> 856 >> 762 >> 801 >> 708 >> 692 >> 765 >> 776 >> 780 >> 754 >> >> Thanks! >> >> -JC >> >> -- >> You received this message because you are subscribed to the Google Groups >> "mechanical-sympathy" group. >> To unsubscribe from this group and stop receiving emails from it, send an >> email to mechanical-sympathy+unsubscr...@googlegroups.com <javascript:>. >> For more options, visit https://groups.google.com/d/optout. >> > -- You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group. To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-sympathy+unsubscr...@googlegroups.com. For more options, visit https://groups.google.com/d/optout.
