JDK-8154302 : C2 removes safepoint poll from loop
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 8,9,10
  • Priority: P3
  • Status: Closed
  • Resolution: Duplicate
  • OS: generic
  • CPU: generic
  • Submitted: 2016-04-09
  • Updated: 2022-04-26
  • Resolved: 2017-12-04
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 10
10Resolved
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Description
FULL PRODUCT VERSION :
java version "1.8.0_77"
Java(TM) SE Runtime Environment (build 1.8.0_77-b03)
Java HotSpot(TM) 64-Bit Server VM (build 25.77-b03, mixed mode)

ADDITIONAL OS VERSION INFORMATION :
Microsoft Windows [版本 10.0.10586]

EXTRA RELEVANT SYSTEM CONFIGURATION :
notebook computer 
ASUS A550JK 
CPU:Intel(R) Core(TM) i7-4710HQ @2.50GHz

A DESCRIPTION OF THE PROBLEM :
If there are some threads(less than the number of computer's logic cpus) working with a endless loop(in that loop:increases an int variable(eg: ++i) and makes a comparison with '==',and has a volatile write), the function 'Thread.sleep' in other thread won't work correctly.

REGRESSION.  Last worked in version 8u77

ADDITIONAL REGRESSION INFORMATION: 
java version "1.8.0_77"
Java(TM) SE Runtime Environment (build 1.8.0_77-b03)
Java HotSpot(TM) 64-Bit Server VM (build 25.77-b03, mixed mode)

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Just execute the test

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
The console will print the sleep time per half-second:
sleep time:0            vInt:0
sleep time:501          vInt:20982098
sleep time:500          vInt:41807469
sleep time:500          vInt:65160899
sleep time:501          vInt:90615990
sleep time:500          vInt:115868104
sleep time:501          vInt:134387463
sleep time:500          vInt:157016031
sleep time:500          vInt:177084187

ACTUAL -
It takes a long time(it's 96 seconds in this test) to print the third printout, means that it slept 96 seconds rather than 0.5 second
sleep time:0            vInt:0
sleep time:501          vInt:19474440
sleep time:96389                vInt:103
sleep time:500          vInt:23039342
sleep time:500          vInt:43348896
sleep time:501          vInt:64601276
sleep time:500          vInt:90043833
sleep time:500          vInt:108501281
sleep time:501          vInt:131417790
sleep time:500          vInt:153950317

And the running jvisualvm.exe will frozen once this test start.

REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
public class SleepTest {
	private static volatile int vInt = 0;
	public static void main(String[] args){
		for(int n=0;n<2;n++){
			new Thread(){
				public void run() {
					int l=0,m=0;
					while(true){
						if(++l==0){
							if(++m == 0)
								//insure that it won't be optimized away
								System.out.println(l);
						}
						vInt=l;
					}
				}
			}.start();
		}
		long oldTime = System.currentTimeMillis();
		while(true){
			System.out.println("sleep time:"+(-oldTime+(oldTime = System.currentTimeMillis()))+"\t\tvInt:"+vInt);
			try {
				Thread.sleep(500);
			} catch (InterruptedException e) {}
		}
	}
}
---------- END SOURCE ----------


Comments
Thanks Roland, I've filed JDK-8192977 for the LoopStripMiningIter=1000 problem. I'll close this bug as a duplicate of JDK-8186027. Loop strip mining helps but to get maximum responsiveness one needs to specify -XX:+UseCountedLoopSafepoint to enforce safepoint polls in each loop iteration.
04-12-2017

There's indeed a small inconsistency in the way UseCountedLoopSafepoints/LoopStripMiningIter is treated for G1: default is +UseCountedLoopSafepoints, LoopStripMiningIter=1000 but with: java -XX:+UseCountedLoopSafepoint a message is printed: When counted loop safepoints are enabled, LoopStripMiningIter must be at least 1 (a safepoint every 1 iteration): setting it to 1 but LoopStripMiningIter is set to 1000 So if you want the pre loop strip mining behaviour of +UseCountedLoopSafepoint, you need to pass -XX:+UseCountedLoopSafepoint -XX:LoopStripMiningIter=1 I'll fix it with a different bug. With loop strip mining, when there's a big jump in sleep time, the 2 threads are stuck in a post loop of SleepTest$1.run(). There's no safepoint polling in post loops with strip mining as the expectation is that it runs for few iterations. The VM is waiting for a safepoint, and the 2 threads run until ++l == 0 which the compiler expects is the exit condition of the loop. The method is then deoptimized (branch never taken) and execution resumes in the interpreter, the safepoint occurs and the threads go back to the infinite loop. All this happens because c2 compiles the infinite loop in an OSR compilation as a strange counted loop.
01-12-2017

[~fmatte] just pointed me to this stack overflow thread: https://stackoverflow.com/questions/47500446/why-isnt-the-last-thread-interrupted Seems like [~apangin] came to the same conclusion regarding this bug. So the remaining question is why loop strip mining does not fix the issue. The issue with the Thread.interrupted() intrinsic not including a safepoint poll seems to be independent of this bug.
29-11-2017

ILW = Safepoint poll is removed from loop causing unresponsive threads, easy to reproduce, -XX:+UseCountedLoopSafepoints (only works with <= JDK 9) or -XX:-PartialPeelLoop = MHM = P3
29-11-2017

I confirm this is compiler issue, Forcing compiler to add safepoint polls in loops (-XX:+UseCountedLoopSafepoints) fixes this issue. below results confirm the same ==using -XX:+UseCountedLoopSafepoints=== java -XX:+UseCountedLoopSafepoints SleepTest sleep time:1 vInt:4014 sleep time:500 vInt:12776521 sleep time:500 vInt:38312326 sleep time:501 vInt:43015187 sleep time:500 vInt:61834002 sleep time:500 vInt:79765403 sleep time:501 vInt:97634422 sleep time:500 vInt:117724638 sleep time:500 vInt:135509659 sleep time:500 vInt:148608887 sleep time:501 vInt:169960402 sleep time:500 vInt:207042945 sleep time:500 vInt:208576174 sleep time:501 vInt:226982896 sleep time:500 vInt:246627932 sleep time:500 vInt:264987622 This is most likely duplicate of JDK-8186027
29-11-2017

Executing with -XX:LoopUnrollLimit=0 generates the following code for the loop in SleepTest$1.run(): ;; B3: # B3 B4 <- B2 B3 Loop: B3-B3 inner Freq: 1e+06 0x00007f35fcd44110: mov %ebx,0x70(%r10) 0x00007f35fcd44114: lock addl $0x0,-0x40(%rsp) ;*putstatic vInt {reexecute=0 rethrow=0 return_oop=0} ; - SleepTest::access$002@2 (line 1) ; - SleepTest$1::run@26 (line 14) 0x00007f35fcd4411a: inc %ebx 0x00007f35fcd4411c: test %ebx,%ebx 0x00007f35fcd4411e: jne 0x00007f35fcd44110 ;*iinc {reexecute=0 rethrow=0 return_oop=0} ; - SleepTest$1::run@4 (line 9) The problem is that there is no safepoint poll in the loop. This is because C2 does partial peeling, treats the loop as counted and then removes the safepoint poll: Loop: N0/N0 has_sfpt Loop: N170/N169 sfpts={ 172 } Loop: N171/N85 counted [int,0),+1 (133396 iters) has_sfpt strip_mined With -XX:-PartialPeelLoop the loop looks fine: ;; B2: # B3 <- B3 top-of-loop Freq: 1e+06 0x00007f18e9174780: mov %ebp,0x70(%r10) 0x00007f18e9174784: lock addl $0x0,-0x40(%rsp) ;*putstatic vInt {reexecute=0 rethrow=0 return_oop=0} ; - SleepTest::access$002@2 (line 1) ; - SleepTest$1::run@26 (line 14) 0x00007f18e917478a: mov 0x80(%r15),%r11 ; ImmutableOopMap{r10=Oop } ;*goto {reexecute=1 rethrow=0 return_oop=0} ; - SleepTest$1::run@30 (line 14) 0x00007f18e9174791: test %eax,(%r11) ; {poll} ;; B3: # B2 B4 <- B1 B2 Loop: B3-B2 inner Freq: 1e+06 It seems like -XX:+UseCountedLoopSafepoints solves this for JDK 9 but does not work with latest JDK 10: java -XX:+UseCountedLoopSafepoints SleepTest Java HotSpot(TM) 64-Bit Server VM warning: When counted loop safepoints are enabled, LoopStripMiningIter must be at least 1 (a safepoint every 1 iteration): setting it to 1 sleep time:0 vInt:255 sleep time:542 vInt:22088950 sleep time:104820 vInt:1090 sleep time:500 vInt:20257344 sleep time:500 vInt:38843764 sleep time:500 vInt:62653667 [~roland], any idea why that is? Seems like your changes for JDK-8186027 changed the behavior.
29-11-2017

Test Result: ######### OS : Windows 7 64-bit JDK: 8uXX : Fail 9ea+111: Fail ====================================== O/P: ****** c:\ji\core-libs>java -version java version "9-ea" Java(TM) SE Runtime Environment (build 9-ea+111) Java HotSpot(TM) 64-Bit Server VM (build 9-ea+111, mixed mode) =========================================================== With Volatile variable =========================================================== c:\ji\core-libs>javac SleepTest.java ------------------------------------------------------------- Without -Xint ------------------------------------------------------------- c:\ji\core-libs>java SleepTest sleep time:0 vInt:0 sleep time:567 vInt:18975440 =>sleep time:94841 vInt:1317860 =>sleep time:165032 vInt:-2110448028 sleep time:500 vInt:-2063116512 sleep time:500 vInt:-2069259074 sleep time:500 vInt:-2022245538 sleep time:500 vInt:-2007253256 sleep time:500 vInt:-2015679241 sleep time:501 vInt:-1965246047 sleep time:500 vInt:-1978392688 c:\ji\core-libs> ------------------------------------------------------------- With -Xint ------------------------------------------------------------- c:\ji\core-libs>java -Xint SleepTest sleep time:0 vInt:1870 sleep time:571 vInt:10382895 sleep time:500 vInt:18606211 sleep time:501 vInt:27112554 sleep time:500 vInt:36079285 sleep time:500 vInt:45125665 sleep time:500 vInt:54377972 sleep time:500 vInt:63791509 sleep time:500 vInt:73385226 sleep time:500 vInt:81814045 c:\ji\core-libs> ======================================================================================================================================== Without Volatile variable =================== ------------------------------------------------------------ Without -Xint ------------------------------------------------------------ c:\ji\core-libs>javac SleepTest.java c:\ji\core-libs>java SleepTest sleep time:0 vInt:255 sleep time:565 vInt:964601698 sleep time:1883 vInt:1065 sleep time:501 vInt:766029465 sleep time:500 vInt:1475300442 sleep time:500 vInt:-2025582293 sleep time:500 vInt:-1375761579 sleep time:500 vInt:-643954595 sleep time:501 vInt:90739714 sleep time:500 vInt:775318796 sleep time:500 vInt:1481394078 sleep time:500 vInt:-2111508677 c:\ji\core-libs> ------------------------------------------------------------ with -Xint ------------------------------------------------------------ c:\ji\core-libs>java -Xint SleepTest sleep time:0 vInt:2054 sleep time:556 vInt:12321690 sleep time:500 vInt:21888311 sleep time:500 vInt:32826803 sleep time:500 vInt:43883225 sleep time:500 vInt:54700163 sleep time:500 vInt:65408200 c:\ji\core-libs>
15-04-2016