Here is the small code which I am trying. This program takes good amount of time to execute. While running, if I try to kill it through the terminate button in eclipse, it returns Terminate Failed
. I can kill it from terminal using kill -9 <PID>
.
But, when I don't print the variable result in the last line of the program (Please check the commented portion of the code), the program exits immediately.
I am wondering :
Why is it taking time to execute when the value of result is being printed?
Please note, if I don't print value
, the same loop gets over immediately.
Why is eclipse not able to kill the program?
Update 1 : It seems JVM is optimize the code during the runtime (not in compile time). This thread is helpful.
Update 2 : When I print the value of value
, jstack <PID>
is not working. Only jstack -F <PID>
is working. Any possible reason?
public class TestClient { private static void loop() { long value =0; for (int j = 0; j < 50000; j++) { for (int i = 0; i < 100000000; i++) { value += 1; } } //When the value is being printed, the program //is taking time to complete System.out.println("Done "+ value); //When the value is NOT being printed, the program //completes immediately //System.out.println("Done "); } public static void main(String[] args) { loop(); } }
Basically, the infinite loop happens when the condition in the while loop always evaluates to true. This can happen when the variables within the loop aren't updated correctly, or aren't updated at all. Let's say you have a variable that's set to 10 and you want to loop while the value is less than 100.
Do-While Loop. A do-while loop is very similar to a while loop but there is one significant difference: Unlike with a while loop, the condition is checked at the end of each iteration. This means that a do-while loop is always executed at least once.
@ErwinBolwidt there are probably more accurate duplicates, but the idea is that System. out. println is not synchronized, that's why the output appears only after the loop is over.
The main() method just controls the repeating of your program.
This is a JIT compiler optimization (not java compiler optimization).
If you compare the byte code generated by java compiler for the two versions you will see that the loop is present in both of them.
This is how the decompiled method with println looks:
private static void loop() { long value = 0L; for(int j = 0; j < '썐'; ++j) { for(int i = 0; i < 100000000; ++i) { ++value; } } System.out.println("Done " + value); }
This is how the decompiled method looks when println is removed:
private static void loop() { long value = 0L; for(int j = 0; j < '썐'; ++j) { for(int i = 0; i < 100000000; ++i) { ++value; } } }
As you can see the loops are still there.
However you can enable JIT compiler logging and assembly printing with the following JVM options:
-XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation -XX:+PrintAssembly
You may also need to download the hsdis-amd64.dylib and put in your working directory (MacOS, HotSpot Java 8)
After you run the TestClient you should see the code produced by JIT compiler in the console. Here I will post only excerpt from the output.
Version without println:
# {method} 'loop' '()V' in 'test/TestClient' 0x000000010e3c2500: callq 0x000000010dc1c202 ; {runtime_call} 0x000000010e3c2505: data32 data32 nopw 0x0(%rax,%rax,1) 0x000000010e3c2510: sub $0x18,%rsp 0x000000010e3c2517: mov %rbp,0x10(%rsp) 0x000000010e3c251c: mov %rsi,%rdi 0x000000010e3c251f: movabs $0x10dc760ec,%r10 0x000000010e3c2529: callq *%r10 ;*iload_3 ; - test.TestClient::loop@12 (line 9) 0x000000010e3c252c: add $0x10,%rsp 0x000000010e3c2530: pop %rbp 0x000000010e3c2531: test %eax,-0x1c18537(%rip) # 0x000000010c7aa000 ; {poll_return} 0x000000010e3c2537: retq
Version with println:
# {method} 'loop' '()V' in 'test/TestClient' 0x00000001092c36c0: callq 0x0000000108c1c202 ; {runtime_call} 0x00000001092c36c5: data32 data32 nopw 0x0(%rax,%rax,1) 0x00000001092c36d0: mov %eax,-0x14000(%rsp) 0x00000001092c36d7: push %rbp 0x00000001092c36d8: sub $0x10,%rsp 0x00000001092c36dc: mov 0x10(%rsi),%r13 0x00000001092c36e0: mov 0x8(%rsi),%ebp 0x00000001092c36e3: mov (%rsi),%ebx 0x00000001092c36e5: mov %rsi,%rdi 0x00000001092c36e8: movabs $0x108c760ec,%r10 0x00000001092c36f2: callq *%r10 0x00000001092c36f5: jmp 0x00000001092c3740 0x00000001092c36f7: add $0x1,%r13 ;*iload_3 ; - test.TestClient::loop@12 (line 9) 0x00000001092c36fb: inc %ebx ;*iinc ; - test.TestClient::loop@22 (line 9) 0x00000001092c36fd: cmp $0x5f5e101,%ebx 0x00000001092c3703: jl 0x00000001092c36f7 ;*if_icmpge ; - test.TestClient::loop@15 (line 9) 0x00000001092c3705: jmp 0x00000001092c3734 0x00000001092c3707: nopw 0x0(%rax,%rax,1) 0x00000001092c3710: mov %r13,%r8 ;*iload_3 ; - test.TestClient::loop@12 (line 9) 0x00000001092c3713: mov %r8,%r13 0x00000001092c3716: add $0x10,%r13 ;*ladd ; - test.TestClient::loop@20 (line 10) 0x00000001092c371a: add $0x10,%ebx ;*iinc ; - test.TestClient::loop@22 (line 9) 0x00000001092c371d: cmp $0x5f5e0f2,%ebx 0x00000001092c3723: jl 0x00000001092c3710 ;*if_icmpge ; - test.TestClient::loop@15 (line 9) 0x00000001092c3725: add $0xf,%r8 ;*ladd ; - test.TestClient::loop@20 (line 10) 0x00000001092c3729: cmp $0x5f5e101,%ebx 0x00000001092c372f: jl 0x00000001092c36fb 0x00000001092c3731: mov %r8,%r13 ;*iload_3 ; - test.TestClient::loop@12 (line 9) 0x00000001092c3734: inc %ebp ;*iinc ; - test.TestClient::loop@28 (line 8) 0x00000001092c3736: cmp $0xc350,%ebp 0x00000001092c373c: jge 0x00000001092c376c ;*if_icmpge ; - test.TestClient::loop@7 (line 8) 0x00000001092c373e: xor %ebx,%ebx 0x00000001092c3740: mov %ebx,%r11d 0x00000001092c3743: inc %r11d ;*iload_3 ; - test.TestClient::loop@12 (line 9) 0x00000001092c3746: mov %r13,%r8 0x00000001092c3749: add $0x1,%r8 ;*ladd ; - test.TestClient::loop@20 (line 10) 0x00000001092c374d: inc %ebx ;*iinc ; - test.TestClient::loop@22 (line 9) 0x00000001092c374f: cmp %r11d,%ebx 0x00000001092c3752: jge 0x00000001092c3759 ;*if_icmpge ; - test.TestClient::loop@15 (line 9) 0x00000001092c3754: mov %r8,%r13 0x00000001092c3757: jmp 0x00000001092c3746 0x00000001092c3759: cmp $0x5f5e0f2,%ebx 0x00000001092c375f: jl 0x00000001092c3713 0x00000001092c3761: mov %r13,%r10 0x00000001092c3764: mov %r8,%r13 0x00000001092c3767: mov %r10,%r8 0x00000001092c376a: jmp 0x00000001092c3729 ;*if_icmpge ; - test.TestClient::loop@7 (line 8) 0x00000001092c376c: mov $0x24,%esi 0x00000001092c3771: mov %r13,%rbp 0x00000001092c3774: data32 xchg %ax,%ax 0x00000001092c3777: callq 0x0000000109298f20 ; OopMap{off=188} ;*getstatic out ; - test.TestClient::loop@34 (line 13) ; {runtime_call} 0x00000001092c377c: callq 0x0000000108c1c202 ;*getstatic out ; - test.TestClient::loop@34 (line 13) ; {runtime_call}
Also you should have the hotspot.log file with JIT compiler steps. Here is an excerpt:
<phase name='optimizer' nodes='114' live='77' stamp='0.100'> <phase name='idealLoop' nodes='115' live='67' stamp='0.100'> <loop_tree> <loop idx='119' > <loop idx='185' main_loop='185' > </loop> </loop> </loop_tree> <phase_done name='idealLoop' nodes='197' live='111' stamp='0.101'/> </phase> <phase name='idealLoop' nodes='197' live='111' stamp='0.101'> <loop_tree> <loop idx='202' > <loop idx='159' inner_loop='1' pre_loop='131' > </loop> <loop idx='210' inner_loop='1' main_loop='210' > </loop> <loop idx='138' inner_loop='1' post_loop='131' > </loop> </loop> </loop_tree> <phase_done name='idealLoop' nodes='221' live='113' stamp='0.101'/> </phase> <phase name='idealLoop' nodes='221' live='113' stamp='0.101'> <loop_tree> <loop idx='202' > <loop idx='159' inner_loop='1' pre_loop='131' > </loop> <loop idx='210' inner_loop='1' main_loop='210' > </loop> <loop idx='138' inner_loop='1' post_loop='131' > </loop> </loop> </loop_tree> <phase_done name='idealLoop' nodes='241' live='63' stamp='0.101'/> </phase> <phase name='ccp' nodes='241' live='63' stamp='0.101'> <phase_done name='ccp' nodes='241' live='63' stamp='0.101'/> </phase> <phase name='idealLoop' nodes='241' live='63' stamp='0.101'> <loop_tree> <loop idx='202' inner_loop='1' > </loop> </loop_tree> <phase_done name='idealLoop' nodes='253' live='56' stamp='0.101'/> </phase> <phase name='idealLoop' nodes='253' live='56' stamp='0.101'> <phase_done name='idealLoop' nodes='253' live='33' stamp='0.101'/> </phase> <phase_done name='optimizer' nodes='253' live='33' stamp='0.101'/> </phase>
You can further analyze the hotspot.log file produced by JIT compiler using the JitWatch tool https://github.com/AdoptOpenJDK/jitwatch/wiki
To disable JIT compiler and run the Java virtual machine in all-interpreted mode you can use the -Djava.compiler=NONE JVM option.
A similar question is in this post Why is my JVM doing some runtime loop optimization and making my code buggy?
It is because of compiler/JVM optimization. When you are printing the result, calculation and hence compiler will keep the loop.
On the side, compiler/JVM will remove the loop when you are not using anything from the loop.
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With