现象
最近报表解析告警群,频繁出现kafka堆积告警。
topic某个partition消费不动,其他partition消费正常,异常奇怪;同时消费者服务其中一个pod先挂掉,引发rebalance,导致其他pod也rebalance,同时挂掉;重启次数较多。
排查过程
- 本地解析该报表并没有复现该问题
- 拿到partition中提交的最近的offset,获取其消息内容;发现该消息内容中的报表数据比其他报表数据大十几倍;从而让运维同事增加pod的内存资源。512m -> 2G,然并软。(由于腾讯云上pod重启只能看到事件,无法实施观察到对应的输出日志;ELK只收集json格式日志)
- 联系运维同事,将deployment中启运行命令改为 tial -f 某个文件,先让deployment挂起。再进入到对应的pod,启动消费者;程序运行几分钟之后就被kill掉
处理方案
排查被kill的源头。
由于使用的python的docker基础镜像,debian系统 /var/log/message(日志)并没有该文件。
使用 strace
工具:用于跟踪进程执行时的系统调用和所接收的信号,用户空间进程和内核的交互,比如系统调用、信号传递、进程状态变更等。
安装 strace
apt update -y
apt install strace -y
运行 strace -p PID
命令,来追踪进程的系统调用蛛丝马迹。
显示结果如下:
16:02:19.192409 mprotect(0x7f4aa886b000, 552960, PROT_READ|PROT_WRITE) = 0 <0.000014>
16:02:19.744000 mmap(NULL, 552960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = -1 ENOMEM (Cannot allocate memory) <0.000108>
16:02:19.755545 mprotect(0x7f4aa88f2000, 552960, PROT_READ|PROT_WRITE) = 0 <0.000019>
16:02:23.404805 mmap(NULL, 552960, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0
16:02:25.325272 +++ killed by SIGKILL +++
[1]+ Killed python will_be_killed.py
KILLED信号对照表
信号 值 处理动作 发出信号的原因
----------------------------------------------------------------------
SIGHUP 1 A 终端挂起或者控制进程终止
SIGINT 2 A 键盘中断(如break键被按下)
SIGQUIT 3 C 键盘的退出键被按下
SIGILL 4 C 非法指令
SIGABRT 6 C 由abort(3)发出的退出指令
SIGFPE 8 C 浮点异常
SIGKILL 9 AEF Kill信号
SIGSEGV 11 C 无效的内存引用
SIGPIPE 13 A 管道破裂: 写一个没有读端口的管道
SIGALRM 14 A 由alarm(2)发出的信号
SIGTERM 15 A 终止信号
SIGUSR1 30,10,16 A 用户自定义信号1
SIGUSR2 31,12,17 A 用户自定义信号2
SIGCHLD 20,17,18 B 子进程结束信号
SIGCONT 19,18,25 进程继续(曾被停止的进程)
SIGSTOP 17,19,23 DEF 终止进程
SIGTSTP 18,20,24 D 控制终端(tty)上按下停止键
SIGTTIN 21,21,26 D 后台进程企图从控制终端读
SIGTTOU 22,22,27 D 后台进程企图从控制终端写
从结果可以看出该程序是被强制KILL了。
debian系统中,可以通过dmesg查看:dmesg -T | grep -E -i -B100 'killed process'
输出结果:
[月 12日 24 16:02:24 2022] [ pid ] uid tgid total_vm rss nr_ptes swapents oom_score_adj name
[月 12日 24 16:02:24 2022] [ 172] 0 172 10553 722 23 1375 0 systemd-journal
[月 12日 24 16:02:24 2022] [ 181] 0 181 10201 398 22 134 -1000 systemd-udevd
[月 12日 24 16:02:24 2022] [ 518] 0 518 8738 361 21 70 0 cron
[月 12日 24 16:02:24 2022] [ 519] 0 519 4756 314 13 45 0 atd
[月 12日 24 16:02:24 2022] [ 520] 0 520 13795 412 31 143 -1000 sshd
[月 12日 24 16:02:24 2022] [ 525] 0 525 4964 161 14 65 0 systemd-logind
[月 12日 24 16:02:24 2022] [ 536] 105 536 10531 172 26 98 -900 dbus-daemon
[月 12日 24 16:02:24 2022] [ 580] 0 580 1064 362 8 34 0 acpid
[月 12日 24 16:02:24 2022] [ 602] 0 602 4926 373 13 37 0 agetty
[月 12日 24 16:02:24 2022] [ 605] 0 605 4881 373 14 37 0 agetty
[月 12日 24 16:02:24 2022] [ 643] 108 643 8346 283 22 134 0 ntpd
[月 12日 24 16:02:24 2022] [ 889] 104 889 12794 369 26 158 0 exim4
[月 12日 24 16:02:24 2022] [11640] 0 11640 4188 1118 15 0 0 atop
[月 12日 24 16:02:24 2022] [29370] 0 29370 14434 420 30 177 0 sshd
[月 12日 24 16:02:24 2022] [29372] 3010 29372 14434 189 29 147 0 sshd
[月 12日 24 16:02:24 2022] [29373] 3010 29373 7813 491 20 587 0 bash
[月 12日 24 16:02:24 2022] [30731] 0 30731 14434 429 30 177 0 sshd
[月 12日 24 16:02:24 2022] [30733] 3010 30733 14434 328 29 154 0 sshd
[月 12日 24 16:02:24 2022] [30734] 3010 30734 7810 432 19 606 0 bash
[月 12日 24 16:02:24 2022] [30746] 3010 30746 13967 408 30 102 0 su
[月 12日 24 16:02:24 2022] [30747] 0 30747 7389 422 19 194 0 bash
[月 12日 24 16:02:24 2022] [31688] 0 31688 13967 408 31 101 0 su
[月 12日 24 16:02:24 2022] [31689] 3010 31689 7808 482 19 566 0 bash
[月 12日 24 16:02:24 2022] [32128] 3010 32128 7761 445 19 32 0 top
[月 12日 24 16:02:24 2022] [32132] 3010 32132 2357921 1868878 4581 467803 0 python
[月 12日 24 16:02:24 2022] [32133] 3010 32133 1255 152 7 57 0 strace
[月 12日 24 16:02:24 2022] Out of memory: Kill process 32132 (python) score 957 or sacrifice child
[月 12日 24 16:02:24 2022] Killed process 32132 (python) total-vm:9431684kB, anon-rss:7473936kB, file-rss:1576kB
结果很明显OOM了。简单粗暴:直接加内存即可;但后续需找出好内存的代码段,进行优化。