如何为 Java 应用程序确定合适的 TLABSIZE 设置？答案

【问题标题】：How do I decide on a suitable TLABSIZE setting for a Java application?如何为 Java 应用程序确定合适的 TLABSIZE 设置？
【发布时间】：2020-09-05 16:29:34
【问题描述】：

我在使用 Java 14 的单 CPU arm7（32 位）设备上的 Java 应用程序偶尔会崩溃在负载下运行几个小时后，总是在ThreadLocalAllocBuffer::resize() 中失败

  A fatal error has been detected by the Java Runtime Environment:
    #
    SIGSEGV (0xb) at pc=0xb6cd515e, pid=1725, tid=1733
    #
    JRE version: OpenJDK Runtime Environment (14.0+36) (build 14+36)
    Java VM: OpenJDK Client VM (14+36, mixed mode, serial gc, linux-arm)
    Problematic frame:
    V
    #
    No core dump will be written. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
    #
    If you would like to submit a bug report, please visit:
    https://bugreport.java.com/bugreport/crash.jsp
    #

--------------- S U M M A R Y ------------

Command Line: -Duser.home=/mnt/app/share/log -Djdk.lang.Process.launchMechanism=vfork -Xms150m -Xmx900m -Dcom.mchange.v2.log.MLog=com.mchange.v2.log.jdk14logging.Jdk14MLog -Dorg.jboss.logging.provider=jdk -Djava.util.logging.config.class=com.jthink.songkong.logging.StandardLogging --add-opens=java.base/java.lang=ALL-UNNAMED lib/songkong-6.9.jar -r

Host: Marvell PJ4Bv7 Processor rev 1 (v7l), 1 cores, 1G, Buildroot 2014.11-rc1
Time: Fri Apr 24 19:36:54 2020 BST elapsed time: 37456 seconds (0d 10h 24m 16s)


    --------------- T H R E A D ---------------

    Current thread (0xb6582a30): VMThread "VM Thread" [stack: 0x7b716000,0x7b796000] [id=3625] _threads_hazard_ptr=0x7742f140

    Stack: [0x7b716000,0x7b796000], sp=0x7b7946b0, free space=505k
    Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
    V [libjvm.so+0x48015e] ThreadLocalAllocBuffer::resize()+0x85

    [error occurred during error reporting (printing native stack), id 0xb, SIGSEGV (0xb) at pc=0xb6b4ccae]

现在这肯定是 JVM 中的错误，但由于它不是标准的 Java 平台之一，而且我没有简单的测试用例，我无法看到它很快得到修复，所以我正在尝试解决它。还值得注意的是，当我使用 Java 11 时，它与 ThreadLocalAllocBuffer::accumulate_statistics_before_gc() 崩溃了，这就是我转向 Java 14 来尝试解决问题的原因。

由于 TLAB 存在问题，一种解决方案是使用 -XX:-UseTLAB 禁用 TLABS，但这会使代码在已经很慢的机器上运行得更慢。

所以我认为另一种解决方案是使用-XX:-ResizeTLAB 禁用调整大小，但是我需要知道计算出合适的大小并指定使用-XX:TLABSize=N。但我不确定 N 实际代表什么以及设置合适的大小

我尝试设置-XX:TLABSize=1000000，这在我看来相当大？

我用

设置了一些日志记录

 -Xlog:tlab*=debug,tlab*=trace:file=gc.log:time:filecount=7,filesize=8M

但我不太了解输出。

[2020-05-19T15:43:43.836+0100] ThreadLocalAllocBuffer::compute_size(132) returns 250132
[2020-05-19T15:43:43.837+0100] TLAB: fill thread: 0x0026d548 [id: 871] desired_size: 976KB slow allocs: 0  refill waste: 15624B alloc: 0.25725     1606KB refills: 1 waste  0.0% gc: 0B slow: 0B fast: 0B
[2020-05-19T15:43:43.853+0100] ThreadLocalAllocBuffer::compute_size(6) returns 250006
[2020-05-19T15:43:43.854+0100] TLAB: fill thread: 0xb669be48 [id: 32635] desired_size: 976KB slow allocs: 0  refill waste: 15624B alloc: 0.00002        0KB refills: 1 waste  0.0% gc: 0B slow: 0B fast: 0B
[2020-05-19T15:43:43.910+0100] ThreadLocalAllocBuffer::compute_size(4) returns 250004
[2020-05-19T15:43:43.911+0100] TLAB: fill thread: 0x76c1d6f8 [id: 917] desired_size: 976KB slow allocs: 0  refill waste: 15624B alloc: 0.91261     8085KB refills: 1 waste  0.0% gc: 0B slow: 0B fast: 0B
[2020-05-19T15:43:43.962+0100] ThreadLocalAllocBuffer::compute_size(2052) returns 252052
[2020-05-19T15:43:43.962+0100] TLAB: fill thread: 0x76e06f10 [id: 534] desired_size: 976KB slow allocs: 4  refill waste: 15688B alloc: 0.13977     1612KB refills: 2 waste  0.2% gc: 0B slow: 4520B fast: 0B
[2020-05-19T15:43:43.982+0100] ThreadLocalAllocBuffer::compute_size(28878) returns 278878
[2020-05-19T15:43:43.983+0100] TLAB: fill thread: 0x76e06f10 [id: 534] desired_size: 976KB slow allocs: 4  refill waste: 15624B alloc: 0.13977     1764KB refills: 3 waste  0.3% gc: 0B slow: 10424B fast: 0B
[2020-05-19T15:43:44.023+0100] ThreadLocalAllocBuffer::compute_size(4) returns 250004
[2020-05-19T15:43:44.023+0100] TLAB: fill thread: 0x7991df20 [id: 32696] desired_size: 976KB slow allocs: 0  refill waste: 15624B alloc: 0.00132       19KB refills: 1 waste  0.0% gc: 0B slow: 0B fast: 0B

更新

我添加了 -XX:+HeapDumpOnOutOfMemoryError 选项重新运行，这次它显示：

java.lang.OutOfMemoryError: Java heap space
Dumping heap to java_pid1600.hprof ...

但是转储本身失败了

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0xb6a81b9a, pid=1600, tid=1606
#
# JRE version: OpenJDK Runtime Environment (14.0+36) (build 14+36)
# Java VM: OpenJDK Client VM (14+36, mixed mode, serial gc, linux-arm)
# Problematic frame:
# V  [libjvm.so+0x22eb9a]  DumperSupport::dump_field_value(DumpWriter*, char, oopDesc*, int)+0x91
#
# No core dump will be written. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /mnt/system/config/Apps/SongKong/songkong/hs_err_pid1600.log
#
# If you would like to submit a bug report, please visit:
#   https://bugreport.java.com/bugreport/crash.jsp

我不清楚转储是否因为 ulimit 或其他原因而失败，但是 java_pid1600.hprof 已创建但为空

我还使用jstat -gc 和jstat -gcutil 监控该过程。我将 putput 的末尾粘贴在这里，对我来说，崩溃前似乎没有特定的内存问题，尽管我只每 5 秒检查一次，所以也许这就是问题所在？

[root@N1-0247 bin]# ./jstat -gc 1600 5s

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
........
30720.0 30720.0  0.0    0.0   245760.0 236647.2  614400.0   494429.2  50136.0 49436.9  0.0    0.0     5084 3042.643  155   745.523   -          - 3788.166
30720.0 30720.0  0.0   28806.1 245760.0 244460.2  614400.0   506541.7  50136.0 49436.9  0.0    0.0     5085 3043.887  156   745.523   -          - 3789.410
30720.0 30720.0 28760.4  0.0   245760.0 245760.0  614400.0   514809.7  50136.0 49437.2  0.0    0.0     5086 3044.895  157   751.204   -          - 3796.098
30720.0 30720.0  0.0   231.1  245760.0 234781.8  614400.0   514809.7  50136.0 49437.2  0.0    0.0     5087 3044.895  157   755.042   -          - 3799.936
30720.0 30720.0  0.0    0.0   245760.0 190385.5  614400.0   519650.7  50136.0 49449.6  0.0    0.0     5087 3045.905  159   758.890   -          - 3804.795
30720.0 30720.0  0.0    0.0   245760.0 190385.5  614400.0   519650.7  50136.0 49449.6  0.0    0.0     5087 3045.905  159   758.890   -          - 3804.795

[root@N1-0247 bin]# ./jstat -gc 1600 5s
     S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT    CGC    CGCT     GCT
..............
     99.70   0.00 100.00  75.54  98.56      -   5080 3037.321   150  724.674     -        - 3761.995
      0.00  29.93  99.30  75.55  98.56      -   5081 3038.403   151  728.584     -        - 3766.987
      0.00 100.00  99.30  75.94  98.56      -   5081 3039.405   152  728.584     -        - 3767.989
    100.00   0.00  99.14  76.14  98.56      -   5082 3040.366   153  734.088     -        - 3774.454
      0.00  96.58  99.87  78.50  98.57      -   5083 3041.366   154  737.960     -        - 3779.325
     56.99   0.00 100.00  78.50  98.58      -   5084 3041.366   154  741.880     -        - 3783.246
      0.00   0.00  96.29  80.47  98.61      -   5084 3042.643   155  745.523     -        - 3788.166
      0.00  93.77  99.47  82.44  98.61      -   5085 3043.887   156  745.523     -        - 3789.410
     93.62   0.00 100.00  83.79  98.61      -   5086 3044.895   157  751.204     -        - 3796.098
      0.00   0.76  95.53  83.79  98.61      -   5087 3044.895   157  755.042     -        - 3799.936
      0.00   0.00  77.47  84.58  98.63      -   5087 3045.905   159  758.890     -        - 3804.795
      0.00   0.00  77.47  84.58  98.63      -   5087 3045.905   159  758.890     -        - 3804.795

更新最新运行

配置gclogging，我得到很多

Pause Young (Allocation Failure)

错误，这是否表明我需要使伊甸园空间更大？

[2020-05-29T14:00:22.668+0100] GC(44) Pause Young (GCLocker Initiated GC)
[2020-05-29T14:00:22.739+0100] GC(44) DefNew: 43230K(46208K)->4507K(46208K) Eden: 41088K(41088K)->0K(41088K) From: 2142K(5120K)->4507K(5120K)
[2020-05-29T14:00:22.739+0100] GC(44) Tenured: 50532K(102400K)->50532K(102400K)
[2020-05-29T14:00:22.740+0100] GC(44) Metaspace: 40054K(40536K)->40054K(40536K)
[2020-05-29T14:00:22.740+0100] GC(44) Pause Young (GCLocker Initiated GC) 91M->53M(145M) 72.532ms
[2020-05-29T14:00:22.741+0100] GC(44) User=0.07s Sys=0.00s Real=0.07s
[2020-05-29T14:00:25.196+0100] GC(45) Pause Young (Allocation Failure)
[2020-05-29T14:00:25.306+0100] GC(45) DefNew: 45595K(46208K)->2150K(46208K) Eden: 41088K(41088K)->0K(41088K) From: 4507K(5120K)->2150K(5120K)
[2020-05-29T14:00:25.306+0100] GC(45) Tenured: 50532K(102400K)->53861K(102400K)
[2020-05-29T14:00:25.307+0100] GC(45) Metaspace: 40177K(40664K)->40177K(40664K)
[2020-05-29T14:00:25.307+0100] GC(45) Pause Young (Allocation Failure) 93M->54M(145M) 111.252ms
[2020-05-29T14:00:25.308+0100] GC(45) User=0.08s Sys=0.02s Real=0.11s
[2020-05-29T14:00:29.248+0100] GC(46) Pause Young (Allocation Failure)
[2020-05-29T14:00:29.404+0100] GC(46) DefNew: 43238K(46208K)->4318K(46208K) Eden: 41088K(41088K)->0K(41088K) From: 2150K(5120K)->4318K(5120K)
[2020-05-29T14:00:29.405+0100] GC(46) Tenured: 53861K(102400K)->53861K(102400K)
[2020-05-29T14:00:29.405+0100] GC(46) Metaspace: 40319K(40792K)->40319K(40792K)
[2020-05-29T14:00:29.406+0100] GC(46) Pause Young (Allocation Failure) 94M->56M(145M) 157.614ms
[2020-05-29T14:00:29.406+0100] GC(46) User=0.07s Sys=0.00s Real=0.16s
[2020-05-29T14:00:36.466+0100] GC(47) Pause Young (Allocation Failure)
[2020-05-29T14:00:36.661+0100] GC(47) DefNew: 45406K(46208K)->5120K(46208K) Eden: 41088K(41088K)->0K(41088K) From: 4318K(5120K)->5120K(5120K)
[2020-05-29T14:00:36.662+0100] GC(47) Tenured: 53861K(102400K)->55125K(102400K)
[2020-05-29T14:00:36.662+0100] GC(47) Metaspace: 40397K(40920K)->40397K(40920K)
[2020-05-29T14:00:36.663+0100] GC(47) Pause Young (Allocation Failure) 96M->58M(145M) 196.531ms
[2020-05-29T14:00:36.663+0100] GC(47) User=0.09s Sys=0.01s Real=0.19s
[2020-05-29T14:00:40.523+0100] GC(48) Pause Young (Allocation Failure)
[2020-05-29T14:00:40.653+0100] GC(48) DefNew: 44274K(46208K)->2300K(46208K) Eden: 39154K(41088K)->0K(41088K) From: 5120K(5120K)->2300K(5120K)
[2020-05-29T14:00:40.653+0100] GC(48) Tenured: 55125K(102400K)->59965K(102400K)
[2020-05-29T14:00:40.654+0100] GC(48) Metaspace: 40530K(41048K)->40530K(41048K)
[2020-05-29T14:00:40.654+0100] GC(48) Pause Young (Allocation Failure) 97M->60M(145M) 131.365ms
[2020-05-29T14:00:40.655+0100] GC(48) User=0.11s Sys=0.01s Real=0.14s
[2020-05-29T14:00:43.936+0100] GC(49) Pause Young (Allocation Failure)
[2020-05-29T14:00:44.100+0100] GC(49) DefNew: 43388K(46208K)->5120K(46208K) Eden: 41088K(41088K)->0K(41088K) From: 2300K(5120K)->5120K(5120K)

更新了 gceasy 完成的 gc 分析

好的，这很有用堆空间。

有点令人沮丧的是我有

-XX:+HeapDumpOnOutOfMemoryError

选项已启用，但当它崩溃时，它会报告尝试创建转储文件时出现问题，因此我无法获得。

当我在 Windows 上使用相同的堆大小设置处理相同的文件时，它会成功而不会失败，但是我会在启用 gclogging 的情况下再次运行，看看它是否达到 simailr 级别，即使它实际上并没有倒下。

再次运行（这是建立在上一次运行中进行的更改并且不显示运行开始）但对我来说内存使用率较高但看起来很正常（锯齿模式）在崩溃之前没有特别的差异。

更新

在上次运行时，我将最大堆从 900MB 减少到 600MB，但我还使用 vmstat 进行了监控，你可以清楚地看到应用程序崩溃的位置，但此时似乎我们并没有特别接近 ow 内存。

        procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
     3  0      0  57072   7812 1174128    0    0  5360     0  211  558 96  4  0  0  0
     1  0      0  55220   7812 1176184    0    0  2048     0  203  467 79 21  0  0  0
     3  0      0  61296   7812 1169096    0    0  2036    44  193  520 96  4  0  0  0
     2  0      0  59808   7812 1171144    0    0  2048    32  212  522 96  4  0  0  0
     1  0      0  59436   7812 1171144    0    0     0     0  180  307 83 17  0  0  0
     1  0      0  59436   7812 1171144    0    0     0     0  179  173 100  0  0  0  0
     1  0      0  59436   7812 1171128    0    0     0     0  179  184 100  0  0  0  0
     2  1      0  51764   7816 1158452    0    0  4124    52  190  490 80 20  0  0  0
     3  0      0  63428   7612 1146388    0    0 20472    48  251  533 86 14  0  0  0
     2  0      0  63428   7616 1146412    0    0     4     0  196  508 99  1  0  0  0
     2  0      0  84136   7616 1146400    0    0     0     0  186  461 84 16  0  0  0
     2  0      0  61436   7608 1148960    0    0 24601     0  325  727 77 23  0  0  0
     4  0      0  60196   7648 1150204    0    0  1160    76  232  611 98  2  0  0  0
     4  0      0  59204   7656 1151052    0    0    52   376  305  570 80 20  0  0  0
     3  0      0  59204   7656 1151052    0    0     0     0  378  433 96  4  0  0  0
     1  0      0 762248   7768 1151420    0    0   106     0  253  660 74 26  0  0  0
     0  0      0 859272   8188 1151892    0    0   417     0  302  550  9 26 64  1  0
     0  0      0 859272   8188 1151892    0    0     0     0  111  132  0  0 100  0  0

【问题讨论】：

尝试通过设置一些选项来解决软件中的错误是非常雄心勃勃的，当并不清楚错误是否真的存在于该功能或该功能只是表现出症状时。最后一行是一个很大的警告信号：error occurred during error reporting (printing native stack), id 0xb, SIGSEGV (0xb) at pc=0xb6b4ccae]，因为它表明不仅该函数执行了非法操作，而且 JVM 似乎处于非法状态，在完全不相关的位置产生 SIGSEGV。这表明您只关注症状。
但除此之外，您还可以使用-XX:+PrintFlagsFinal，在您的设置中查看MinTLABSize 的值，这会提示您有关TLABSize 选项的数量级。跨度>
我知道原因很难追踪（即使不是不可能），尤其是在你没有编写的软件中。如果我有更好的建议，我就写了。您可以使用my other comment 中提到的选项，也许固定的 TLAB 大小确实有帮助，但我不是很乐观……
我担心显然需要指定 --add-opens=java.base/java.lang=ALL-UNNAMED。除此之外，您还应该考虑其他可能性：1）真正的硬件问题和 2）操作系统问题。
...这些问题或指定--add-opens=java.base/java.lang=ALL-UNNAMED 的必要性意味着这些库正在访问java.lang 包的内部。可能在 Java 版本之间发生变化的内部结构现在会损害 JVM 的稳定性。我们正在谈论java.lang 包...

标签： java performance garbage-collection heap-memory

【解决方案1】：

我认为你可能已经走错路了：

您的进程更有可能在分配内存方面存在一般问题，而不是在两个不同的 Java 版本中存在两个不同的错误。

你是否已经检查过进程是否有足够的内存？当进程内存不足时，也可能发生分段错误。我还会检查交换文件的配置。几年前，我在调整大小或分配方法的某个地方也遇到了 Java 8 莫名其妙的段错误。就我而言，操作系统交换文件的大小设置为零。

您在错误日志文件的顶部看到了什么错误？你只复制了单线程的信息。

更新

你肯定没有 GC 的问题。如果 GC 会超载，您会在收到带有消息的 java.lang.OutOfMemoryError 时有些：

超出 GC 开销限制

GC 尝试收集垃圾，但它也有 CPU 限制。具体行为取决于实际的 GC 实现，但通常垃圾会在 GC 使用更多 CPU 周期之前积累（参见您的大 OldGen）。因此，只要您没有收到提到的 OOM 错误，增加的堆使用量是完全正常的。

本机代码中的分段错误表明访问本机内存有问题。当 JVM 尝试生成转储时，您甚至会遇到分段错误。这是访问本机内存的一般问题的附加指标。

仍然没有答案的是您是否真的有足够的本机内存供主机上运行的所有进程使用。

Linux 过度使用内存通常会触发 OOM 杀手。但是在某些情况下 OOM 杀手没有被触发（详见kernel documentation）。在这种情况下，进程可能会因 SIGSEGV 而死。与其他本机应用程序一样，JVM 也使用mmap。 man pages of mmap 还提到，根据使用的参数，如果没有可用的物理内存，写入时可能会出现 SIGSEGV。

【讨论】：

好吧，应用程序从未在任何其他环境（windows、macos、标准 linux）上崩溃，并且在使用 Java 9 时从未崩溃。它可能内存不足，但应该是 OutOfMemoryError抛出的JVM不应该只是崩溃，可能与交换有关，不知道我如何检查这个？
由于操作系统可能允许内存过度使用，您可能会遇到不会出现内存不足错误的情况。你还没有提到你的操作系统。所以我假设你使用的是 Linux。使用以下命令检查您的操作系统正在运行的过度使用模式：sysctl vm.overcommit_memory。检查交换文件配置取决于您的操作系统。您的硬件描述让我假设您在 Raspi 上运行。如果您应该使用 Raspian，以下命令会显示交换文件配置的状态：sudo service dphys-swapfile status
不使用 Rasbperrypi，我使用的是 Linux 3.3.4-ROMROOT-NT1，cmd sysctl vm.overcommit_memory 返回 vm.overcommit_memory = 0
使用 free -h 检查交换大小。如果交换大小为 0，则禁用交换。您还可以通过将 vm.overcommit_memory 更改为 2 来暂时禁用过度使用，并查看是否出现内存不足错误而不是 segfault。
ok 交换已禁用，free -h 显示正在使用 1.2GB，我已将堆大小设置为 900mb，因此我的应用程序实际使用的总内存为 1.2GB（Heap + Metaspace+ThreadstackSpace等）或如果使用所有 900MB 堆可以使用的最大值？

【解决方案2】：

根据您的 jstat 数据及其在此处的解释：https://docs.oracle.com/en/java/javase/11/tools/jstat.html#GUID-5F72A7F9-5D5A-4486-8201-E1D1BA8ACCB5

我不希望 HeapSpace 出现 OutOfMemoryError，因为老年代填充的缓慢而稳定的速率以及 from 和 to 空间的小尺寸（我不知道您的应用程序是否可能随时分配一个巨大的数组很快）除非：

初始堆大小 (-Xms) 小于最大值 (-Xmx) 并且
Linux 已过度使用虚拟内存

如果您确实过度使用（而谁没有），也许您应该使用vmstat 1 关注 Linux 或经常为 sar 收集数据

但我确实想知道为什么您不使用带有 -Xlog:gc*:stderr 的垃圾收集日志记录或带有 -Xlog:gc*:file= 的文件，并且可能使用 https://gceasy.io/ 进行分析，因为它的开销非常低（除非写入日志文件很慢）并且非常精确。有关日志记录语法的更多信息，请参阅：https://openjdk.java.net/jeps/158 和 https://openjdk.java.net/jeps/271

java -Xlog:gc*:stderr -jar yourapp.jar

并使用以下工具轻松分析这些日志：

https://gceasy.io/
JClarity 普查

这应该会实时提供与 jstack 类似的信息（据我所知）

【讨论】：

初始堆大小 (-Xms) 小于最大值 (-Xmx)，你认为我应该尝试将其设置为相同吗，机器上没有交换但我无法更改，但是我将堆设置为小于可用内存的一半，并且几乎没有其他运行，所以应该没问题，我现在有 vmstat 运行？
监控 gc 不是我以前必须打扰的事情，所以这一切对我来说都是新的，但我正在考虑记录 gc，所以我接下来会尝试。
很高兴您现在监控您的虚拟内存，因为这可能会揭示操作系统虚拟内存限制的任何问题，因为 Java 堆可能会增长到 -Xmx 并且 Java 为每个线程使用本机内存（堆栈)、元空间，以及出于效率原因在本地方法 (JNI) 中实现的任何内容，例如 zip、直接 ByteBuffer 等
请同时验证ulimit -v 和ulimit -s 和朋友的输出：ulimit -a 对于运行Java 的用户，它不限制内存使用，有关一些解释，请参见bash 手册页（我假设您使用 bash 作为 shell，而 ulimit 是内置的 shell）和：man7.org/linux/man-pages/man2/getrlimit.2.html - 因为它们也可能导致分段错误。
Sum(free+cache+buffers) 不应接近于零。另见：linuxatemyram.com