jvm-故障排查hs_pidxx-log日志文件

概述

#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (mmap) failed to map 12288 bytes for committing reserved memory.
# Possible reasons:
#   The system is out of physical RAM or swap space
#   In 32 bit mode, the process size limit was hit
# Possible solutions:
#   Reduce memory load on the system
#   Increase physical memory or swap space
#   Check if swap backing store is full
#   Use 64 bit Java on a 64 bit OS
#   Decrease Java heap size (-Xmx/-Xms)
#   Decrease number of Java threads
#   Decrease Java thread stack sizes (-Xss)
#   Set larger code cache with -XX:ReservedCodeCacheSize=
# This output file may be truncated or incomplete.
#
#  Out of Memory Error (os_linux.cpp:2673), pid=87787, tid=140293400606464
#
# JRE version: OpenJDK Runtime Environment (8.0_41-b04) (build 1.8.0_41-b04)
# Java VM: OpenJDK 64-Bit Server VM (25.40-b25 mixed mode linux-amd64 compressed oops)
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#

开头给出了发生的错误 ,以及可能的原因

线程和进程

可以看到都是 block 阻塞状态 .

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

Current thread (0x00007fa2a0457000):  JavaThread "ForkJoinPool.commonPool-worker-6" daemon [_thread_new, id=97331, stack(0x00007f989a3eb000,0x00007f989a4ec000)]

Stack: [0x00007f989a3eb000,0x00007f989a4ec000],  sp=0x00007f989a4ea7b0,  free space=1021k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0xa549bd]  VMError::report_and_die()+0x2bd
V  [libjvm.so+0x4e099b]  report_vm_out_of_memory(char const*, int, unsigned long, VMErrorType, char const*)+0x8b
V  [libjvm.so+0x8bd733]  os::Linux::commit_memory_impl(char*, unsigned long, bool)+0x103
V  [libjvm.so+0x8bd7fc]  os::pd_commit_memory(char*, unsigned long, bool)+0xc
V  [libjvm.so+0x8b66da]  os::commit_memory(char*, unsigned long, bool)+0x2a
V  [libjvm.so+0x8bb7ef]  os::pd_create_stack_guard_pages(char*, unsigned long)+0x7f
V  [libjvm.so+0x9fb8ce]  JavaThread::create_stack_guard_pages()+0x5e
V  [libjvm.so+0xa01b37]  JavaThread::run()+0x47
V  [libjvm.so+0x8bfd58]  java_start(Thread*)+0x108
C  [libpthread.so.0+0x7ea5]  start_thread+0xc5


---------------  P R O C E S S  ---------------

Java Threads: ( => current thread )
=>0x00007fa2a0457000 JavaThread "ForkJoinPool.commonPool-worker-6" daemon [_thread_new, id=97331, stack(0x00007f989a3eb000,0x00007f989a4ec000)]
  0x00007fa2a04a9000 JavaThread "ForkJoinPool.commonPool-worker-13" daemon [_thread_blocked, id=97330, stack(0x00007f989a9f1000,0x00007f989aaf2000)]
  0x00007fa2a838a800 JavaThread "ForkJoinPool.commonPool-worker-20" daemon [_thread_blocked, id=97324, stack(0x00007f989a5ed000,0x00007f989a6ee000)]
  0x00007fa2a837f000 JavaThread "ForkJoinPool.commonPool-worker-27" daemon [_thread_blocked, id=97323, stack(0x00007f989a4ec000,0x00007f989a5ed000)]
  0x00007fa2a838b800 JavaThread "ForkJoinPool.commonPool-worker-2" daemon [_thread_blocked, id=97322, stack(0x00007f989b1f9000,0x00007f989b2fa000)]
  0x00007fa29c3a2000 JavaThread "ForkJoinPool.commonPool-worker-9" daemon [_thread_blocked, id=97300, stack(0x00007f989aef6000,0x00007f989aff7000)]
  0x00007fa29c399800 JavaThread "ForkJoinPool.commonPool-worker-16" daemon [_thread_blocked, id=97299, stack(0x00007f989aff7000,0x00007f989b0f8000)]
  0x00007fa2983f2800 JavaThread "ForkJoinPool.commonPool-worker-23" daemon [_thread_in_Java, id=97298, stack(0x00007f989d219000,0x00007f989d31a000)]
  0x00007fa2983f2000 JavaThread "ForkJoinPool.commonPool-worker-30" daemon [_thread_blocked, id=97297, stack(0x00007f989bc03000,0x00007f989bd04000)]
  0x00007fa27c381800 JavaThread "ForkJoinPool.commonPool-worker-5" daemon [_thread_in_Java, id=97265, stack(0x00007f989b0f8000,0x00007f989b1f9000)]
  0x00007fa27c406800 JavaThread "ForkJoinPool.commonPool-worker-12" daemon [_thread_in_Java, id=97264, stack(0x00007f989b3fb000,0x00007f989b4fc000)]
  0x00007fa0fd75c800 JavaThread "FutureContext-pool-5" [_thread_blocked, id=97179, stack(0x00007f989a8f0000,0x00007f989a9f1000)]
  0x00007fa0fd75b800 JavaThread "FutureContext-pool-4" [_thread_blocked, id=97178, stack(0x00007f989abf3000,0x00007f989acf4000)]
  0

JVM 参数

可以看到 JVM 使用的是 G1 垃圾收集器 , 设置了最大的的内存大小为 4GB , 记住这里下面看GC 回收事件的时候有伏笔

VM Arguments:
jvm_args: -Xmx4096M -Xms4096M -XX:MetaspaceSize=512M -XX:MaxMetaspaceSize=512M -XX:+UseG1GC -agentlib:ByteCodeDecryptor -Xdebug -Xrunjdwp:server=y,transport=dt_socket,address=8011,suspend=n 
java_command: workflow-web.jar --spring.config.location=/apps/svr/gpm/workflow/config/application-dev.yml
java_class_path (initial): workflow-web.jar
Launcher Type: SUN_STANDARD

Environment Variables:
JAVA_HOME=/apps/soft/openJdk1.8
JRE_HOME=/apps/soft/openJdk1.8/jre
CLASSPATH=.:/apps/soft/openJdk1.8/lib:/apps/soft/openJdk1.8/jre/lib
PATH=/opt/libreoffice7.2/program:/apps/soft/openJdk1.8/bin:/opt/libreoffice7.2/program:/apps/soft/openJdk1.8/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/root/bin
SHELL=/bin/bash

GC 回收事件

可以看到前几个GC 事件中 , heap total 4194304K , 我们参考前面 JVM 的设置, JVM 设置了最大的的内存大小为 4GB , 也就是说GC 的时候好几次都达到了最大的内存使用限制 , 而 full 0 说明了根本就没有进行全代的垃圾回收 , 再看 GC 前 , young region 有 1228 个 ,而回收后只有 28个,清除了1000多个, 每一个 region size 2048K (2KB) , 也对应着回收的内存 , 这样子我们就可以得出分析 , 肯定是有一个不断产生的对象的线程存在 ,并且这个产生对象时间非常快 , 而产生的对象呢存活时间短 ,可以马上给回收(只是刚好触发了gc , 所以给回收了) .

GC Heap History (10 events):
Event: 1911330.532 GC heap before
{Heap before GC invocations=3612 (full 0):
 garbage-first heap   total 4194304K, used 3531348K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 1228 young (2514944K), 23 survivors (47104K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
Event: 1911330.738 GC heap after
Heap after GC invocations=3613 (full 0):
 garbage-first heap   total 4194304K, used 983915K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 28 young (57344K), 28 survivors (57344K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
}
Event: 1911930.589 GC heap before
{Heap before GC invocations=3613 (full 0):
 garbage-first heap   total 4194304K, used 3522920K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 1228 young (2514944K), 28 survivors (57344K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
Event: 1911930.791 GC heap after
Heap after GC invocations=3614 (full 0):
 garbage-first heap   total 4194304K, used 994931K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 34 young (69632K), 34 survivors (69632K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
}
Event: 1912530.531 GC heap before
{Heap before GC invocations=3614 (full 0):
 garbage-first heap   total 4194304K, used 3527940K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 1228 young (2514944K), 34 survivors (69632K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
Event: 1912530.742 GC heap after
Heap after GC invocations=3615 (full 0):
 garbage-first heap   total 4194304K, used 999123K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 36 young (73728K), 36 survivors (73728K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
}
Event: 1913130.675 GC heap before
{Heap before GC invocations=3615 (full 0):
 garbage-first heap   total 4194304K, used 3534328K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 1228 young (2514944K), 36 survivors (73728K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
Event: 1913130.848 GC heap after
Heap after GC invocations=3616 (full 0):
 garbage-first heap   total 4194304K, used 999284K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 35 young (71680K), 35 survivors (71680K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
}
Event: 1913730.736 GC heap before
{Heap before GC invocations=3616 (full 0):
 garbage-first heap   total 4194304K, used 3544991K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 1228 young (2514944K), 35 survivors (71680K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
Event: 1913730.906 GC heap after
Heap after GC invocations=3617 (full 0):
 garbage-first heap   total 4194304K, used 1001903K [0x00000006c0000000, 0x00000006c0204000, 0x00000007c0000000)
  region size 2048K, 35 young (71680K), 35 survivors (71680K)
 Metaspace       used 204323K, capacity 218883K, committed 222464K, reserved 1247232K
  class space    used 21212K, capacity 24188K, committed 24832K, reserved 1048576K
}

总结

通过分析hs_pidxx.log 文件得出一些有用的消息 ,从而助于我们解决应用出现的问题 .