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

Question

我在使用 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，一种解决方案是禁用 TLABS，-XX:-UseTLAB但这会使代码在已经很慢的机器上运行得更慢。

所以我认为另一个解决方案是禁用调整大小-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 分析

好的，所以这很有用，我将日志上传到 gceasy.org，它清楚地表明，在崩溃前不久，堆大小明显更高，接近 900mb 的限制，即使经过多次完整的 gc，我认为基本上它已经用完了堆空间.

有点令人沮丧的是我有

-XX:+HeapDumpOnOutOfMemoryError

选项已启用，但是当它崩溃时，它报告了一个问题，试图创建转储文件，因此我无法获得一个。

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

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

更新

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

        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

Answer 1

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

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

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

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

更新

GC 绝对没有问题。如果 GC 过载，您会收到以下java.lang.OutOfMemoryError消息：

GC 开销超出限制

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

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

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

Linux 的内存过度使用通常会触发 OOM 杀手。但有些情况下 OOM Killer 不会被触发（详细信息请参阅内核文档）。在这种情况下，进程可能会因 SIGSEGV 而终止。与其他本机应用程序一样，JVM 也使用mmap. mmap 的手册页还提到，根据所使用的参数，如果没有可用的物理内存，则在写入时可能会出现 SIGSEGV。