缓慢的应用程序，频繁的 JVM 挂起与单一 CPU 设置和 Java 12+
Slow application, frequent JVM hangs with single-CPU setups and Java 12+
我们有一个客户端应用程序（经过 10 年以上的开发）。它的 JDK 最近从 OpenJDK 11 升级到 OpenJDK 14。在单CPU（禁用超线程）Windows 10 设置（以及在 VirtualBox 机器中只有一个可用 CPU）上，与 Java 11 相比，应用程序启动非常慢。此外，它大部分时间使用 100% CPU。我们还可以通过将处理器关联设置为仅一个 CPU (c:\windows\system32\cmd.exe /C start /affinity 1 ...).
来重现该问题
在我的 VirtualBox 机器中以最少的手动交互启动应用程序并执行查询的一些测量：
- 打开JDK 11.0.2: 36 秒
- 打开JDK 13.0.2：~1.5 分钟
- 打开JDK 13.0.2
-XX:-UseBiasedLocking：46 秒
- 打开JDK 13.0.2
-XX:-ThreadLocalHandshakes: 40 秒
- 打开JDK 14: 5-6 分钟
- 打开JDK 14
-XX:-UseBiasedLocking: 3-3,5 分钟
- 打开JDK 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 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-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：
With OpenJDK 14 应用程序在我的（单CPU）VirtualBox 机器（运行 i7-6600U CPU).虚拟机有 3.5 GB RAM。根据任务管理器，40%+ 是可用的，磁盘 activity 是 0%（我猜这意味着没有交换）。将另一个 CPU 添加到虚拟机（并为物理机启用超线程）使应用程序再次足够快。我只是想知道，在 JDK 开发期间是否有意权衡以在（罕见的）单 CPU 机器上损失性能以使 JVM 在 multicore/hyper-threading CPUs 上更快？
根据我的经验，JDK 的性能问题主要与以下之一有关：
- JIT 编译
- VM 配置（堆大小）
- GC算法
- JVM/JDK 中的更改破坏了已知良好的 运行 应用程序
- （哦，我忘了提到 class 正在加载...）
如果您只是使用自 OpenJDK11 以来的默认 JVM 配置，也许您应该将一些更突出的选项设置为固定值，例如 GC、堆大小等
也许一些图形分析工具可以帮助追踪您的问题。像 Retrace、AppDynamics 或 FlightRecorder 之类的。与日志文件所能提供的相比，这些在给定时间提供了关于堆、GC 周期、RAM、线程、CPU 负载等的总体状态的更多概述。
我是否正确理解您的应用程序在 运行 的第一秒内将大约 30710 行写入日志（在 OpenJDK11 下）？为什么第一秒在OpenJDK14下"only"写了大概7k行？对于刚刚在不同 JVM 上启动的应用程序来说，这似乎是一个巨大的差异......你确定没有例如大量的异常堆栈跟踪转储到日志中吗？
其他数字有时甚至更高，所以减速可能与异常日志记录有关？或者甚至交换，如果 RAM 变低？
其实我在想，如果一个应用程序没有在日志中写入任何东西，这就是顺利运行没有问题的标志（除非它在这段时间完全冻结）。从第 12 秒到第 22 秒（在此处的 OpenJDK14 案例中）发生的事情是我更关心的……记录的行穿过屋顶……为什么？
然后日志记录下降到大约 1-2k 行的历史最低值...that 的原因是什么？ （好吧，也许是 GC 在第 22 秒开始并做了一个 tabula rasa 来解决一些事情......？）
另一件事可能是您关于 "single CPU" 机器的陈述。这是否也意味着 "single core"（Idk，也许您的软件是在旧硬件或其他东西上定制的）？
"single CPU" 虚拟机在那些机器上 运行？
但我认为，我对这些假设是错误的，因为现在几乎所有 CPU 都是多核的......但我可能会调查多线程问题（死锁）问题。
由于它使用了 100% CPU "most of the time"，并且 Java 14 需要 10 倍的时间（！），这意味着您浪费了 90% 的 CPU 在 Java 14.
运行 out of heap space can 这样做，因为你在 GC 上花费了很多时间，但你似乎已经裁定了出。
我注意到您正在调整偏向锁定选项，这会产生重大影响。这告诉我，也许您的程序在多个线程中执行大量并发工作。您的程序可能有一个并发错误，它出现在 Java 14 中，但没有出现在 Java 10 中。这也可以解释为什么添加另一个 CPU 会使它的速度提高两倍以上。
并发错误通常只在您不走运时才会出现，触发因素可能真的是任何事情，比如对 hashmap 组织的更改等。
首先，如果可行，请检查是否有任何循环可能正在忙等待而不是休眠。
然后，运行 采样模式下的探查器（jvisualvm 会做）并寻找占用总时间的百分比比应有的大得多的方法。由于您的性能下降了 10 倍，因此其中的任何问题都应该真正跳出来。
小心记录到慢速磁盘，它会减慢您的应用程序：
但这似乎不太可能是问题的原因，因为 CPU 仍然很忙，而且由于线程-，您不必等待所有线程到达安全点本地握手：https://openjdk.java.net/jeps/312
也与您遇到的问题没有直接关系，但更一般地说，如果您想尝试从硬件中挤出更多性能来启动时间，请查看 AppCDS（class 数据共享）：
https://blog.codefx.org/java/application-class-data-sharing/
这是一个有趣的问题，它需要不确定的努力来缩小它的范围，因为需要尝试许多排列和组合，并收集和整理数据。
似乎已经有一段时间没有解决这个问题了。也许这可能需要升级。
编辑 2：由于 "ThreadLocalHandshakes" 已被弃用，我们可以假设锁定是争用的，建议尝试不使用 "UseBiasedLocking" 以希望加快这种情况。
但是，有一些建议可以收集更多数据并尝试隔离问题。
- 分配一个以上的核心[我看到你已经试过了，问题消失了。 thread/s 执行排除其他人似乎是一个问题。见下面第 7 条）
- 分配更多的堆（也许 v14 的需求比早期的 jdks 更高）
- 为 Win 10 分配更多内存VB。
- 检查 OS 系统消息（您的情况是 Win 10）
- 运行 在非虚拟化的 Win 10 中。
- 尝试 jdk14
的不同版本
- 每隔（或配置文件）几个时间间隔执行一次线程转储。分析什么线程是运行独占。也许有公平分时的设置。也许有更高优先级的线程运行。那个线程是什么，它在做什么？在 linux 中，您可以实时统计与进程关联的轻量级进程（线程）及其状态。在 Win 10 上有类似的东西吗？
- CPU用法？ 100% 或更少？受 CPU 或 mem 约束？ 100% CPU 在服务线程中？哪个服务线程？
- 您是否明确设置了 GC 算法？
我亲眼目睹了版本中与 GC、堆大小调整、虚拟化容器问题等有关的问题。
我认为这个问题没有简单的答案，尤其是这个问题已经存在一段时间了。但我们可以尽力而为，让我们知道其中一些隔离步骤的结果。
编辑 1：从更新的问题来看，它似乎与 GC 或另一个服务线程非公平地接管单核（线程本地握手）有关？
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 的一些测量（有两个 CPUs）：
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 秒对比 ~400 毫秒
我也在主题中发送了this findings to the hotspot-dev@openjdk mail list and devs there confirmed that this is something that the JDK could handle better. You can find supposed fixes。
Another thread about the regression on hotspot-runtime-dev@. JIRA issue for the fix: JDK-8244340
我们有一个客户端应用程序（经过 10 年以上的开发）。它的 JDK 最近从 OpenJDK 11 升级到 OpenJDK 14。在单CPU（禁用超线程）Windows 10 设置（以及在 VirtualBox 机器中只有一个可用 CPU）上，与 Java 11 相比，应用程序启动非常慢。此外，它大部分时间使用 100% CPU。我们还可以通过将处理器关联设置为仅一个 CPU (c:\windows\system32\cmd.exe /C start /affinity 1 ...).
在我的 VirtualBox 机器中以最少的手动交互启动应用程序并执行查询的一些测量：
- 打开JDK 11.0.2: 36 秒
- 打开JDK 13.0.2：~1.5 分钟
- 打开JDK 13.0.2
-XX:-UseBiasedLocking：46 秒 - 打开JDK 13.0.2
-XX:-ThreadLocalHandshakes: 40 秒 - 打开JDK 14: 5-6 分钟
- 打开JDK 14
-XX:-UseBiasedLocking: 3-3,5 分钟 - 打开JDK 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 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-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：
With OpenJDK 14 应用程序在我的（单CPU）VirtualBox 机器（运行 i7-6600U CPU).虚拟机有 3.5 GB RAM。根据任务管理器，40%+ 是可用的，磁盘 activity 是 0%（我猜这意味着没有交换）。将另一个 CPU 添加到虚拟机（并为物理机启用超线程）使应用程序再次足够快。我只是想知道，在 JDK 开发期间是否有意权衡以在（罕见的）单 CPU 机器上损失性能以使 JVM 在 multicore/hyper-threading CPUs 上更快？
根据我的经验，JDK 的性能问题主要与以下之一有关：
- JIT 编译
- VM 配置（堆大小）
- GC算法
- JVM/JDK 中的更改破坏了已知良好的 运行 应用程序
- （哦，我忘了提到 class 正在加载...）
如果您只是使用自 OpenJDK11 以来的默认 JVM 配置，也许您应该将一些更突出的选项设置为固定值，例如 GC、堆大小等
也许一些图形分析工具可以帮助追踪您的问题。像 Retrace、AppDynamics 或 FlightRecorder 之类的。与日志文件所能提供的相比，这些在给定时间提供了关于堆、GC 周期、RAM、线程、CPU 负载等的总体状态的更多概述。
我是否正确理解您的应用程序在 运行 的第一秒内将大约 30710 行写入日志（在 OpenJDK11 下）？为什么第一秒在OpenJDK14下"only"写了大概7k行？对于刚刚在不同 JVM 上启动的应用程序来说，这似乎是一个巨大的差异......你确定没有例如大量的异常堆栈跟踪转储到日志中吗？
其他数字有时甚至更高，所以减速可能与异常日志记录有关？或者甚至交换，如果 RAM 变低？
其实我在想，如果一个应用程序没有在日志中写入任何东西，这就是顺利运行没有问题的标志（除非它在这段时间完全冻结）。从第 12 秒到第 22 秒（在此处的 OpenJDK14 案例中）发生的事情是我更关心的……记录的行穿过屋顶……为什么？
然后日志记录下降到大约 1-2k 行的历史最低值...that 的原因是什么？ （好吧，也许是 GC 在第 22 秒开始并做了一个 tabula rasa 来解决一些事情......？）
另一件事可能是您关于 "single CPU" 机器的陈述。这是否也意味着 "single core"（Idk，也许您的软件是在旧硬件或其他东西上定制的）？
"single CPU" 虚拟机在那些机器上 运行？ 但我认为，我对这些假设是错误的，因为现在几乎所有 CPU 都是多核的......但我可能会调查多线程问题（死锁）问题。
由于它使用了 100% CPU "most of the time"，并且 Java 14 需要 10 倍的时间（！），这意味着您浪费了 90% 的 CPU 在 Java 14.
运行 out of heap space can 这样做，因为你在 GC 上花费了很多时间，但你似乎已经裁定了出。
我注意到您正在调整偏向锁定选项，这会产生重大影响。这告诉我，也许您的程序在多个线程中执行大量并发工作。您的程序可能有一个并发错误，它出现在 Java 14 中，但没有出现在 Java 10 中。这也可以解释为什么添加另一个 CPU 会使它的速度提高两倍以上。
并发错误通常只在您不走运时才会出现，触发因素可能真的是任何事情，比如对 hashmap 组织的更改等。
首先，如果可行，请检查是否有任何循环可能正在忙等待而不是休眠。
然后，运行 采样模式下的探查器（jvisualvm 会做）并寻找占用总时间的百分比比应有的大得多的方法。由于您的性能下降了 10 倍，因此其中的任何问题都应该真正跳出来。
小心记录到慢速磁盘，它会减慢您的应用程序：
但这似乎不太可能是问题的原因，因为 CPU 仍然很忙，而且由于线程-，您不必等待所有线程到达安全点本地握手：https://openjdk.java.net/jeps/312
也与您遇到的问题没有直接关系，但更一般地说，如果您想尝试从硬件中挤出更多性能来启动时间，请查看 AppCDS（class 数据共享）：
https://blog.codefx.org/java/application-class-data-sharing/
这是一个有趣的问题，它需要不确定的努力来缩小它的范围，因为需要尝试许多排列和组合，并收集和整理数据。
似乎已经有一段时间没有解决这个问题了。也许这可能需要升级。
编辑 2：由于 "ThreadLocalHandshakes" 已被弃用，我们可以假设锁定是争用的，建议尝试不使用 "UseBiasedLocking" 以希望加快这种情况。
但是，有一些建议可以收集更多数据并尝试隔离问题。
- 分配一个以上的核心[我看到你已经试过了，问题消失了。 thread/s 执行排除其他人似乎是一个问题。见下面第 7 条）
- 分配更多的堆（也许 v14 的需求比早期的 jdks 更高）
- 为 Win 10 分配更多内存VB。
- 检查 OS 系统消息（您的情况是 Win 10）
- 运行 在非虚拟化的 Win 10 中。
- 尝试 jdk14 的不同版本
- 每隔（或配置文件）几个时间间隔执行一次线程转储。分析什么线程是运行独占。也许有公平分时的设置。也许有更高优先级的线程运行。那个线程是什么，它在做什么？在 linux 中，您可以实时统计与进程关联的轻量级进程（线程）及其状态。在 Win 10 上有类似的东西吗？
- CPU用法？ 100% 或更少？受 CPU 或 mem 约束？ 100% CPU 在服务线程中？哪个服务线程？
- 您是否明确设置了 GC 算法？
我亲眼目睹了版本中与 GC、堆大小调整、虚拟化容器问题等有关的问题。
我认为这个问题没有简单的答案，尤其是这个问题已经存在一段时间了。但我们可以尽力而为，让我们知道其中一些隔离步骤的结果。
编辑 1：从更新的问题来看，它似乎与 GC 或另一个服务线程非公平地接管单核（线程本地握手）有关？
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 的一些测量（有两个 CPUs）：
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 秒对比 ~400 毫秒
我也在主题中发送了this findings to the hotspot-dev@openjdk mail list and devs there confirmed that this is something that the JDK could handle better. You can find supposed fixes。 Another thread about the regression on hotspot-runtime-dev@. JIRA issue for the fix: JDK-8244340