Odd performance observation

Performance Tuning
#1

Ok, this isn’t a gaming related observation but it is performance related. What I have is a benchmark that has been run by several people in a number of different environments and JDKs. The list includes HP-UX, Solaris 5.9, Mandrake linux, SuSe Linux, W2K, and XP. JDKs include 1.4.2_02, 1.4.2_04, 1.4.2_5 and the latest 1.5.0.

What I did was setup a micro-benchmark (Jeff hold your tongue, I know it’s a loaded weapon pointed at my foot :)) to look at the performance of the new for loop. I totally expected that the run times and memory profiles for each scenario would looke the same and those were the results that I got. What I didn’t expect to see was some strange numbers on my XP box. First to explain the test.

  • setup fixtures for the test
  • run the test to pre-heat the VM
  • call System.gc();
  • call sleep( 1000);
  • repeat many times
    - run the test (start timer, test, stop timer)
    - call gc
    - sleep

When I run this test in XP, I see a run time of about 200ms. This is result is repeatable in other XP environments and does not seem to depend on the version of the JDK.

If I eliminate the sleep, the run time DROPS to about 80ms (and no, the sleep is not in the metered section of code).

When I run this test on any of the other hardward/OS combinations, the numbers look ok.

So as bizzare as it sounds, some how, in XP, calling sleep affects how the thread will run AFTER sleep has long finished. I’ve looked at Java thread priority and it’s rock stable at 5. I can’t see how it can be a thread scheduling problem coming out of sleep since the thread is needs to be running to start the timer and perform the unit of work.

So the question here is, does anyone have any idea what might be going on?

#2

Maybe Windows swapped out the process during the sleep, hence it had to take time to swap it back in.

#3

[quote]Maybe Windows swapped out the process during the sleep, hence it had to take time to swap it back in.
[/quote]
Interesting thought…

I run with no swap. For the purposes of this exercise, I did configure a 1 gig swap space to make sure that the no swap space configuration was not at the root of the problem. That said, I suspect that XP silently configures some minimal amount of swap space that you can’t eliminate.

Although I didn’t note any disk activity during the test, I wasn’t expecting any and didn’t watch as closely as I should have ::). I just re-ran the test and this disk was fairly (but not 100%) quiet during the run. So it would seem as though the running process does trigger some extremely small amount of disk activity. This leads me to believe that everything may be sitting in (disk) cache and given that the system is otherwise idle, this amount of disk activity is only enough to trigger a sporadic read/write operation.

So, if the process is partly swapped out but only to disk cache (speculation here), then that might account for some of the difference. That said, I’m not sure that it should/account for a more than doubling of the timings.

I just had a run on a Mac and those numbers looked pretty clean so it’s looking more and more like this behavior is unique to XP.