java - 应用程序缓慢，JVM 在单 CPU 设置和 Java 12+ 时频繁挂起-6ren

java - 应用程序缓慢，JVM 在单 CPU 设置和 Java 12+ 时频繁挂起

转载作者：行者123 更新时间：2023-12-01 06:59:00

我们有一个客户端应用程序(经过 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 分钟

带有 -XX:-UseBiasedLocking 的 OpenJDK 13.0.2:46 秒

带有 -XX:-ThreadLocalHandshakes 的 OpenJDK 13.0.2:40 秒

OpenJDK 14:5-6 分钟

带有 -XX:-UseBiasedLocking 的 OpenJDK 14: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-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.5 GB RAM。根据任务管理器 40%+ 是免费的，磁盘 Activity 为 0%(我猜这意味着没有交换)。向虚拟机添加另一个 CPU(并为物理机启用超线程)使应用程序再次足够快。我只是想知道，在 JDK 开发过程中，为了让 JVM 在多核/超线程 CPU 上更快，在(罕见的)单 CPU 机器上损失性能是有意的权衡吗？

最佳答案

TL;博士 : 这是一个 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(带有两个 CPU)中对 Windows 10 x64 进行一些测量:

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那里的开发人员确认 this is something that the JDK could handle better .您可以找到 supposed fixes在线程中。
Another thread about the regression on hotspot-runtime-dev@ .修复的 JIRA 问题: JDK-8244340

关于java - 应用程序缓慢，JVM 在单 CPU 设置和 Java 12+ 时频繁挂起，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/61375565/

文章推荐： sql - 如何在oracle DB中检查某个日期是否在当前日历月中

文章推荐： jQuery - 如果前一个元素没有特定的类，则删除该元素

文章推荐： java swing并发在JTextArea中循环显示文本

C 程序我想知道是否有办法简化我的 dayofyear 程序？
我是 C 语言新手，我编写了这个 C 程序，让用户输入一年中的某一天，作为返回，程序将输出月份以及该月的哪一天。该程序运行良好，但我现在想简化该程序。我知道我需要一个循环，但我不知道如何去做。这是程序
java - GUI Java 程序 - Paint 程序
我一直在努力找出我的代码有什么问题。这个想法是创建一个小的画图程序，并有红色、绿色、蓝色和清除按钮。我有我能想到的一切让它工作，但无法弄清楚代码有什么问题。程序打开，然后立即关闭。 import ja
homebrew - 从 Homebrew 程序/欺骗程序到 Homebrew 程序/核心的迁移是什么？
我想安装screen，但是接下来我应该做什么？ $ brew search screen imgur-screenshot screen
python - 客户端(python 程序)没有收到服务器(c 程序)返回的响应？
我有一个在服务器端工作的 UDP 套接字应用程序。为了测试服务器端，我编写了一个简单的 python 客户端程序，它发送消息“hello world how are you”。服务器随后应接收消息，将
python - 运行一个 shell 脚本，该脚本运行一个 python 程序，然后运行一个 R 程序
我有一个 shell 脚本，它运行一个 Python 程序来预处理一些数据，然后运行一个 R 程序来执行一些长时间运行的任务。我正在学习使用 Docker 并且我一直在运行 FROM r-base:l
python - 在 Linux 中从 Python 启动一个 c 程序，将一个大文本字符串作为参数传递给 c 程序
在 Linux 中。我有一个 c 程序，它读取一个 2048 字节的文本文件作为输入。我想从 Python 脚本启动 c 程序。我希望 Python 脚本将文本字符串作为参数传递给 c 程序，而不是将
在网页上调起本机C#程序
前言最近开始整理笔记里的库存草稿，本文是 23 年 5 月创建的了（因为中途转移到 onedrive，可能还不止）网页调起电脑程序是经常用到的场景，比如百度网盘下载，加入 QQ 群之类的我
VHDL 程序
对于一个类，我被要求编写一个 VHDL 程序，该程序接受两个整数输入 A 和 B，并用 A+B 替换 A，用 A-B 替换 B。我编写了以下程序和测试平台。它完成了实现和行为语法检查，但它不会模拟。尽
haskell 程序
module Algorithm where import System.Random import Data.Maybe import Data.List type Atom = String ty
求给定N个数的最小公倍数的C++程序
我想找到两个以上数字的最小公倍数求给定N个数的最小公倍数的C++程序最佳答案 int lcm(int a, int b) { return (a/gcd(a,b))*b; } 对于gcd，请查看
索引器的c#程序
这个程序有错误。谁能解决这个问题？ Error is :TempRecord already defines a member called 'this' with the same paramete
铁路围栏密码的C++程序
当我运行下面的程序时，我在 str1 和 str2 中得到了垃圾值。所以 #include #include #include using namespace std; int main() {
死兔子的C++程序
这是我的作业: 一对刚出生的兔子(一公一母)被放在田里。兔子在一个月大时可以交配，因此在第二个月的月底，每对兔子都会生出两对新兔子，然后死去。注:在第0个月，有0对兔子。第 1 个月，有 1 对兔子
十进制转十六进制的C++程序
我编写了一个程序，通过对字母使用 switch 命令将十进制字符串转换为十六进制，但是如果我使用 char，该程序无法正常工作!没有 switch 我无法处理 9 以上的数字。我希望你能理解我，因为我
连接MySQL的C++程序
我是 C++ 新手(虽然我有一些 C 语言经验)和 MySQL，我正在尝试制作一个从 MySQL 读取数据库的程序，我一直在关注这个 tutorial但当我尝试“构建”解决方案时出现错误。 (我正在使
Swift If 程序
仍然是一个初学者，只是尝试使用 swift 中的一些基本函数。有人能告诉我这段代码有什么问题吗？ import UIKit var guessInt: Int var randomNum = arc
折叠常量的C++程序
我正在用 C++11 编写一个函数，它采用 constant1 + constant2 形式的表达式并将它们折叠起来。 constant1 和 constant2 存储在 std::string 中，
2个矩阵相加和相乘的C++程序
我用 C++ 编写了这段代码，使用运算符重载对 2 个矩阵进行加法和乘法运算。当我执行代码时，它会在第 57 行和第 59 行产生错误，非法结构操作(两行都出现相同的错误)。请解释我的错误。提前致谢:
交换字符串中两个字符的C++程序
我是 C++ 的初学者，我想编写一个简单的程序来交换字符串中的两个字符。例如；我们输入这个字符串:“EXAMPLE”，我们给它交换这两个字符:“E”和“A”，输出应该类似于“AXEMPLA”。我在
确定三角形的C++程序
我需要以下代码的帮助: 声明 3 个 double 类型变量，每个代表三角形的三个边中的一个。提示用户为第一面输入一个值，然后将用户的输入设置为您创建的代表三角形第一条边的变量。将最后 2 个步

行者123

个人简介

我是一名优秀的程序员,十分优秀！

作者热门文章

滴滴打车优惠券免费领取

全站热门文章

首页

博学

6Ren·AI

商城

java - 应用程序缓慢，JVM 在单 CPU 设置和 Java 12+ 时频繁挂起