java - jdk11 g1gc 花费大量时间准备 TLAB-6ren

java - jdk11 g1gc 花费大量时间准备 TLAB

转载作者：行者123 更新时间：2023-12-04 11:39:07

gc.log 显示 Prepare TLABs 阶段花费了大约 57 秒，这是 Not Acceptable 。而且，这种情况五天才发生一次。我只想弄清楚究竟发生了什么以及如何避免。
[gc.log]

[2021-08-02T11:38:38.134+0800][322490.377s][161325][safepoint     ] Entering safepoint region: G1CollectForAllocation
[2021-08-02T11:38:38.134+0800][322490.378s][161325][gc,start      ] GC(238) Pause Young (Normal) (G1 Evacuation Pause)
[2021-08-02T11:38:38.134+0800][322490.378s][161325][gc,task       ] GC(238) Using 18 workers of 18 for evacuation
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)   Pre Evacuate Collection Set: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Prepare TLABs: 57039.1ms
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Choose Collection Set: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Humongous Register: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)   Evacuate Collection Set: 3.8ms
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Ext Root Scanning (ms):   Min:  0.0, Avg:  0.4, Max:  3.5, Diff:  3.5, Sum:  7.2, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Update RS (ms):           Min:  0.0, Avg:  0.5, Max:  0.9, Diff:  0.9, Sum:  8.7, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)       Processed Buffers:        Min: 0, Avg:  2.9, Max: 16, Diff: 16, Sum: 53, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)       Scanned Cards:            Min: 0, Avg: 265.7, Max: 623, Diff: 623, Sum: 4783, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)       Skipped Cards:            Min: 0, Avg: 20.4, Max: 32, Diff: 32, Sum: 368, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Scan RS (ms):             Min:  0.0, Avg:  0.2, Max:  0.3, Diff:  0.3, Sum:  3.2, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)       Scanned Cards:            Min: 0, Avg: 27.3, Max: 120, Diff: 120, Sum: 491, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)       Claimed Cards:            Min: 0, Avg: 29.9, Max: 129, Diff: 129, Sum: 538, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)       Skipped Cards:            Min: 0, Avg: 187.6, Max: 347, Diff: 347, Sum: 3377, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Code Root Scanning (ms):  Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.1, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     AOT Root Scanning (ms):   skipped
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Object Copy (ms):         Min:  0.0, Avg:  2.0, Max:  2.6, Diff:  2.6, Sum: 35.7, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.422s][161325][gc,phases     ] GC(238)     Termination (ms):         Min:  0.0, Avg:  0.4, Max:  0.6, Diff:  0.6, Sum:  7.4, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)       Termination Attempts:     Min: 1, Avg:  4.8, Max: 9, Diff: 8, Sum: 86, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     GC Worker Other (ms):     Min:  0.0, Avg:  0.1, Max:  0.3, Diff:  0.2, Sum:  2.2, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     GC Worker Total (ms):     Min:  3.4, Avg:  3.6, Max:  3.7, Diff:  0.3, Sum: 64.7, Workers: 18
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)   Post Evacuate Collection Set: 1.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Code Roots Fixup: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Clear Card Table: 0.2ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Reference Processing: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Weak Processing: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Merge Per-Thread State: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Code Roots Purge: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Redirty Cards: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     DerivedPointerTable Update: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Free Collection Set: 0.3ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Humongous Reclaim: 0.1ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Start New Collection Set: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Resize TLABs: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)     Expand Heap After Collection: 0.0ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,phases     ] GC(238)   Other: 57039.6ms
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,heap       ] GC(238) Eden regions: 865->0(867)
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,heap       ] GC(238) Survivor regions: 27->25(112)
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,heap       ] GC(238) Old regions: 20->20
[2021-08-02T11:39:35.179+0800][322547.423s][161325][gc,heap       ] GC(238) Humongous regions: 5->5
[2021-08-02T11:39:35.180+0800][322547.423s][161325][gc,metaspace  ] GC(238) Metaspace: 45664K->45664K(1091584K)
[2021-08-02T11:39:35.180+0800][322547.423s][161325][gc            ] GC(238) Pause Young (Normal) (G1 Evacuation Pause) 916M->48M(1488M) 57045.332ms
[2021-08-02T11:39:35.180+0800][322547.423s][161325][gc,cpu        ] GC(238) User=0.00s Sys=0.09s Real=57.05s
[2021-08-02T11:39:35.180+0800][322547.423s][161325][safepoint     ] Leaving safepoint region
[2021-08-02T11:39:35.180+0800][322547.423s][161325][safepoint     ] Total time for which application threads were stopped: 57.0457609 seconds, Stopping threads took: 0.0000407 seconds

最佳答案

就我而言，gc 日志不足以找到根本原因。
一些建议:

添加 -Xlog:gc+tlab=debug显示与 TLAB 相关的日志。

注意日志以:“TLAB totals: thrds:”开头，引用TLAB源码:threadLocalAllocBuffer.cpp

与gc日志对比分析可能出现的问题

如果日志显示“TLAB totals: thrds:”和“Pre Evacuate Collection Set”之间有很大的延迟，你应该深入研究“TLAB totals: thrds:”日志并找出原因(线程数太大，新创建线程并分配一些新对象...)

如果日志显示“TLAB totals: thrds:”和“Pre Evacuate Collection Set”之间几乎没有延迟，那么您应该将日志级别切换到 -Xlog:gc*=debug了解更多信息

一些怀疑:

也许有很多新创建的线程，每个线程至少创建一个对象。这可能会导致 TLAB 准备缓慢，因为会有很多 TLAB 来填充虚拟对象。

关于java - jdk11 g1gc 花费大量时间准备 TLAB，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/68644526/

文章推荐： typescript - 在 Typescript 中递归泛型？

文章推荐： javascript - 在 Shopware 6 中覆盖现有的插件 JS

arrays - 花费 O(1) 时间的数组访问是否可以改进？
我一直在读一本分配给类(class)的书，它提到数组访问需要 O(1) 时间。我意识到这非常快(也许尽可能快)，但是如果您有一个循环必须多次引用它，那么分配一个临时变量以在数组中查找值有什么好处吗？或
MySQL - 查询性能问题 - 花费 25 秒以上
我一直试图找出为什么这个查询花了这么长时间。以前，它的执行时间约为 150 毫秒到 200 毫秒，但现在需要 25 秒或更长时间。这是从昨晚到今天之间的事。唯一改变的就是将数据添加到表中。根据下面的
javascript - ng-if 花费 500 个观察者 - 性能
我有一个 ng repeat 重复数据。 - data.image(src)部分为null，src=null的不再重复。我用一个简单的 ng-if 解决了它。
phpunit --path-coverage(分支覆盖)花费 100 倍以上的时间
我有一个包含大量测试的 Laravel 项目。我正在使用 pcov 来计算代码覆盖率，大约需要 4 分钟。但是 pcov 不支持分支覆盖，所以我决定使用 xdebug。使用 xdebug 测试执行，
c# - AutoMapper 花费 4 秒绘制 19 个对象
我已经被这个问题困扰了一段时间了，我被难住了。 Automapper 需要 4 秒来映射 19 个对象。在我的机器(24GB 内存，3.6Ghz i7)上，该操作应该花费毫秒或纳秒。这是映射调用。
phpunit --path-coverage(分支覆盖)花费 100 倍以上的时间
我有一个包含大量测试的 Laravel 项目。我正在使用 pcov 来计算代码覆盖率，大约需要 4 分钟。但是 pcov 不支持分支覆盖，所以我决定使用 xdebug。使用 xdebug 测试执行，
java - TCP 连接比 ping 花费 X100 更长的时间
我在机器 A 上有一个 java 进程通过 TCP 与机器 B 上的 Tomcat 通信。 TCP 连接(只是 syn-syn/ack 交换)始终需要 100 毫秒的数量级，而 ping 请求需要 1
asp.net - 花费 200 万条记录的 Asp.Net GridView
我做了一项任务，从 sqlserver 获取超过 200 万条记录并将它们填充到 Asp.net GridView 中。问题是，查询需要超过 2 分钟才能获得记录，而我的查询现在已经完全优化。当我
javascript - 花费 X 秒并将其转换为 h :m:s 的最有效/最短方法
我希望将 165 秒变成 2:40 而不是 0:2:45 函数需要能够适应秒值的大小。我知道有无数种方法可以做到这一点，但我正在寻找一种干净的方法来做到这一点，除了 jQuery 之外没有任何外部库

行者123

个人简介

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

作者热门文章

滴滴打车优惠券免费领取

全站热门文章

首页

博学

6Ren·AI

商城

java - jdk11 g1gc 花费大量时间准备 TLAB