当前位置: 首页 > 知识库问答 >
问题:

应用程序速度慢,JVM频繁挂起,单CPU设置和Java 12

有玄天
2023-03-14

我们有一个客户端应用程序(经过10年的开发)。其JDK最近从OpenJDK 11升级到了OpenJDK 14。在单CPU(禁用超线程)Windows 10设置中(以及在只有一个可用CPU的VirtualBox机器内),与Java 11相比,应用程序启动速度非常慢。此外,它大部分时间使用100%的CPU。我们还可以通过将处理器相关性设置为仅一个CPU来重现这个问题(c:\windows\system32\cmd.exe/c start/affinity 1…)。

在我的VirtualBox机器中启动应用程序并以最少的手动交互进行查询的一些测量:

  • OpenJDK 11.0.2:36秒
  • OpenJDK 13.0.2:~1.5分钟
  • OpenJDK 13.0.2 with-XX:-UseBiasedLocking: 46秒
  • OpenJDK 13.0.2 with-XX:-ThreadLocalHandshakes: 40秒
  • OpenJDK 14:5-6分钟
  • OpenJDK 14 with-XX:-UseBiasedLocking: 3-3,5分钟
  • OpenJDK 15 EA Build 20:~4,5分钟

只更改了使用的JDK(和提到的选项)。(-XX:-ThreadLocalHandshakes在Java 14中不可用。)

我们已经尝试记录了JDK 14使用Xlog:all=debug:file=app所做的事情。txt:正常运行时间、tid、级别、标记:filecount=50。

在OpenJDK 11.0.2中,每秒计算日志行似乎相当顺利:

$ cat jdk11-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
  30710 0
  44012 1
  55461 2
  55974 3
  27182 4
  41292 5
  43796 6
  51889 7
  54170 8
  58850 9
  51422 10
  44378 11
  41405 12
  53589 13
  41696 14
  29526 15
   2350 16
  50228 17
  62623 18
  42684 19
  45045 20

另一方面,OpenJDK 14似乎有着有趣的平静时期:

$ cat jdk14-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
   7726 0
   1715 5
  10744 6
   4341 11
  42792 12
  45979 13
  38783 14
  17253 21
  34747 22
   1025 28
   2079 33
   2398 39
   3016 44

那么,在1-4秒、7-10秒和14-20秒之间发生了什么?

...
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerFactory$1 java.lang.Thread CleanerFactory.java:45
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerImpl java.lang.Thread CleanerImpl.java:117
[0.350s][7248][info ][biasedlocking        ] Aligned thread 0x000000001727e010 to 0x000000001727e800
[0.350s][7248][info ][os,thread            ] Thread started (tid: 2944, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.350s][6884][info ][os,thread            ] Thread is alive (tid: 6884).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack dimensions: 0x00000000175b0000-0x00000000176b0000 (1024k).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack guard pages activated: 0x00000000175b0000-0x00000000175b4000.
[0.350s][7248][debug][thread,smr           ] tid=7248: Threads::add: new ThreadsList=0x0000000017254500
[0.350s][7248][debug][thread,smr           ] tid=7248: ThreadsSMRSupport::free_list: threads=0x0000000017253d50 is freed.
[0.350s][2944][info ][os,thread            ] Thread is alive (tid: 2944).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack dimensions: 0x00000000177b0000-0x00000000178b0000 (1024k).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack guard pages activated: 0x00000000177b0000-0x00000000177b4000.
[0.351s][2944][debug][class,resolve        ] java.lang.Thread java.lang.Runnable Thread.java:832
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.misc.InnocuousThread CleanerImpl.java:135
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.ref.PhantomCleanable CleanerImpl.java:138
[0.351s][2944][info ][biasedlocking,handshake] JavaThread 0x000000001727e800 handshaking JavaThread 0x000000000286d800 to revoke object 0x00000000c0087f78
[0.351s][2944][debug][vmthread               ] Adding VM operation: HandshakeOneThread
[0.351s][6708][debug][vmthread               ] Evaluating non-safepoint VM operation: HandshakeOneThread
[0.351s][6708][debug][vmoperation            ] begin VM_Operation (0x00000000178af250): HandshakeOneThread, mode: no safepoint, requested by thread 0x000000001727e800

# no log until 5.723s

[5.723s][7248][info ][biasedlocking          ]   Revoked bias of currently-unlocked object
[5.723s][7248][debug][handshake,task         ] Operation: RevokeOneBias for thread 0x000000000286d800, is_vm_thread: false, completed in 94800 ns
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.lang.ref.Cleaner ZipFile.java:715
[5.723s][7248][debug][class,resolve          ] java.lang.ref.Cleaner jdk.internal.ref.CleanerImpl$PhantomCleanableRef Cleaner.java:220
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.util.WeakHashMap ZipFile.java:716
...

第二次暂停稍晚一点:

...
[6.246s][7248][info ][class,load              ] java.awt.Graphics source: jrt:/java.desktop
[6.246s][7248][debug][class,load              ]  klass: 0x0000000100081a00 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 5625 checksum: 0025818f
[6.246s][7248][debug][class,resolve           ] java.awt.Graphics java.lang.Object (super)
[6.246s][7248][info ][class,loader,constraints] updating constraint for name java/awt/Graphics, loader 'bootstrap', by setting class object
[6.246s][7248][debug][jit,compilation         ]   19       4       java.lang.Object::<init> (1 bytes)   made not entrant
[6.246s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1400 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 700 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 800 ns

# no log until 11.783s

[11.783s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 6300 ns
[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[11.783s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[11.783s][7248][debug][protectiondomain        ] Checking package access
[11.783s][7248][debug][protectiondomain        ] class loader: a 'jdk/internal/loader/ClassLoaders$AppClassLoader'{0x00000000c0058628} protection domain: a 'java/security/ProtectionDomain'{0x00000000c058b948} loading: 'java/awt/Graphics'
[11.783s][7248][debug][protectiondomain        ] granted
[11.783s][7248][debug][class,resolve           ] sun.launcher.LauncherHelper java.awt.Graphics LauncherHelper.java:816 (reflection)
[11.783s][7248][debug][class,resolve           ] jdk.internal.reflect.Reflection [Ljava.lang.reflect.Method; Reflection.java:300
[11.783s][7248][debug][class,preorder          ] java.lang.PublicMethods$MethodList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
...

然后是第三个:

...
[14.578s][7248][debug][class,preorder          ] java.lang.InheritableThreadLocal source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[14.578s][7248][info ][class,load              ] java.lang.InheritableThreadLocal source: jrt:/java.base
[14.578s][7248][debug][class,load              ]  klass: 0x0000000100124740 super: 0x0000000100021a18 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 1338 checksum: 8013ed55
[14.578s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal (super)
[14.578s][7248][debug][jit,compilation         ]  699       3       java.lang.ThreadLocal::get (38 bytes)   made not entrant
[14.578s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1600 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 900 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 0 ns
[14.579s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 900 ns

# no log until 21.455s

[21.455s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 12100 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns
[21.455s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[21.455s][7248][debug][class,resolve           ] sun.security.jca.Providers java.lang.InheritableThreadLocal Providers.java:39
[21.455s][7248][info ][class,init              ] 1251 Initializing 'java/lang/InheritableThreadLocal'(no method) (0x0000000100124740)
[21.455s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal InheritableThreadLocal.java:57
[21.456s][7248][debug][class,preorder          ] sun.security.jca.ProviderList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[21.456s][7248][info ][class,load              ] sun.security.jca.ProviderList source: jrt:/java.base
[21.456s][7248][debug][class,load              ]  klass: 0x00000001001249a8 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 11522 checksum: bdc239d2
[21.456s][7248][debug][class,resolve           ] sun.security.jca.ProviderList java.lang.Object (super)
...

以下两行似乎很有趣:

[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns

握手用了5.5秒和6.8秒,这正常吗?

我在使用这个命令运行update4j演示应用程序(与我们的应用程序完全无关)时也经历了同样的减速(和类似的日志):

Z:\swing>\jdk-14\bin\java -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50 \
    -jar update4j-1.4.5.jar --remote http://docs.update4j.org/demo/setup.xml

在单CPU Windows 10设置上,我应该寻找什么使我们的应用程序再次更快?我可以通过更改应用程序中的某些内容或添加JVM参数来解决这个问题吗?

这是一个JDK错误,我应该报告吗?

更新2020-04-25:

据我所见,日志文件还包含GC日志。以下是第一个GC日志:

$ cat app.txt.00 | grep "\[gc"
[0.016s][7248][debug][gc,heap          ] Minimum heap 8388608  Initial heap 60817408  Maximum heap 1073741824
[0.017s][7248][info ][gc,heap,coops    ] Heap address: 0x00000000c0000000, size: 1024 MB, Compressed Oops mode: 32-bit
[0.018s][7248][info ][gc               ] Using Serial
[22.863s][6708][info ][gc,start                ] GC(0) Pause Young (Allocation Failure)
[22.863s][6708][debug][gc,heap                 ] GC(0) Heap before GC invocations=0 (full 0): def new generation   total 17856K, used 15936K [0x00000000c0000000, 0x00000000c1350000, 0x00000000d5550000)
...

不幸的是,它似乎并不相关,因为它在第三次暂停后开始。

更新2020-04-26:

使用OpenJDK 14,应用程序在我的(单CPU)VirtualBox机器(在i7-6600U CPU上运行)中使用100%的CPU。虚拟机具有3.5GB RAM。根据任务管理器,40%是空闲的,磁盘活动是0%(我想这意味着没有交换)。向虚拟机添加另一个CPU(并为物理机启用超线程)使应用程序再次足够快。我只是想知道,在JDK开发过程中,为了使JVM在多核/超线程CPU上运行得更快,在(罕见的)单CPU机器上损失性能是否是有意的权衡?


共有3个答案

漆雕成弘
2023-03-14

因为它“大部分时间”都在使用100%的CPU,而且需要10倍的时间(!)对于Java 14,这意味着在Java 14中浪费了90%的CPU。

用完堆空间可以做到这一点,因为您在GC中花费了大量时间,但您似乎已经排除了这种可能性。

我注意到您正在调整有偏锁定选项,这会产生显著的差异。这告诉我,您的程序可能在多个线程中执行大量并发工作。您的程序可能存在Java 14中出现的并发错误,但Java 10中没有。这也可以解释为什么添加另一个CPU会使速度提高一倍以上。

并发错误通常只在你运气不好的时候才会出现,触发因素可能真的是任何事情,比如更改hashmap组织等等。

首先,如果可行的话,检查是否有任何循环可能正忙于等待而不是睡眠。

然后,在采样模式下运行分析器(jVisual alvm就可以了),并寻找占用总时间比它们应该占用的时间大得多的方法。由于您的性能下降了10倍,因此其中的任何问题都应该真正跳出来。

唐法
2023-03-14

根据我的经验,JDK的性能问题主要与以下之一有关:

  • JIT编译
  • VM配置(堆大小)
  • GC算法
  • JVM/JDK中的变化打破了已知良好运行的应用程序
  • (哦,我忘了提到类加载…)

如果您只使用自OpenJDK11以来的默认JVM配置,也许您应该将一些更突出的选项设置为固定值,例如GC、Heap size等。

也许一些图形分析工具可以帮助跟踪您的问题。如Retrace、AppDynamics或FlightRecorder等。与日志文件相比,它们提供了在给定时间内堆、GC周期、RAM、线程、CPU负载等的总体状态的更多概述。

我是否正确理解您的应用程序在运行的第一秒钟内(在OpenJDK11下)将30710行写入日志?为什么它在第一秒内“只”在OpenJDK14下写大约7k行?对我来说,对于一个刚刚在不同JVM上启动的应用程序来说,这似乎是一个巨大的差异。。。例如,您确定没有大量异常堆栈跟踪转储到日志中吗?

其他数字有时甚至更高,所以可能是与异常日志记录有关?如果RAM变低,甚至交换?

事实上,我在想,如果一个应用程序没有在日志中写入任何内容,这是一个没有问题的平稳运行的标志(除非它在这段时间完全冻结)。从第12-22秒(在这里的OpenJDK14案例中)发生的事情是我更关心的...日志行穿过屋顶...为什么?

然后日志记录下降到大约12k行的所有时间低值...这是什么原因??(嗯,也许是GC在第22秒开始,并做了一个解决一些问题的白板...?)

另一件事可能是你关于“单CPU”机器的声明。这是否也意味着“单核”(Idk,也许你的软件是根据传统硬件或其他东西定制的)?

“单CPU”虚拟机在这些机器上运行?但我认为,我对这些假设是错误的,因为现在几乎所有的CPU都是多核的。。。但我可能会研究多线程问题(死锁)。

卫胜
2023-03-14
匿名用户

太长别读:这是一个OpenJDK回归归档为JDK-8244340,并已在JDK 15 Build24 (2020/5/20)中修复。

除此之外,我没有这样做,但我可以用一个简单的问候世界来重现这个问题:

public class Main {
    public static void main(String[] args) {
        System.out.println("Hello world");
    }
}

我使用了这两个批处理文件:

main-1cpu。bat,它将java进程限制为仅一个CPU:

c:\windows\system32\cmd.exe /C start /affinity 1 \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-1cpu.txt:uptime,tid,level,tags:filecount=50 \
    Main

main-full.batjava进程可以使用两个CPU:

c:\windows\system32\cmd.exe /C start /affinity FF \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-full.txt:uptime,tid,level,tags:filecount=50 \
    Main

(不同之处在于日志文件的值和名称。我将其包装以便于阅读,但在Windows上用包装可能不起作用。)

在VirtualBox中的Windows 10 x64上进行了一些测量(带有两个CPU):

PS Z:\main> Measure-Command { .\main-1cpu.bat }

...    
TotalSeconds      : 7.0203455
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5751352
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5585384
...


PS Z:\main> Measure-Command { .\main-1cpu.bat }

...
TotalSeconds      : 23.6482685
...

生成的跟踪记录包含您可以在问题中看到的类似停顿。

在没有tracelogs的情况下运行Main更快,但单CPU和双CPU版本之间仍然存在差异:约4-7秒,而约400毫秒。

我已将这些发现发送到热点-dev@openjdk邮件列表和开发人员确认,这是JDK可以更好地处理的事情。你也可以在线程中找到假设的修复。关于热点运行时回归的另一个线程-dev@.JIRA问题修复:JDK-8244340

 类似资料:
  • 我正在尝试测试Aparapi的性能。我看到过一些博客,其中的结果显示,Aparapi确实在做数据并行操作的同时提高了性能。 但我在测试中没有看到这一点。这里是我所做的,我写了两个程序,一个使用Aparapi,另一个使用普通循环。 方案1:在Aparapi 程序2:使用循环 程序1需要大约330ms,而程序2只需要大约55ms。我是不是做错什么了?我在Aparpai程序中打印出了执行模式,它打印出的

  • 我正在做一个大学作业,我必须午餐3个服务器处理客户和一个服务器组的领导,这里是场景: 领导者开始。 leader 运行 3 台服务器(必须使用 Runtime.getRuntime().exec() 将它们作为 jar 文件运行); 向服务器发送激活消息以开始为客户端提供服务 客户端开始与服务器通信。 问题是在客户端发出3或4个请求后,服务器挂起,只有当领导者终止时才完成其工作。如果我从cmd手动

  • 我有一个多项目(2个模块),它的建设需要大约1/2分钟每次。当我在Android Studio按下Run的时候,我每次都要等待才能重建app,慢得不得了。每次都用了6/8分钟。 在Android Studio中有没有可能实现构建过程的自动化?或者对于如何让这个过程更快,你有什么建议吗? 这是我的build.gradle文件(应用程序模块):

  • 我们已经使用jmap在Java 6下运行的大型多服务器应用程序上测量堆大小大约2年了。我们每分钟测量一次。每次测量所用的时间(经过的时间)不到1秒。 我们现在正在Java 7下测试同一个应用程序。现在突然之间,jmap通常需要10秒、20秒,有时甚至更长时间,而且它似乎慢了下来(甚至可能停止!)在那段时间里,JVM。 我们在jmap输出中看到的唯一区别(Java6和Java7之间)是关于有多少字符

  • 问题内容: 每次我运行Selenium IDE时,速度控制都设置为“快速”,是否可以将速度控制默认设置为“慢”? 问题答案: 将此命令放在脚本的开头: 命令:setSpeed 目标:3000 IDE具有较慢的速度和较快的速度。但是,这更为精确,因此您可以控制每个命令的延迟(以毫秒为单位)。此示例使每个命令等待3秒。

  • 我将SpringBoot2.6.2与docker等一起使用-我的应用程序通过如下所示: foo.bar肯定如预期的那样工作。但是我不确定这样说是否正确... …也在那里。这行吗? 加-我使用从Spring来管理和更改中的一些变量,这就像一个魅力。但是出于某种原因,它在那里放了一些反斜杠,导致: …这仍然正确吗?它有用吗? 感谢您的帮助或建议:-)