为什么这个循环次数很多的程序，在循环后有一个 `println` 时需要花费时间？

Question

这是我正在尝试的小代码。程序执行需要很长时间。如果在运行时我尝试通过eclipse中的终止按钮将其杀死，则会返回 Terminate Failed 。我可以使用 kill -9 <PID>从终端杀死它。

但是，当我不打印程序最后一行中的变量结果时（请检查代码的注释部分），程序立即退出。

我想知道：

1. 为什么打印 value 时执行需要时间？
   请注意，如果我不打印 value ，相同的循环会立即结束。

2. 为什么eclipse无法杀死程序？

更新1： 似乎JVM在运行时（而非编译时）优化代码。 本线程 有帮助。

更新2： 当我打印 value 的值时， jstack <PID> 无法工作。任何可能的原因？

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

- Arnab Biswas

---

这个循环正在运行五万亿次迭代。 - Anthony Bonarrigo

这是由于编译器的优化。当你打印结果时，编译器会保留循环计算，同时在没有使用循环中任何内容时，编译器会移除循环。 - Ambrish

我怀疑编译器在不打印值时会进行一些优化。由于该值未被使用，因此循环不需要运行，并且它会从字节码中删除。让我再次确认这个假设。 - medvedev1088

@Ambrish 我认为这不是编译器级别的优化。如果您使用 javap -c TestClient 检查两种情况生成的字节码，输出结果没有任何区别。 - Not a bug

@Prashant 是的，但这与编译器优化无关！！！ - Not a bug

Answer 1

这是一种JIT编译器优化（不是Java编译器优化）。

如果您比较使用Java编译器生成的两个版本的字节码，您将看到循环在两个版本中都存在。

以下是带有println的反编译方法的方式：

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

去除println后，反编译方法的样子如下：

private static void loop() {
    long value = 0L;

    for(int j = 0; j < '썐'; ++j) {
        for(int i = 0; i < 100000000; ++i) {
            ++value;
        }
    }
}

正如您所见，循环仍然存在。

但是，您可以使用以下JVM选项启用JIT编译器日志记录和汇编打印：

-XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation -XX:+PrintAssembly

您可能还需要下载hsdis-amd64.dylib并将其放在您的工作目录中（MacOS，HotSpot Java 8）

运行TestClient后，您应该在控制台中看到JIT编译器生成的代码。这里我只会发布部分输出内容。

没有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

使用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}

还应该有包含JIT编译步骤的hotspot.log文件。这里是一个摘录：

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

您可以使用JitWatch工具进一步分析JIT编译器生成的hotspot.log文件。 https://github.com/AdoptOpenJDK/jitwatch/wiki 要禁用JIT编译器并以全解释模式运行Java虚拟机，您可以使用-Djava.compiler = NONE JVM选项。

类似的问题在这篇文章中Why is my JVM doing some runtime loop optimization and making my code buggy?。

- medvedev1088

---

你说得对。感谢指出链接。这又指向了另一个有用的链接：https://dev59.com/SWDVa4cB1Zd3GeqPepJ4 - Arnab Biswas

@ArnabBiswas 我在我的回答中提供了更多细节。 - medvedev1088

对于那些好奇的人，反编译的循环中的썐字符是一个Unicode字符，其十进制值为50000。 - Tim

Answer 2

这是因为编译器/JVM进行了优化。当您打印结果时，计算和循环将被编译器保留。

另一方面，当您没有使用循环中的任何内容时，编译器/JVM将会移除该循环。

- Ambrish

---

实际上，循环在字节码中并没有被丢弃。因此这可能是JVM进行了优化。 - medvedev1088

循环不会被移除。我们在循环内有一些操作 value += 1;。请查看字节码。循环仍然存在。 - Kartic

只有在value变量在方法内被定义时，循环才会被移除。如果变量在方法外声明，则始终执行循环。 - Ian2thedv

有没有办法验证这个问题或者找出JVM在执行代码时实际做了什么？ - wonderb0lt

我认为这必须是编译器和JVM的组合。尝试将打印放置在try的catch中。根据您的尝试语句，循环有时会被跳过，有时会被执行。我认为JVM比我们意识到的要聪明... - Ian2thedv

Answer 3

基本上，JVM非常聪明。它可以感知您是否在使用任何变量，并基于此实际删除与其相关的任何处理。由于您注释掉了打印“value”的代码行，因此它会感知到该变量不会在任何地方使用，并且不会运行循环，甚至没有一次。

但是当您打印值时，它必须运行您的循环，这又是一个非常大的数字（50000 * 100000000）。现在，此循环的运行时间取决于许多因素，包括但不限于您机器的处理器、JVM分配的内存、处理器的负载等。

至于您关于eclipse无法终止它的问题，我可以轻松地在我的机器上使用eclipse杀死程序。也许您应该再检查一下。

- Aakash

---

实际上这是JVM的优化。 - medvedev1088

我更倾向于将优化未使用的计算称为“公平”。如果在两种情况下都优化掉循环，因为结果值可以在不循环的情况下计算出来（你自己暗示了如何），那就是“智能”的。 - Holger

@Holger，JVM 最终只是一个程序，它的智能程度取决于它的程序员。从本质上讲，如果 JVM 可以通过向前查看变量不会被使用来省略执行循环，那么这不是聪明吗？显然，我们可以使用公式（sum = n *（n + 1））来解决 OP 的问题，但使用这个公式而不是编写循环难道不是 OP 的聪明之举吗？然而，我理解代码优化并不是 OP 的问题。他只是想了解为什么某些事情会以特定的方式发生。 - Aakash

您IP地址为143.198.54.68，由于运营成本限制，当前对于免费用户的使用频率限制为每个IP每72小时10次对话，如需解除限制，请点击左下角设置图标按钮（手机用户先点击左上角菜单按钮）。 - Holger

Answer 4

我猜测，当您不打印结果时，编译器会注意到value的值从未被使用，因此可以将整个循环作为优化删除。所以没有println，您根本没有循环，程序立即退出，而在打印值时，您正在执行所有的5,000,000,000,000次迭代，这可能会有点冗长。作为建议，请尝试：

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

在这种情况下，编译器将无法优化loop（）中的循环，因为它可能会被各种其他类调用，因此它将在所有情况下执行。

- piet.t

---

Eclipse无法终止它怎么办？ - Arnab Biswas

谢谢。是的，返回值会减慢程序的运行速度。 - Arnab Biswas

我猜你不知道“HotSpot”是什么意思。如果其他代码没有调用该方法，那么它是否可以调用并不重要。 HotSpot优化器仍然能够优化这个特定的调用，这就是关键所在。 - Holger

Answer 5

为什么打印result的值时需要时间来执行？请注意，如果我不打印值，则相同的循环会立即结束。

实话实说，我在eclipse（windows）中运行了您的代码，即使您注释了system.out.println行，它仍然在运行。我在调试模式下进行了双重检查（如果您打开调试透视图，您将在（默认情况下）左上角看到所有正在运行的应用程序。）

但是如果它对您来说运行得很快，那么最有可能的答案是由于Java编译器/JVM优化。我们都学过Java是快速的，尽管它是一种解释性（主要）语言，因为它将源代码转换为字节码，使用JIT编译器，热点等。

为什么eclipse无法终止程序？

我可以在eclipse（windows）中成功终止程序。也许是特定eclipse版本或linux存在问题。（不确定）通过快速的谷歌搜索，可以找到多种情况，其中eclipse无法终止程序。

- Raj