故障出现时间和描述
前段时间下午3点左右,项目组某个系统出现问题,具体为机器无法登陆,报错catnot allocate memory,如下图所示:
先紧急启动备机,然后重启这台故障的的机器(由于无法登陆重启linux),重启应用解决,中间止血速度,且由于是封板期间,未造成生产故障。后续经排查,由于下面代码问题,导致每次部署请求,都会创建固定线程池,请求完毕,但是由于线程池未手工shutdown,导致每次请求都会创建固定线程池,最终导致的该问题。
故障复盘和分析
catnot allocate memory问题,初看以为是内存不足导致,但是由于我们的应用启动参数有 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/ -XX:ErrorFile=/data/logs/hs_err_pid%p.log,在oom情况下会生成oom文件,但是实际未生成,且最小最大堆内存是8g,基本排除了oom的情况。通过网上查询,catnot allocate memory除了内存不足导致这个问题外,还有就是线程数太高,也会导致该问题。
通过排查项目代码,发现下面这里,每次请求创建个固定线程池,这样系统运行一个多月,最终出现了这个问题。
解决办法:在请求结束对线程池进行shutdown操作,或者把线程池移保存到该bean的属性上。
最后通过查看日志,日志里面有大量的unable to create new native thread错误,这说明创建线程已经达到上限。
故障复现:
step1:
创建个demo应用,进行模拟,代码如下所示,每次请求创建个固定线程池,每次请求线程+10,
step2:
使用controller接收请求,使用jmeter进行压测
controller如下
jmeter配置如下:
直接在windows下启动jmeter进行压测即可,小测试不需要把jmeter放到linux了。
step3:
写个shell allocate.sh不断统计线程数,shell内容如下
#! /bin/bash
PID=`ps -fe | grep java | grep allocate-0.0.1-SNAPSHOT | grep -v grep | awk '{print $2}'`
log=~/allocate.`date +%Y%m%d'.'%H%M%S`.log
> $log
for i in {1..900000}
do
tasks=`ls /proc/$PID/task | wc -l`
echo "第$i次循环打印->`date +%Y-%m-%d'.'%H:%M:%S` --> $tasks" >> $log
sleep 3
done
备注:/proc/${PID}/task下面就是线程数
step4:
测试步骤:先启动应用,然后启动allocate.sh,最后使用jmeter进行压测,最终发现线程数达到7250后不再增加,查看demo应用,里面报错大量的java.lang.OutOfMemoryError: unable to create new native thread,和生产应用错误相同。
实际中,使用线程都是使用的线程池,但是线程池创建不当,比如我们这个项目,就会导致这样问题,这个问题不容易发现,且比较容易忽略。如果有监控,可以通过监控查看应用一周内的线程数是否一直在增加,我们对这个应用没有看监控习惯,这个习惯要改。如果没有监控,可以通过上面的shell输出线程数。
故障总结
1.出现故障,要有迅速止血的方案。通常是快速重启
2.经常查看监控,查看内存、cpu、线程、jvm内存、gc指标。监控默认通常是查询当天一段时间内的,要经常查看一周内的指标监控趋势,比如我们这个线程数一直增加问题,后面通过查看一周的监控,很容易就看到一直在增长,就会去解决,而非等到出了故障才发现。
3.我们这个应用这么久才发现这个问题的原因是由于快速迭代,半个月发版一次,线程数增长到上线3w多是很难的,这样问题产生也是由于没做压测导致。对于新应用,要做压测。
故障引发的思考,linux /proc学习
问题:生产上线程数达到了3w多是上线,但是测试环境应用启动线程数是7250,应用创建的线程数和什么有关系呢?
linux一切皆文件,内存信息也会映射到文件内,具体目录是/proc
用户和应用程序可以通过 /proc 得到系统的信息,并可以改变内核的某些参数。由于系统的信息,如进程,是动态改变的,所以用户或应用程序读取 /proc 文件时,/proc 文件系统是动态从系统内核读出所需信息并提交的。
/proc 下还有三个很重要的目录:net,scsi 和 sys。 sys 目录是可写的,可以通过它来访问或修改内核的参数,而 net 和 scsi 则依赖于内核配置。例如,如果系统不支持 scsi,则 scsi 目录不存在。
除了以上介绍的这些,还有的是一些以数字命名的目录,它们是进程目录。系统中当前运行的每一个进程都有对应的一个目录在 proc 下,以进程的 PID 号为目录名,它们是读取进程信息的接口。而 self 目录则是读取进程本身的信息接口,是一个 link。
/proc/sys/kernel 内核
/proc/sys/kernel/pid_max 系统最大pid值,在大型系统里可适当调大
/proc/sys/kernel/threads-max 系统允许的最大线程数
对应文件/etc/sysctl.conf,修改该文件永久生效。临时生效通过echo "32768" > /proc/sys/kernel/pid_max只改/proc/sys/kernel/xxx即可。
/proc/sys/net 网络
对于高并发的服务,经常会优化tcp参数,如果临时生效,可以直接修改这里
/proc/sys/net/ipv4/tcp_rmem 优化TCP接收
/proc/sys/net/ipv4/tcp_wmem 优化发送缓冲区
优化TCP协议栈
打开TCP SYN cookie选项,有助于保护服务器免受SyncFlood攻击。
net.ipv4.tcp_syncookies=1 对应/proc/sys/net/ipv4/tcp_syncookies
打开TIME-WAIT套接字重用功能,对于存在大量连接的Web服务器非常有效。
net.ipv4.tcp_tw_recyle=1 对应/proc/sys/net/ipv4/tcp_tw_recyle
net.ipv4.tcp_tw_reuse=1 对应/proc/sys/net/ipv4/tcp_tw_reuse
减少处于FIN-WAIT-2连接状态的时间,使系统可以处理更多的连接。
net.ipv4.tcp_fin_timeout=30 对应/proc/sys/net/ipv4/tcp_fin_timeout
减少TCP KeepAlive连接侦测的时间,使系统可以处理更多的连接。
net.ipv4.tcp_keepalive_time=1800 对应/proc/sys/net/ipv4/tcp_keepalive_time
增加TCP SYN队列长度,使系统可以处理更多的并发连接。
net.ipv4.tcp_max_syn_backlog=819200 对应/proc/sys/net/ipv4/tcp_max_syn_backlog
/proc/sys/scsi 磁盘
略,暂时不懂。
/proc/PID/ 进程状态
列举几个常用的
cmdline 显示应用的启动命令,比如java -jar xxx.jar,显示的就是完整命令java -jar xxx.jar
comm 显示启动的命令,比如java -jar xxx.jar方法启动,显示的命令就是java
cwd 链接,包含了当前进程工作目录的一个链,比如cwd -> /usr/local/devops/projects/allvms-restart-allocate/7c083dac,如下图所示
exe启动命令的链接,比如exe -> /usr/local/devops/tool/jdk/jdk1.8.0_73/bin/java
environ 包含了可用进程环境变量的列表
limits 文件句柄限制,如图所示,最大允许打开7259个句柄数
task,是个目录,下面是当前PID进程创建的线程,可以统计线程数。
fd 这个目录包含了进程打开的每一个文件的链接。
mem 包含了进程在内存中的内容。
stat 包含了进程的状态信息。
statm 包含了进程的内存使用信息。
应用可创建的线程数
由系统层面和用户层面决定。
系统层面:
参数/proc/sys/kernel/threads-max,有直接关系,每个进程中做多创建的的线程数目。用于指示整个系统可生成的最大线程数 参数/proc/sys/kernel/pid_max,有直接关系,系统中最多分配的pid数量。用于指定系统能够分配的PID的个数(即系统能够创建的最大进程个数) 参数/proc/sys/vm/max_map_count,数量越大,能够创建的线程数目越多,目前具体关系未明
通过echo临时设置:echo 204800 > /proc/sys/kernel/threads-max echo 204800 > /proc/sys/kernel/pid_max echo 204800 > /proc/sys/kernel/pid_max
永久修改
sysctl -w kernel.threads-max=2061206 修改最大线程数
sysctl -w kernel.pid_max=4194303 修改最大pid数
sysctl -w vm.max_map_count=4194303
用户层面:
可以通过修改/etc/security/limits.d/20-nproc.conf文件设置普通用户的线程数限制。注:/etc/security/limits.conf只是设置root用户
当前应用最大可开启的线程数通过/proc/PID/limits查看Max processes
jvm参数限制:
此外可以开启的最大线程数除了以上,还受到jvm参数设置,这个具体计算暂时不清楚。通常只需要linux不限制即可。
linux /var/log/message说明
/var/log/messages 存放的是系统的日志信息,它记录了各种事件,基本上什么应用都能往里写日志,在做故障诊断时可以首先查看该文件内容。在本次故障也参考了这个文件,文件格式说明如下
可以分为几个字段来描述这些事件信息:
1. 事件的日期和时间
2. 事件的来源主机
3. 产生这个事件的程序[进程号]
4. 实际的日志信息
如:Nov 9 15:00:10 JD salt-minion[6728]: [ERROR ] fork #1 failed: 12 ([Errno 12] Cannot allocate memory)
1. 产生这个事件的时间是:Nov 9 15:00:10
2. 事件的来源主机为:JD
3. 产生这个事件的程序和进程号为:salt-minion[6728]
4. 这个事件实际的日志信息为:[ERROR ] fork #1 failed: 12 ([Errno 12] Cannot allocate memory)