Thread.sleep() in Windows XP won't do short sleeps

[Steve11235]

This is a follow up to a previous post.

I have the same problem as before, which you can see by looking at the output. However, this time, I'm running on a four processor Intel box with 4 gig of memory. Please note, this is a Windows XP specific problem. (And yes, I know XP only uses 3 gig of the 4...)

Creating a thread with a very long sleep is supposed to correct this behavior, but I can't make it work. The code runs; can anyone tweak it to get the expected behavior?

package tests;

public class SleepTest {

    public static void main(String[] args) {
        final SleepTest instance = new SleepTest();
        instance.run();
    }

    public void run() {
        final Thread ripVanWinkle;
        long startTime = 0;

        // Rip VanWinkle is a fable about a man who slept for 20 years...
        ripVanWinkle = new Thread(new Runnable() {

            public void run() {
                try {
                    Thread.sleep(Integer.MAX_VALUE);
                }
                catch (InterruptedException ex) {
                }
            }
        });
        ripVanWinkle.setDaemon(true);
        ripVanWinkle.start();
        /*
         * Let Rip get going
         */
        try {
            Thread.sleep(100);
        }
        catch (InterruptedException ex) {
        }

        for (int i = 1; i <= 50; i++) {
            startTime = System.currentTimeMillis();
            try {
                // Throw in some nanos, just to see...
                Thread.sleep(i, 987654);
            }
            catch (InterruptedException ex) {
            }
            System.out.println("Slept: " + i + ", lasted: " + (System.currentTimeMillis() - startTime));
        }
    }
}

Output:

run:
Slept: 1, lasted: 0
Slept: 2, lasted: 15
Slept: 3, lasted: 0
Slept: 4, lasted: 0
Slept: 5, lasted: 16
Slept: 6, lasted: 0
Slept: 7, lasted: 15
Slept: 8, lasted: 0
Slept: 9, lasted: 16
Slept: 10, lasted: 16
Slept: 11, lasted: 15
Slept: 12, lasted: 0
Slept: 13, lasted: 16
Slept: 14, lasted: 16
Slept: 15, lasted: 15
Slept: 16, lasted: 31
Slept: 17, lasted: 16
Slept: 18, lasted: 16
Slept: 19, lasted: 15
Slept: 20, lasted: 32
Slept: 21, lasted: 15
Slept: 22, lasted: 31
Slept: 23, lasted: 16
Slept: 24, lasted: 31
Slept: 25, lasted: 32
Slept: 26, lasted: 15
Slept: 27, lasted: 31
Slept: 28, lasted: 32
Slept: 29, lasted: 31
Slept: 30, lasted: 31
Slept: 31, lasted: 31
Slept: 32, lasted: 32
Slept: 33, lasted: 31
Slept: 34, lasted: 47
Slept: 35, lasted: 31
Slept: 36, lasted: 31
Slept: 37, lasted: 47
Slept: 38, lasted: 31
Slept: 39, lasted: 47
Slept: 40, lasted: 32
Slept: 41, lasted: 46
Slept: 42, lasted: 47
Slept: 43, lasted: 47
Slept: 44, lasted: 47
Slept: 45, lasted: 47
Slept: 46, lasted: 47
Slept: 47, lasted: 47
Slept: 48, lasted: 47
Slept: 49, lasted: 46
Slept: 50, lasted: 63
BUILD SUCCESSFUL (total time: 1 second)

[neilcoffey]

Steve, are you sure the problem you're seeing isn't just the poor granularity of System.currentTimeMillis()?

In general, you should use System.nanoTime() for this kind of measurement.

[angryboy]

 Thread.sleep(i, 987654);

haha, did you ever take a look at the src for this?
the nano doesn't do anything on windows as of jdk1.6u13

Oh yeah, you should use nanoTime or some jni timer.

[neilcoffey]

BTW, as I recall, the nanos are rounded up/down to the nearest milli. But yes, certainly the number of nanoseconds won't be honoured, and I don't think there's a maintstream OS that schedules with nanosecond granularity. Not just yet!!!

[Steve11235]

Neil- Thanks, U Da' Man!

AB- I wanted to try every silly little thing. I does seem to make a difference; although, as you pointed out, it seems to round off.

To recap what Neil said, System.currentTimeMillis() is only accurate to 15 millisecond intervals. *Not* good for measurements like this. Use System.nanoTime() instead, divide by 1000000d if desired.

For posterity, here are the results, without the silly nanos added to the sleep:

run:
Slept: 1, lasted: 2.0
Slept: 2, lasted: 2.0
Slept: 3, lasted: 3.7
Slept: 4, lasted: 4.7
Slept: 5, lasted: 5.7
Slept: 6, lasted: 6.6
Slept: 7, lasted: 7.6
Slept: 8, lasted: 8.6
Slept: 9, lasted: 9.6
Slept: 10, lasted: 10.6
Slept: 11, lasted: 11.5
Slept: 12, lasted: 12.6
Slept: 13, lasted: 13.5
Slept: 14, lasted: 14.5
Slept: 15, lasted: 15.5
Slept: 16, lasted: 16.5
Slept: 17, lasted: 17.4
Slept: 18, lasted: 18.4
Slept: 19, lasted: 19.4
Slept: 20, lasted: 20.4
Slept: 21, lasted: 21.3
Slept: 22, lasted: 22.3
Slept: 23, lasted: 23.3
Slept: 24, lasted: 24.3
Slept: 25, lasted: 25.3
Slept: 26, lasted: 26.2
Slept: 27, lasted: 27.2
Slept: 28, lasted: 28.1
Slept: 29, lasted: 29.1
Slept: 30, lasted: 30.1
Slept: 31, lasted: 31.1
Slept: 32, lasted: 32.0
Slept: 33, lasted: 33.1
Slept: 34, lasted: 34.0
Slept: 35, lasted: 35.0
Slept: 36, lasted: 36.0
Slept: 37, lasted: 36.9
Slept: 38, lasted: 37.9
Slept: 39, lasted: 38.9
Slept: 40, lasted: 39.9
Slept: 41, lasted: 40.9
Slept: 42, lasted: 42.8
Slept: 43, lasted: 43.8
Slept: 44, lasted: 44.8
Slept: 45, lasted: 45.8
Slept: 46, lasted: 46.7
Slept: 47, lasted: 47.7
Slept: 48, lasted: 48.6
Slept: 49, lasted: 49.6
Slept: 50, lasted: 50.6
BUILD SUCCESSFUL (total time: 1 second)

[neilcoffey]

As far as I can see, this squares with Thread.sleep measurements that I've made under Windows: on a quiet system, Windows can pretty much honour your requested sleep to the nearest millisecond, but if anything will tend to oversleep.

[Steve11235]

Dear Microsoft-

I've said a lot of nasty things about Windows over the years. I take this one back...

-Sincerely, Steve