记一次线上coredump事故

时间：2021-07-23 09:38:52

1、事故背景

　　上周三凌晨，我负责的某个模块在多台机器上连续发生coredump，幸好发生在业务低峰期，而且该模块提供的功能也不是核心流程功能，所以对线上业务影响比较小。发生coredump后，运维收到报警后立马拉起了服务，服务宕机时间为3分钟左右。

2、事故分析

　　第二天立即组织了事故分析小组，对事故发生原因进行了排查，coredump的时候JVM保存了coredump文件，运维帮忙转换成了问题分析结果文件，如下

#
# There is insufficient memory for the Java Runtime Environment to continue.
# Native memory allocation (malloc) failed to allocate 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:2756), pid=43471, tid=140153494918912
#
# JRE version: Java(TM) SE Runtime Environment (7.0_75-b13) (build 1.7.0_75-b13)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (24.75-b04 mixed mode linux-amd64 compressed oops)
# Core dump written. Default location: /home/xiaoju/marketing-mall/core or core.43471 (max size 100000000 kB). To ensure a full core dump, try "ulimit -c unlimited" before s
tarting Java again
#

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

Current thread (0x00007f8080013800): JavaThread "ThreadPool_2" [_thread_new, id=31832, stack(0x00007f7807375000,0x00007f7807476000)]

Stack: [0x00007f7807375000,0x00007f7807476000], sp=0x00007f7807474980, free space=1022k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V [libjvm.so+0x9a18da] VMError::report_and_die()+0x2ea
V [libjvm.so+0x4975ab] report_vm_out_of_memory(char const*, int, unsigned long, char const*)+0x9b
V [libjvm.so+0x81ebae] os::Linux::commit_memory_impl(char*, unsigned long, bool)+0xfe
V [libjvm.so+0x81ec6c] os::pd_commit_memory(char*, unsigned long, bool)+0xc
V [libjvm.so+0x8169da] os::commit_memory(char*, unsigned long, bool)+0x2a
V [libjvm.so+0x81d13d] os::pd_create_stack_guard_pages(char*, unsigned long)+0x6d
V [libjvm.so+0x953e1e] JavaThread::create_stack_guard_pages()+0x5e
V [libjvm.so+0x95a764] JavaThread::run()+0x34
V [libjvm.so+0x820b88] java_start(Thread*)+0x108

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

Java Threads: ( => current thread )
=>0x00007f8080013800 JavaThread "ThreadPool_2" [_thread_new, id=31832, stack(0x00007f7807375000,0x00007f7807476000)]
0x00007f8080013000 JavaThread "ThreadPool_1" [_thread_blocked, id=31828, stack(0x00007f780eff1000,0x00007f780f0f2000)]
0x00007f808000a000 JavaThread "ThreadPool_0" [_thread_blocked, id=31827, stack(0x00007f7807577000,0x00007f7807678000)]
0x00007f8080009800 JavaThread "ThreadPool_0" [_thread_blocked, id=31824, stack(0x00007f7807779000,0x00007f780787a000)]
0x00007f8424261000 JavaThread "dubboConsumer-100.69.174.35:7101-thread-619" daemon [_thread_blocked, id=31816, stack(0x00007f7807476000,0x00007f7807577000)]
0x00007f80c0012800 JavaThread "ThreadPool_0" [_thread_blocked, id=31803, stack(0x00007f780797b000,0x00007f7807a7c000)]
0x00007f83fc09d000 JavaThread "dubboConsumer-100.69.112.55:7101-thread-621" daemon [_thread_blocked, id=31800, stack(0x00007f7807678000,0x00007f7807779000)]

　　基本的意思是说内存空间不足导致malloc系统调用失败，同时我们还发现打印出来的coredump时的java线程数以ThreadPool（原有名称替换为ThreadPool）开头的线程数有30000多个，然后定位到“ThreadPool”的线程池的使用位置，发现近期的改动是将ThreadPoolExecutor该成了二方库的ThreadPoolExecutor。当时改动的原因是使用二方库线程池会将flag传递到线程内，方便排查问题。在使用方式上没有改动，每一次调用创建一个线程池，异步处理多个任务，同步等待拿到处理任务结果，调用shutdown方法。

　　我们发现了发生coredump的基本原因是发生了内存泄露，声明的线程没有及时回收导致线程占用空间过大，查看java启动参数还没有配置-Xss（thread stack size），所以对于linux 64位系统，jvm默认设置线程栈大小位1M，所以就ThreadPool开头的线程就已经占用了30多G的空间，线上的物理内存为128G，一般占用90到100G，所以ThreadPool开头的线程直接导致内存耗尽，进程coredump。

　　在明确了coredump发生的原因后，还要确认为什么创建了那么多以ThreadPool开头的线程，在查看二方库的ThreadPoolExecutor的构造函数后一切真相大白了。二方库的ThreadPoolExecutor继承了jdk的ThreadPoolExecutor，二方库的ThreadPoolExecutor的构造函数初始化了父类线程池，同时也创建了一个定时调度线程池，用于统计该线程池内部使用线程数，空闲线程数，任务处理数等一些基本日志信息，而shutdown没有重新父类的shutdown方法，导致线程池释放的时候只释放了父类的，没有释放掉统计线程池，所以每一次接口调用都会增加一个线程，而这个接口调用量不大，线程数就会慢慢堆积知道内存耗尽。分布式调用框架使用了robin的方式也就是轮训，所以在单位时间内每一台机器上的接口调用次数差不多，创建的统计线程池也差不多，因此这四台机器也就在相近的时间先后dump，自此，本次coredump事故发生的前因后果都浮出了水面。

3、反思

　　本次事故是由多个因素导致的：

  1. 原有设计不合理，使用线程池应尽量声明为static，本身线程池除了利用他的并行性，还为了避免线程创建销毁的开销
  2. 修改代码时，是否为等价修改，还是需要多留个心眼，特别是公司二方库，往往实现上逻辑不完备，该重写shutdown方法没有重写

　　总之，程序员在日常工作开发过程中，还是要敬畏每一行代码，认真仔细，养成良好的编码习惯。

相关文章