问题现象

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

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

  1. $du -sh *
  2. 248K core.170254
  3. 248K core.242719
  4. 248K core.31624

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

  1. #file core.170254
  2. 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时的调用栈:

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

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

  1. Program terminated with signal 3, Quit.

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

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

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

问题分析

问题1

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

  1. $cat cp.sh
  2. while true ; do
  3. cp -fr bigfile bigfile_copy
  4. sleep 1
  5. done

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

  1. $cat kill.sh
  2. while true ;
  3. do
  4. kill -3 `ps -ef |grep "cp -fr" |head -n 1 |awk -F' ' '{print $2}'`
  5. done

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

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

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

  1. ulimit -c unlimited

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

  1. $sh cp.sh
  2. cp.sh: line 7: 7222 Quit (core dumped) cp -fr bigfile bigfile_copy
  3. cp.sh: line 7: 7416 Quit (core dumped) cp -fr bigfile bigfile_copy
  4. cp.sh: line 7: 7605 Quit (core dumped) cp -fr bigfile bigfile_copy
  5. 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做如下设置:

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

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