26

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();
        }
    }
Community
  • 1
  • 1
Arnab Biswas
  • 4,495
  • 3
  • 42
  • 60
  • 6
    This loop is running 5,000,000,000,000 iterations – Anthony Bonarrigo May 08 '15 at 05:54
  • Most likely to conversion of your value is taking a long time to convert to a `String`. – Evan Knowles May 08 '15 at 05:54
  • Because 50000 * 100000000 = 5,000,000,000 How about remove the loop, do int value = 50000 * 100000000; and read some programming books before posting on SO – Derrops May 08 '15 at 05:54
  • Loop is running 100000000 * 50000 iterations – Rakesh KR May 08 '15 at 05:54
  • 15
    It is because of compiler optimization. When you are printing the result, calculation and hence compile will keep the loop, on the side, compiler will remove the loop when you are not using anything from the loop. – Ambrish May 08 '15 at 05:58
  • 1
    I suspect the compiler does some optimisation when you don't print the value. Since the value is unused the loop doesn't need to be run and it gets dropped from byte code. Let me double check this assumption. – medvedev1088 May 08 '15 at 06:03
  • I have further clarified in the question, loop is not an issue here. Printing the "value" at the end is contributing to the time to execute. – Arnab Biswas May 08 '15 at 06:04
  • Printing the value is triggering the loop execution. So it not just printing the value, it is loop execution time as well. – Ambrish May 08 '15 at 06:15
  • 1
    @Ambrish I don't think it is compiler level optimization, If you will check the bite code generated for both the cases using `javap -c TestClient`, there is no difference in output of both cases. – Not a bug May 08 '15 at 06:18
  • @KisHanSarsecHaGajjar you can give `javap -v TestClient` for more information. only String append part is different – Prashant May 08 '15 at 06:20
  • @Prashant Yes but that has nothing to do with compiler optimization !!! – Not a bug May 08 '15 at 06:58
  • i know its JVM optimization. but that also depend on What specific vendor of JVM you are using – Prashant May 08 '15 at 07:30
  • I have not received any response for the jstack (Update #2) above. Any thoughts? – Arnab Biswas May 08 '15 at 16:42

5 Answers5

22

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?

Community
  • 1
  • 1
medvedev1088
  • 3,645
  • 24
  • 42
  • 1
    You are correct. Thanks for pointing to the link. That in turn points to another link which is helpful : http://stackoverflow.com/questions/9336704/jvm-option-to-optimize-loop-statements – Arnab Biswas May 08 '15 at 08:06
  • 1
    @ArnabBiswas I provided more details in my answer. – medvedev1088 May 08 '15 at 10:39
  • 2
    For those that are curious, the `썐` character in the decompiled for loop is [a Unicode character](http://unicodelookup.com/#%EC%8D%90/1) with a decimal value of 50000. – Tim May 08 '15 at 18:55
12

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.

Ambrish
  • 3,627
  • 2
  • 27
  • 42
  • What about eclipse not able to kill it? – Arnab Biswas May 08 '15 at 06:09
  • @ArnabBiswas, I tried to execute the code on eclipse and it is killing the process (with little delay). Please check it on your end. – Ambrish May 08 '15 at 06:13
  • 2
    Actually the loop is not dropped in the byte code. So it may be the JVM optimisation. – medvedev1088 May 08 '15 at 06:16
  • Bytecode is still same for both ways, only Append part is changed while printing value. but while running same code in both ways using myEclipse its taking huge time. – Prashant May 08 '15 at 06:18
  • -1, I don't think it is compiler level optimization, If you will check the bite code generated for both the cases using `javap -c TestClient`, there is no difference in output of both cases. – Not a bug May 08 '15 at 06:19
  • 1
    The loop will not be removed. We have some operation within loop `value += 1;`. See the bytecode. The loop is still there. – Kartic May 08 '15 at 06:38
  • @Kartic as i think the same because Bytecode is same for loop so some optimization is done by JVM – Prashant May 08 '15 at 06:42
  • 2
    The loop will only be removed if the `value` variable is defined within the method. If the variable is declared outside of the method it will always execute the loop. – Ian2thedv May 08 '15 at 06:50
  • Just an observation: If you put a debug point anywhere in your code and the run your program in debug mode and then press `F8` your program will take time. On the other hand if you simply run it, it will be completed in no time. I guess it has something to do with JIT. I don't know may be JIT is simply ignoring the loop as `value` is never used. – Kartic May 08 '15 at 07:09
  • 2
    Is there any way to verify this / find out what the JVM actually does when it hits the code there? – wonderb0lt May 08 '15 at 08:06
  • @wonderb0lt, I agree with you. Is there any way to confirm our assumptions. – Arnab Biswas May 08 '15 at 08:11
  • 1
    I think the it must be a combination of the compiler and JVM. Try placing the print in the `catch` of a `try`. Based on the statements in your try, the loop is sometimes skipped, and sometimes executed. Think the JVM is smarter than we realize... – Ian2thedv May 08 '15 at 09:05
  • @wonderb0lt Please see my answer. I provided more details from JIT compiler. – medvedev1088 May 08 '15 at 10:45
7

Basically, JVM is really very smart. It can sense if you are using any variable or not, and based on that, it can actually remove any processing related to that. Since you commented out your line of code which prints "value", it senses that this variable is not going to be used anywhere, and will not run the loop, not even once.

But when you do print the value, it has to run your loops, which again is a very large number (50000 * 100000000). Now, running time of this loop depends on your a lot of factors, including but not limited to, your machine's processor, memory given to JVM, processor's load etc.

As far as your question of eclipse not able to terminate it is concerned, I can easily kill the program using eclipse on my machine. Maybe you should check again.

Aakash
  • 2,029
  • 14
  • 22
  • 1
    In fact it's a JVM optimisation. – medvedev1088 May 08 '15 at 06:23
  • I’d rather call optimizing away unused computation “fair”. It would be “smart”, if it optimized away the loop in both cases, as the result value can be calculated without looping (you hinted yourself, how). – Holger May 08 '15 at 12:15
  • @Holger, JVM is ultimately is just a program, which is as smart as it's programmers. In essence, if JVM can omit execution of a loop just by looking ahead that a variable will not be used, isn't it smartness? Obviously, we can use the formula (sum = n * (n + 1)) for the problem of OP, but wouldn't that be smartness of OP to use this formula rather than writing a loop? However, I understand that code optimization is not the problem of OP. He just wants to understand why something happens a specific way. – Aakash May 11 '15 at 07:06
  • The point about unused values is that the optimizer doesn’t need to analyze the loop. It only has to figure out that the *calling code* doesn’t use the return value, hence, the code doesn’t need to be executed regardless of what the loop does or whether the code has a loop at all, as long as it is side-effect free, which is easy to test for Java byte code. In contrast, replaces repeated addition by a multiplication *does* require analyzing the loop… – Holger May 11 '15 at 08:17
3

I suspect that when aou don't print the result the compiler notices that the value of value is never used and thus is able to remove the entire loop as an optimization.

So without the println you are not looping at all and the program just exits at once while when printing the value you are doing all of the 5,000,000,000,000 iterations and this might get a bit lengthy.

As a suggestion try

public class TestClient {
public static long loop() {
    long value =0;

    for (int j = 0; j < 50000; j++) {
        for (int i = 0; i < 100000000; i++) {
            value += 1;
        }
    }
    return value   
 }

public static void main(String[] args) {
    // this might also take rather long
    loop();
    // as well as this
    // System.out.println(loop());
}
}

Here the compiler will not be able to optimize away the loop in loop() since it might be called from various other classes, so it will be executed in all cases.

piet.t
  • 11,718
  • 21
  • 43
  • 52
  • What about eclipse not able to kill it? – Arnab Biswas May 08 '15 at 06:09
  • Thanks. Yes, returning the value is slowing down the program. – Arnab Biswas May 08 '15 at 08:09
  • 1
    I guess, you don’t now what “HotSpot” means. It doesn’t matter whether other code *could* invoke the method if it doesn’t. The HotSpot optimizer is still able to optimize this one specific invocation and that’s what it is all about. – Holger May 08 '15 at 12:00
2

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.

To be truthful , I ran your code in eclipse(windows) and it keeps running even if you comment the system.out.println line. I double checked in debug mode (if you open the Debug perspective you will see all running apps in (by default) the top left. )

But if it runs quickly for you then the most plausible answer is that it is because of java compiler/JVM optimization. We have all learnt java is fast in-spite of being an interpreted(primarily) language because it converts source code to bytecode,uses JIT compiler,Hot spot etc.

Why is not eclipse able to kill the program?

I can kill the program successfully in eclipse(windows). Maybe some issue with the specific eclipse version or linux.(not sure ) . A quick google search gives multiple scenarios when eclipse fails to terminate a program.

Raj
  • 1,945
  • 20
  • 40