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

Question

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();
        }
    }

Ranchman

This loop is running 5,000,000,000,000 iterations – Pry

Most likely to conversion of your value is taking a long time to convert to a String. – Underdeveloped

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 – German

Loop is running 100000000 * 50000 iterations – Cataplasm

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. – Chitterlings

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. – Augie

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. – Ranchman

Printing the value is triggering the loop execution. So it not just printing the value, it is loop execution time as well. – Chitterlings

@Chitterlings 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. – Huntingdonshire

@KisHanSarsecHaGajjar you can give javap -v TestClient for more information. only String append part is different – Stonedeaf

@Stonedeaf Yes but that has nothing to do with compiler optimization !!! – Huntingdonshire

i know its JVM optimization. but that also depend on What specific vendor of JVM you are using – Stonedeaf

I have not received any response for the jstack (Update #2) above. Any thoughts? – Ranchman

Answer 1

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?

Augie

You are correct. Thanks for pointing to the link. That in turn points to another link which is helpful : #9337204 – Ranchman

@ArnabBiswas I provided more details in my answer. – Augie

For those that are curious, the 썐 character in the decompiled for loop is a Unicode character with a decimal value of 50000. – Solo

Answer 2

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.

Chitterlings

What about eclipse not able to kill it? – Ranchman

@ArnabBiswas, I tried to execute the code on eclipse and it is killing the process (with little delay). Please check it on your end. – Chitterlings

Actually the loop is not dropped in the byte code. So it may be the JVM optimisation. – Augie

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. – Stonedeaf

-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. – Huntingdonshire

The loop will not be removed. We have some operation within loop value += 1;. See the bytecode. The loop is still there. – Foolscap

@Foolscap as i think the same because Bytecode is same for loop so some optimization is done by JVM – Stonedeaf

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. – Chiffon

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. – Foolscap

Is there any way to verify this / find out what the JVM actually does when it hits the code there? – Estivation

@wonderb0lt, I agree with you. Is there any way to confirm our assumptions. – Ranchman

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... – Chiffon

@Estivation Please see my answer. I provided more details from JIT compiler. – Augie

Answer 3

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.

Sycosis

In fact it's a JVM optimisation. – Augie

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). – Gensler

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

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… – Gensler

Answer 4

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.

Lussier

What about eclipse not able to kill it? – Ranchman

Thanks. Yes, returning the value is slowing down the program. – Ranchman

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. – Gensler

Answer 5

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.

Athene