United StatesChange Country, Oracle Worldwide Web Sites Communities I am a... I want to...
Bug ID: JDK-6313903 Thread.sleep(3) might wake up immediately on windows
JDK-6313903 : Thread.sleep(3) might wake up immediately on windows

Details
Type:
Bug
Submit Date:
2005-08-22
Status:
Closed
Updated Date:
2014-01-27
Project Name:
JDK
Resolved Date:
2014-01-24
Component:
hotspot
OS:
windows_2003,windows_2000
Sub-Component:
runtime
CPU:
x86
Priority:
P5
Resolution:
Won't Fix
Affected Versions:
hs13,6
Fixed Versions:
tbd_major

Related Reports
Relates:
Relates:
Relates:
Relates:

Sub Tasks

Description
This program:
---------------------------------------------------
public class uu {
    public static void main(String[] args) throws Throwable {
	long t0 = System.currentTimeMillis();
	java.util.concurrent.TimeUnit.MILLISECONDS.sleep(3);
	System.out.println(System.currentTimeMillis()-t0);
    }
}
---------------------------------------------------
should print a number no less than 3, but on windows-amd64
and more rarely, windows-i586, it often prints 0.
Probably a hotspot bug (but it could conceivably be core libraries)

This causes j2se regtest test/java/util/concurrent/TimeUnit/Basic.java to fail
Doug Lea asked,

What happens if you instead just call Thread.sleep(3)?

Good question.

-----------------------------------------------------
public class uu {
    public static void main(String[] args) throws Throwable {
	if (args.length == 1 && args[0].equals("TimeUnit")) {
	    long t0 = System.currentTimeMillis();
	    java.util.concurrent.TimeUnit.MILLISECONDS.sleep(3);
	    System.out.println(System.currentTimeMillis()-t0);
	} else if (args.length == 1 && args[0].equals("Thread")) {
	    long t0 = System.currentTimeMillis();
	    Thread.sleep(3);
	    System.out.println(System.currentTimeMillis()-t0);
	}
    }
}
-----------------------------------------------------
The above program, when invoked with either argument "Thread" or "TimeUnit"
prints "0" on windows-amd64 most of the time.
So this is definitely not a TimeUnit bug.

                                    

Comments
EVALUATION

First of all the test is not quite accurate, System.currentTimeMillis has
a granularity of 10ms, if the code is changed to use System.nanoTime. 
The VM (1.6.0-b55) does sleep for the required time with no signs of chronic
insomnia, as observed earlier.

[K:/L/A/HS/6313903] cat ut.java
public class ut {
    public static void dojuc()  throws InterruptedException {
        //long t0 = System.currentTimeMillis();
        long t0 = System.nanoTime();
        java.util.concurrent.TimeUnit.MILLISECONDS.sleep(3);
        //System.out.println("timeunit:" + (System.currentTimeMillis()-t0));
        System.out.println("timeunit:" + (System.nanoTime()-t0)/1000000);
    }
    public static void main(String[] args) throws Throwable {
        for (int i = 0 ; i < 10 ; i++)      {
             dojuc();
        }

    }
}
[K:/L/A/HS/6313903] java ut
timeunit:15
timeunit:1
timeunit:3
timeunit:3
timeunit:3
timeunit:3
timeunit:3
timeunit:3
timeunit:3
timeunit:3

However the testing revealed that the first time it sleeps, it seems to 
sleep for a long time, and the second time its for a very short time
and then it stabilizes to 3msec (perhaps thread scheduling/clock transients), 
this is also consistent with a native test case, as follows:

[C:/XXXX] ./Insomnia on
MIN res : 1
MAX res : 1000000
sleepy time = 3, elapsed time=12.08533 secs HighRes(on)
sleepy time = 3, elapsed time=0.42910 secs HighRes(on)
sleepy time = 3, elapsed time=3.85608 secs HighRes(on)
sleepy time = 3, elapsed time=3.86530 secs HighRes(on)
sleepy time = 3, elapsed time=3.86613 secs HighRes(on)
sleepy time = 3, elapsed time=3.86697 secs HighRes(on)
sleepy time = 3, elapsed time=3.86865 secs HighRes(on)
sleepy time = 3, elapsed time=3.86530 secs HighRes(on)
sleepy time = 3, elapsed time=3.86166 secs HighRes(on)
sleepy time = 3, elapsed time=3.86837 secs HighRes(on)
Hit CR to coninue......

Here is the native test case:
// Insomnia.cpp : Defines the entry point for the console application.
#pragma comment( lib, "winmm" )

#include <iostream>
#include <tchar.h>
#include <windows.h>


class HighResolutionInterval {
  // The default timer resolution seems to be 10 milliseconds.
  // (Where is this written down?)
  // If someone wants to sleep for only a fraction of the default,
  // then we set the timer resolution down to 1 millisecond for 
  // the duration of their interval.
  // We carefully set the resolution back, since otherwise we 
  // seem to incur an overhead (3%?) that we don't need.
private:
	static const int DEFAULT_RESOLUTION=1;
public:
  HighResolutionInterval(long ms) {
      MMRESULT result = timeBeginPeriod(DEFAULT_RESOLUTION);
  }
  ~HighResolutionInterval() {
      MMRESULT result = timeEndPeriod(DEFAULT_RESOLUTION);
  }
};

int os_sleep(long ms, bool highResMode) {
	HANDLE events[1];
	   events[0] = CreateEvent( 
        NULL,   // no security attributes
        FALSE,  // auto-reset event object
        FALSE,  // initial state is nonsignaled
        NULL);  // unnamed object


	int result = -1;
	HighResolutionInterval *phri=NULL;
	if(highResMode)
		phri = new HighResolutionInterval( ms );
	if (WaitForMultipleObjects(1, events, FALSE, (DWORD)ms) == WAIT_TIMEOUT) {
		result = -3;
	} else {
		printf("Error in WaitForMultipleObjects\n");
		result = -2;
	}
	delete phri; //if it is NULL, harmless
	return result;
}

double gethrTime(LARGE_INTEGER freq) {

	LARGE_INTEGER hrcount;

	if (QueryPerformanceCounter(&hrcount) != TRUE) {
		printf("Error: QueryPerformanceCounter\n");
		exit(-12);
	}
	
	return ((double)(hrcount.QuadPart)/(double)(freq.QuadPart))*1000;
}
int _tmain(int argc, _TCHAR* argv[]) {
	bool highResMode = (argc > 1 && _stricmp(argv[1],"on") == 0) ? TRUE : FALSE;
	long ms = ((argc > 2 && *argv[2] != '\0') ? atol(argv[2]) : 3L);
	TIMECAPS tc;
	memset(&tc,0,sizeof(tc));
	if (timeGetDevCaps(&tc, sizeof(TIMECAPS)) != TIMERR_NOERROR) {
		printf("Error: timeGetDevCaps failed\n");
		exit(-1);
	}

	printf("MIN res : %d\n", tc.wPeriodMin);
	printf("MAX res : %d\n", tc.wPeriodMax);

	LARGE_INTEGER freq;
	if (QueryPerformanceFrequency(&freq) !=	TRUE) {
		printf("Error: QueryPerformanceFrequency\n");
		exit(-10);
	}
	if (freq.QuadPart == 1000) {
		printf("Error: QueryPerformanceFrequency resolution	not	supported\n");
		exit(-11);
	}

	for (int i = 0 ; i < 10 ; i++) {
		double t0 = gethrTime(freq);
		os_sleep(ms, highResMode);
		double t1 = gethrTime(freq);
		printf("sleepy time = %d, elapsed time=%2.5f secs HighRes%s\n", ms, t1-t0, (highResMode) ? "(on)" : "(off)" );
	}
	printf("Hit CR to continue......\n");
	while (getchar() != '\n');
	return 0;
}

based on the above test result,I am downgrading this bug to P5 and will be 
reporting this to Microsoft through the established channels, until then.....
                                     
2005-10-10
We don't support Windows XP anymore, anyone running into this on Windows 2003 probably already has applied the patch from Microsoft. 
                                     
2014-01-24
This issue is not specific to Windows XP. This is a general problem on all Windows platforms - the Thread.sleep time is wildly unpredictable.

D:\testcode>more SleepAccuracy.java
public class SleepAccuracy {
  public static void main(String[] args) throws Throwable {
    long delay = 1;
    for (int i = 0; i < 5; i++) {
      long start = System.nanoTime();
      Thread.sleep(delay);
      long end = System.nanoTime();
      System.out.printf("Expected %dms, actual %.2fms%n", delay, (end-start)/(1000.0*1000));
    }
  }
}

D:\testcode>d:\tools\apps\Java\64\jdk1.8.0\bin\java SleepAccuracy
Expected 1ms, actual 4.33ms
Expected 1ms, actual 14.61ms
Expected 1ms, actual 13.98ms
Expected 1ms, actual 0.74ms
Expected 1ms, actual 14.87ms

D:\testcode>d:\tools\apps\Java\64\jdk1.8.0\bin\java -XX:+ForceTimeHighResolution SleepAccuracy
Expected 1ms, actual 12.51ms
Expected 1ms, actual 14.22ms
Expected 1ms, actual 14.62ms
Expected 1ms, actual 14.89ms
Expected 1ms, actual 13.61ms

D:\testcode>d:\tools\apps\Java\64\jdk1.8.0\bin\java -XX:+ForceTimeHighResolution SleepAccuracy
Expected 1ms, actual 8.92ms
Expected 1ms, actual 14.81ms
Expected 1ms, actual 14.59ms
Expected 1ms, actual 11.79ms
Expected 1ms, actual 13.40ms


D:\testcode>ver

Microsoft Windows [Version 6.1.7601]


ie Windows 7.

Please re-open.
                                     
2014-01-27
EVALUATION

Note as per 5068368 there is no explicit requirement that a sleep last for at least the amount of time requested, so an early return is valid according to the JLS third edition.

That said, the very short sleeps that have been observed seem to fall outside the realm of expected behaviour and so require further investigation. It is unclear at this stage whether the problem is with the sleep, or the use of System.nanoTime to measure the elapsed time.
                                     
2006-06-02



Hardware and Software, Engineered to Work Together