应用程序缓慢,JVM 频繁挂起,单 CPU 设置和 Java 12+
Posted
技术标签:
【中文标题】应用程序缓慢,JVM 频繁挂起,单 CPU 设置和 Java 12+【英文标题】:Slow application, frequent JVM hangs with single-CPU setups and Java 12+ 【发布时间】:2020-04-22 21:39:39 【问题描述】:我们有一个客户端应用程序(经过 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 与-XX:-UseBiasedLocking
:46 秒
OpenJDK 13.0.2 与 -XX:-ThreadLocalHandshakes
:40 秒
OpenJDK 14:5-6 分钟
OpenJDK 14 与 -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:uptime,tid,level,tags: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 demo app(与我们的应用程序完全无关)时,我遇到了同样的减速(和类似的日志):
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 年 4 月 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.5 GB RAM。根据任务管理器 40%+ 是免费的,磁盘活动是 0%(我想这意味着没有交换)。向虚拟机添加另一个 CPU(并为物理机启用超线程)使应用程序再次变得足够快。我只是想知道,在 JDK 开发过程中,为了让 JVM 在多核/超线程 CPU 上更快地降低(稀有)单 CPU 机器上的性能,这是一种有意的权衡吗?
【问题讨论】:
-Xlog:all=debug
是否开启 GC 日志记录?这是我对任何停顿的第一个猜测。
您是否尝试使用分析器运行并比较结果?我认为这是很自然的事情。
还检查 Windows 系统消息,尝试为 jdk 14 构建不同的版本。如果所有其他方法都失败,请升级为问题?
@Yan.F:OpenJDK 11 不会永远支持,是时候准备新版本和错误了。此外,这似乎是一个 JDK 错误 - 它可能已修复或未修复,但也可以帮助其他人。无论如何,对我来说,这主要是好奇心。另一方面,我现在想告诉我们的客户什么是我们应用程序的最低系统要求。
@Khanna111:是的,我刚刚写了它作为答案。
【参考方案1】:
TL;DR:这是一个 OpenJDK regression filed as JDK-8244340,已在 JDK 15 Build 24 (2020/5/20) 中修复。
我没有,但我可以用一个简单的 hello world 重现这个问题:
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.bat
,java
进程可以同时使用两个 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
(区别在于日志文件的 affinity
值和名称。我已将其包裹起来以便于阅读,但使用 \
包裹可能不适用于 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
...
生成的跟踪日志包含您可以在问题中看到的类似暂停。
在没有跟踪日志的情况下运行 Main
更快,但仍然可以看到单 CPU 和双 CPU 版本之间的差异:~4-7 秒 vs. ~400 毫秒。
我已经发送了this findings to the hotspot-dev@openjdk mail list,那里的开发人员确认了this is something that the JDK could handle better。您也可以在帖子中找到supposed fixes。 Another thread about the regression on hotspot-runtime-dev@。修复的 JIRA 问题:JDK-8244340
【讨论】:
【参考方案2】:根据我的经验,JDK 的性能问题主要与以下情况之一有关:
JIT 编译 VM 配置(堆大小) GC 算法 JVM/JDK 中的更改会破坏已知运行良好的应用程序 (哦,我忘了提到类加载...)如果你只是使用自 OpenJDK11 以来的默认 JVM 配置,也许你应该将一些更突出的选项设置为固定值,如 GC、堆大小等。
也许一些图形分析工具可以帮助追踪您的问题。像 Retrace、AppDynamics 或 FlightRecorder 等。与日志文件相比,这些提供了在给定时间堆、GC 周期、RAM、线程、CPU 负载等的整体状态的更多概述。
我是否正确理解您的应用程序在运行的第一秒内(在 OpenJDK11 下)将大约 30710 行写入日志?为什么在 OpenJDK14 下第一秒“只”写了大约 7k 行?对于刚刚在不同 JVM 上启动的应用程序而言,这似乎是一个巨大的差异……您确定没有例如大量的异常堆栈跟踪转储到日志中吗?
有时其他数字甚至更高,所以减速可能与异常日志记录有关?甚至交换,如果 RAM 变低?
其实我在想,如果一个应用程序没有在日志中写入任何内容,这表明它运行顺利,没有问题(除非它在这段时间内完全冻结)。从 12 秒到 22 秒(这里的 OpenJDK14 案例)发生的事情让我更关心...记录的行穿过屋顶...为什么?
然后日志记录下降到大约 1-2k 行的所有时间低值...... 那个的原因是什么? (好吧,也许是 GC 在 22 秒开始执行并解决了一些问题……?)
另一件事可能是您对“单 CPU”机器的陈述。这是否也意味着“单核”(Idk,也许您的软件是在旧硬件或其他东西上定制的)?
那些机器上运行的是“单 CPU”虚拟机? 但我认为,我对这些假设是错误的,因为现在几乎所有 CPU 都是多核的......但我可能会调查多线程问题(死锁)问题。
【讨论】:
请不要在您的帖子中使用签名或标语,重复的“GL 和 HF”被认为是噪音,会分散您在此处帖子内容的注意力。请参阅meta.stackexchange.com/help/behavior 了解更多信息。 “我是否正确理解您的应用程序在运行的第一秒内(在 OpenJDK11 下)将大约 30710 行写入日志?” - 是的,你是对的。 “您确定没有大量异常堆栈跟踪转储到日志中吗?” - 日志很干净,我没有发现任何奇怪的地方,应用程序工作正常(除了它运行得非常非常慢)。 GC 在第 22 秒启动,之后应用程序仍然很慢。我也更新了这个问题。请注意,update4j 演示应用也有同样的问题。谢谢你的回答! 一秒钟内超过 30k+ 的日志行是相当巨大的......你不同意吗?我真的很想知道在这么短的时间内记录这么多的日志行有什么用处……您是否尝试过完全关闭日志记录并以这种模式分析应用程序? (我很好奇,但也许日志记录真的没有你暗示的 update4j 行为的影响)【参考方案3】:由于它“大部分时间”都在使用 100% 的 CPU,并且使用 Java 14 所需的时间要长 10 倍(!),这意味着您在 Java 14 中浪费了 90% 的 CPU。
堆空间用完可以这样做,因为您在 GC 上花费了大量时间,但您似乎已经排除了这一点。
我注意到您正在调整偏向锁定选项,这会产生重大影响。这告诉我,也许你的程序在多个线程中做了很多并发工作。您的程序可能存在并发错误,该错误出现在 Java 14 中,但未出现在 Java 10 中。这也可以解释为什么添加另一个 CPU 会使其速度提高一倍以上。
并发错误通常只在您运气不好时才会出现,而触发因素实际上可能是任何事情,例如更改 hashmap 组织等。
首先,如果可行,请检查是否有任何循环可能是忙于等待而不是休眠。
然后,在采样模式下运行分析器(jvisualvm 会这样做)并查找占用总时间百分比远大于应有时间的方法。由于您的表现下降了 10 倍,因此其中的任何问题都应该真正跳出来。
【讨论】:
Biased Locking 过去是必要的,但现在没有那么多了,建议默认禁用,稍后删除:openjdk.java.net/jeps/374【参考方案4】:这是一个有趣的问题,它需要不确定的努力来缩小范围,因为需要尝试许多排列和组合以及收集和整理数据。
似乎已经有一段时间没有解决这个问题了。也许这可能需要升级。
编辑 2:由于“ThreadLocalHandshakes”已被弃用,我们可以假设锁定是争用的,建议尝试不使用“UseBiasedLocking”以希望加快这种情况。
但是有一些建议可以收集更多数据并尝试隔离问题。
-
分配多个核心 [我看到你已经尝试过了,问题就消失了。似乎是线程执行排除其他线程的问题。见下文第 7 条)
分配更多的堆(也许v14的需求比早期的jdks更多)
为 Win 10 VB 分配更多内存。
检查操作系统系统消息(在您的情况下为 Win 10)
在非虚拟化 Win 10 中运行。
尝试不同版本的 jdk 14
每隔(或配置文件)几个时间间隔执行一次线程转储。分析什么线程在独占运行。也许有一个公平分时的环境。也许有更高优先级的线程正在运行。那个线程是什么,它在做什么?在 linux 中,您可以实时统计与进程关联的轻量级进程(线程)及其状态。 Win 10 上有类似的东西吗?
CPU 使用率? 100% 或更少?受 CPU 或内存限制?服务线程中的 100% CPU?哪个服务线程?
您是否明确设置了 GC 算法?
我亲眼目睹了与 GC、堆大小调整、虚拟化容器问题等有关的版本中的问题。
我认为,对此没有简单的答案,尤其是因为这个问题已经存在了一段时间。但我们可以尽力而为,让我们知道其中一些隔离步骤的结果。
编辑 1:从更新的问题来看,它似乎与 GC 或另一个服务线程不公平地接管单核(线程本地握手)有关?
【讨论】:
添加一个额外的 CPU 内核,用于触发从客户端从 32 位系统上的 Java 人体工程学切换到具有不同 GC 和分层编译的服务器类 vm,如果仍然如此,它可能会解释突然的差异在性能和内存使用方面,是的,JVM 性能很复杂? Java 人体工程学(默认设置)对于 1 个 CPU(例如:-XX:+UseSerialGC)或 2 个 CPU(例如:G1GC、LoopStripMiningIter=1000、...ShortLoop=100)仍然不同在使用 -XX:+PrintFlagsFinal 确保我将所有参数调整为相同或类似的运行 update4j 之后,使用 cmd.exe /C start /affinity 0x1 仅使用一个而不是 2 个 CPU 启动仍然非常慢(但使用 0x3 非常快- 因此使用 2 cpu(1 + 10 二进制))。我确认我们不能通过使用旨在避免任何 GC 开销的 Epsilon GC 来责备任何垃圾收集器。然而,分层编译已启用 我明白了。使用 Epsilon GC,它似乎也很慢。在这种情况下,线程状态和转储来评估卡在哪里可能是一种方法。在 Java 世界和操作系统世界(如果我记得是 gcore 的话,linux)【参考方案5】:小心记录到慢速磁盘,它会减慢您的应用程序:
https://engineering.linkedin.com/blog/2016/02/eliminating-large-jvm-gc-pauses-caused-by-background-io-traffic
但这似乎不是问题的原因,因为 CPU 仍然很忙,而且由于线程本地握手,您不必等待所有线程都到达安全点:https://openjdk.java.net/jeps/312
也与您遇到的问题没有直接关系,但更一般地说,如果您想在启动时间尝试从硬件中挤出更多性能,请查看 AppCDS(类数据共享):
https://blog.codefx.org/java/application-class-data-sharing/
【讨论】:
以上是关于应用程序缓慢,JVM 频繁挂起,单 CPU 设置和 Java 12+的主要内容,如果未能解决你的问题,请参考以下文章