数据库内核月报－ 2015 / 08-PgSQL · 答疑解惑 · 归档进程cp命令的core文件追查

最新推荐文章于 2022-02-22 17:20:45 发布

weixin_33804582

最新推荐文章于 2022-02-22 17:20:45 发布

阅读量191

点赞数

CC 4.0 BY-SA版权

文章标签：数据库操作系统 awk

原文链接：https://yq.aliyun.com/articles/50960

本文分析了PostgreSQL归档进程中由archiver进程产生的coredump文件的原因，并给出了相应的解决方案。核心问题是由于内存溢出导致的系统Kill操作，进而引发Postmaster发送SIGQUIT信号给子进程，最终导致cp命令进程产生core文件。

问题现象

最近我们的几个非生产实例中，均出现了由archiver进程产生的core dump文件，让人如临大敌：是不是遇到了PG的大BUG导致了crash？

先来看看这些core文件。由于我们在/proc/sys/kernel/core_pattern指定了存放core文件的目录，所以可以在这个目录里面找到这些core文件。幸运的是，这些core文件都不大，一般几百KB，没有对文件系统的存储空间造成压力：

$du -sh *
248K    core.170254
248K    core.242719
248K    core.31624

使用file命令，看一下core文件的基本信息：

#file core.170254
core.170254: ELF 64-bit LSB core file x86-64, version 1 (SYSV), SVR4-style, from 'cp pg_xlog/00000001000000410000006E /xxxx/yyy/zzz/00000001000'

可以看到，这些core文件由执行cp命令的进程产生，而且这个cp命令是在拷贝PG的xlog。因为我们设置了PG的archieve_command参数为’cp %f /xxx/yyy/zzz/%p’，所以判断这个执行cp命令的进程，应该是由归档进程调用，用于归档日志的。

根据我们以前的经验，crash一般是由于代码的Bug引起。难道系统的cp命令有Bug导致了core？

初步分析

我们用gdb看一下发生core dump时的调用栈：

$gdb postgres core.31624

Core was generated by `cp pg_xlog/000000010000004200000091 /xxx/yyy/zzz/00000001000'.
Program terminated with signal 3, Quit.
#0  0x0000003ed44da360 in ?? ()
Missing separate debuginfos, use: debuginfo-install glibc-2.12-1.80.2.alios6.x86_64
(gdb) bt
#0  0x0000003ed44da360 in ?? ()
#1  0x0000000000407df9 in ?? ()
#2  0x007da781c2f60000 in ?? ()
......

Oops，由于没有安装glibc的调试信息（debug info），看不到调用栈的函数名。但从上面的信息里面，我们得到了一个重要线索：

Program terminated with signal 3, Quit.

就是说cp命令在执行的过程中，收到一个编号为3的信号。查看文档，这个信号就是SIGQUIT。这儿有两个疑问：

为什么收到SIGQUIT后，会产生core文件？
为什么归档进程在调用cp命令进行日志归档时，会收到SIGQUIT信号？

下面我们以这两个问题为线索进行分析。

问题分析

问题1

先看第1个问题，我们使用简单的脚本模拟一下。用一个脚本，不断的拷贝文件，我们使用较大的文件，以使cp命令运行的时间足够长：

$cat cp.sh
while true ; do

cp -fr bigfile bigfile_copy

sleep 1

done

在上述脚本运行过程中，再用另一个脚本不断的向其发送SIGQUIT信号：

$cat kill.sh
while true ;
do

kill -3 `ps -ef |grep "cp -fr" |head -n 1 |awk -F' ' '{print $2}'`

done

注意，我们发送信号的目标进程必须是cp.sh进程的执行cp -fr命令的子进程，而不是cp.sh本身。这时，我们发现cp.sh的脚本收到了SIGQUIT信号：

cp.sh: line 7:  3683 Quit                    cp -fr /tmp/* /tmp2
cp.sh: line 7:  3879 Quit                    cp -fr /tmp/* /tmp2

但奇怪的是，系统的core目录并没用core文件产生。原来，Linux系统缺省的环境下，每个用户进程的core文件的size limit是0，需要显式增大size limit，才能打印出core文件。我们使用下面的命令，放开core文件的size limit：

ulimit -c unlimited

再次运行cp.sh和kill.sh，发现core file 产生了！

$sh cp.sh
cp.sh: line 7:  7222 Quit                    (core dumped) cp -fr bigfile bigfile_copy
cp.sh: line 7:  7416 Quit                    (core dumped) cp -fr bigfile bigfile_copy
cp.sh: line 7:  7605 Quit                    (core dumped) cp -fr bigfile bigfile_copy
cp.sh: line 7:  7798 Quit                    (core dumped) cp -fr bigfile bigfile_copy

看来，cp命令在收到SIGQUIT时，产生core文件是正常的。查阅文档和cp命令的源代码发现，原来，Linux下如果进程不对SIGQUIT信号做捕获（即不设置信号处理函数），进程在收到SIGQUIT的行为就是打印core文件并退出。

问题2

现在再看第2个问题，为什么cp命令的进程会收到SIGQUIT信号？是不是Postmaster发出的呢？

仔细查看系统日志记录（位于/var/log/messages），发现系统出现过OOM（Out of Memory) Kill事件。就是说，PG实例使用了过多的内存，把系统内存耗光后，Linux系统发出了kill -9信号给某些占用内存较多的子进程。子进程收到Kill -9信号后，就会无条件退出。而Linux内核在子进程退出时，会向其父进程，即PG的Postmaster主进程发送SIGCHILD信号。从PG代码可以看到，Postmaster在处理这些SIGCHILD信号时，如果发现子进程是被Kill -9杀掉的，则要用发信号的方式通知所有子进程退出（除了像sysloger这种非关键进程外）。这时Postmaster向子进程发生的退出信号就是SIGQUIT！所以我们高度怀疑cp命令收到的SIGQUIT正是Postmaster发出的。

但有个疑问是，产生core文件的cp命令进程，是归档进程利用syscmd函数新启动一个独立的子进程，所以其实它是Postmaster进程的“孙子”进程；而Postmaster只是像它直接的子进程发送了信号，信号是如何到达这个孙子进程的呢？

仔细查看代码发现，原来，PG代码里面fork一个子进程后，会建立一个子进程组(Process Group)，这个子进程fork出的进程，都会在这个进程组里面。向这个子进程发信号，组中所有进程都会收到。

结论与解决方案

自此，谜底揭开，core文件的产生原因可以总结为，发生OOM Kill时，PG主进程会向所有子进程和子进程所拥有的Process Group发送Kill -3信号；另一方面，归档进程会fork子进程来执行归档命令（即cp命令），此子进程在归档进程的Process Group里面，故也收到了Kill -3信号。而且该进程会对信号执行缺省动作即产生core文件。所产生的core文件为cp命令的core文件（一般300k左右，对系统影响不大）。

我们知道，如果我们设置core file的size limit为0，就会阻止core文件产生。而对于出问题的PG实例，我们是在pg_ctl启动进程时加入了-c选项，将core file 的size limit去除；而所有Postmaster的子进程和孙子进程，又继承了父进程的size limit，导致core file产生。所以，此问题的一个规避方法为，对archive_command做如下设置：

archive_command='ulimit -c 0 && cp %p /u01/tmp/%f'

这样在cp命令被归档进程调用时，其core file的size limit为0，即便收到SIGQUIT信号，也不会打印core dump file。