Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Why is this program which loops many times taking time when there is a `println` after the loops?

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 :

  1. 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.

  2. 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();         }     } 
like image 687
Arnab Biswas Avatar asked May 08 '15 05:05

Arnab Biswas


People also ask

Why is my while loop running infinitely?

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.

How many times does a Do While loop execute Java?

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.

Can we use system out Println in for loop?

@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.

How do you repeat a whole program in Java?

The main() method just controls the repeating of your program.


2 Answers

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

JitWatch TriView for TestClient

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?

like image 53
medvedev1088 Avatar answered Oct 17 '22 00:10

medvedev1088


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.

like image 42
Ambrish Avatar answered Oct 17 '22 00:10

Ambrish