如何用GDB 排查 Python 程序故障

如何用GDB 排查 Python 程序故障，相信很多没有经验的人对此束手无策，为此本文总结了问题出现的原因和解决方法，通过这篇文章希望你能解决这个问题。

某Team在用Python开发一些代码，涉及子进程以及设法消除僵尸进程的需求。实践中他们碰上Python程序非预期退出的现象。最初他们决定 用GDB调试Python解释器，查看exit()的源头。我听了之后，觉得这个问题应该用别的调试思路。帮他们排查这次程序故障时，除去原始问题，还衍 生了其他问题。

为了简化现场、方便调试，已将原始问题、衍生问题浓缩成DebugPythonWithGDB_6.py、DebugPythonWithGDB_7.py。

$ vi DebugPythonWithGDB_6.py

PHP

#!/usr/bin/env python# -*- encoding: utf-8 -*-import sys, os, signal, subprocess, shlex, tracebackdef on_SIGCHLD ( signum, frame ) :print "[on_SIGCHLD"sys.stdout.write( "signum = %u\n" % signum )traceback.print_stack( frame )print os.waitpid( -1, os.WNOHANG )"""try :print os.waitpid( -1, os.WNOHANG )except OSError :sys.stdout.write( 'Line[%u]: OSError\n' % sys.exc_info()[2].tb_lineno )"""print "on_SIGCHLD]"def do_more ( count ) :print '[do_more() begin %u]' % countos.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )"""## 这里存在竞争条件，可以增加触发OSError异常的概率#os.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )os.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )os.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )os.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )"""print '[do_more() end %u]' % countdef main ( prog, args ) :if 0 == len( args ) :print 'Usage: %s ' % progelse :sys.stdout.write( "Parent = %u\n" % os.getpid() )## 本例中，即使有下列代码，Ctrl-C仍然无效。#signal.signal( signal.SIGINT, signal.SIG_DFL )## signal.signal( signal.SIGCHLD, signal.SIG_IGN )#signal.signal( signal.SIGCHLD, on_SIGCHLD )#count = 0while True :## 本例中父进程只是一个调度框架，不需要与子进程进行通信，因此不# 需要特别处理"stdin=None, stdout=None, stderr=None"。#child = subprocess.Popen \(## 不要直接用args[0].split()，它在处理单、双引号时不是我们# 期望的行为。考虑这种例子，ls -l "/tmp/non exist"#shlex.split( args[0] ),## all file descriptors except 0, 1 and 2 will be closed# before the child process is executed#close_fds = True,cwd = "/tmp")sys.stdout.write( "Child = %u\n" % child.pid )## child.send_signal( signal.SIGTERM )# child.terminate()#child.kill()## child.wait()#do_more( count )count += 1if '__main__' == __name__ :try :main( os.path.basename( sys.argv[0] ), sys.argv[1:] )except KeyboardInterrupt :pass

PHP

$ python DebugPythonWithGDB_6.py 'python -c "import time;time.sleep(3600)"'Parent = 10244Child = 10245[do_more() begin 0][on_SIGCHLDsignum = 17File "DebugPythonWithGDB_6.py", line 81, inmain( os.path.basename( sys.argv[0] ), sys.argv[1:] )File "DebugPythonWithGDB_6.py", line 76, in maindo_more( count )File "DebugPythonWithGDB_6.py", line 20, in do_moreprint '[do_more() begin %u]' % count(10245, 9)on_SIGCHLD]Child = 10246[on_SIGCHLDsignum = 17File "DebugPythonWithGDB_6.py", line 81, inmain( os.path.basename( sys.argv[0] ), sys.argv[1:] )File "DebugPythonWithGDB_6.py", line 76, in maindo_more( count )File "DebugPythonWithGDB_6.py", line 21, in do_moreos.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )Traceback (most recent call last):File "DebugPythonWithGDB_6.py", line 81, inmain( os.path.basename( sys.argv[0] ), sys.argv[1:] )File "DebugPythonWithGDB_6.py", line 76, in maindo_more( count )File "DebugPythonWithGDB_6.py", line 21, in do_moreos.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )File "DebugPythonWithGDB_6.py", line 10, in on_SIGCHLDprint os.waitpid( -1, os.WNOHANG )OSError: [Errno 10] No child processes

流程进入on_SIGCHLD()，但os.waitpid()抛出OSError异常。帮助里写的是，如果系统调用 waitpid()返回-1，就抛出异常: An OSError is raised with the value of errno when  the syscall returns -1. 10245号子进程在on_SIGCHLD()里waitpid()成功，(10245,  9)中的9表示该进程是被SIGKILL干掉的，符合预期。  10246号子进程是do_more()里的os.system()产生的shell进程，它结束时向10244号父进程投递了SIGCHLD信号。 on_SIGCHLD()里waitpid()时，已经在别处wait*()过，10246号子进程已经彻底消失，系统调用waitpid()返回 -1，Python函数os.waitpid()抛出异常。 整个过程非常复杂，用伪代码描述如下:

PHP

do_more()os.system()posix_system() // posixmodule.c__libc_system() // weak_alias (__libc_system, system)do_system() // sysdeps/posix/system.c/** SIG_IGN** Ctrl-C暂时失效*/sigaction( SIGINT, &sa, &intr )/** 屏蔽(阻塞)SIGCHLD信号*/sigaddset( &sa.sa_mask, SIGCHLD )sigprocmask( SIG_BLOCK, &sa.sa_mask, &omask )fork()子进程(10246号子进程)/** 恢复原有SIGINT信号处理方式*/sigaction( SIGINT, &intr, (struct sigaction *)NULL )/** 调用"sh -c ..."*/execve()[shell子进程结束，向DebugPythonWithGDB_6.py投递SIGCHLD][由于SIGCHLD信号已被屏蔽(阻塞)，其保持在内核态的未决信号链上]父进程(10244号父进程)/** 同步调用，会阻塞。不是在信号句柄中异步调用。** 10246号子进程在此被wait*()回收后彻底消失*/waitpid( pid, &status, 0 )/** 恢复原有SIGINT信号处理方式*/sigaction( SIGINT, &intr, (struct sigaction *)NULL )/** 取消对SIGCHLD的屏蔽(阻塞)*/sigprocmask( SIG_SETMASK, &omask, (sigset_t *)NULL )[SIGCHLD信号的屏蔽(阻塞)被取消][DebugPythonWithGDB_6.py的C级信号句柄signal_handler()安排"延迟调用"后返回][DebugPythonWithGDB_6.py的on_SIGCHLD()此时并未得到执行，因为built-in函数os.system()尚未返回]/** built-in函数os.system()返回后，10244号父进程开始处理"延迟调用"，调用* Python级信号句柄。这个SIGCHLD信号是10246号子进程投递过来的。** DebugPythonWithGDB_6.py的on_SIGCHLD()得到执行*/on_SIGCHLD()/** 调用waitpid( -1, &status, WNOHANG )，试图处理10246号子进程。** 10246号子进程已为前述waitpid( pid, &status, 0 )所处理，此处系统调用* 返回-1，导致os.waitpid()抛出OSError异常。*/os.waitpid( -1, os.WNOHANG )

整个过程之所以如此复杂，主要是因为Python的信号处理机制比较复杂，让已经非常复杂的Linux信号机制再添变数。参看:

PHP

《2.50 对Python解释器进行调试》《22.0 Linux信号机制》

就本例而言，为了确保DebugPythonWithGDB_6.py不因OSError异常而终止，只需在on_SIGCHLD()中调用os.waitpid()时捕捉OSError异常:

PHP

def on_SIGCHLD ( signum, frame ) :try :print os.waitpid( -1, os.WNOHANG )except OSError :sys.stdout.write( 'Line[%u]: OSError\n' % sys.exc_info()[2].tb_lineno )

前述观点有些是动态调试得到，有些是静态分析得到。有人可能问了，为什么不拦截Python进程的C级信号句柄，查看SIGCHLD 信号源，以此确认10246号子进程可能被回收两次？其实我最初也想这么干来着，但这是行不通的，因为Python的C级信号句柄 signal_handler()是那种最原始的单形参信号句柄，不是高大上的三形参信号句柄。 用GDB调试Python解释器:

PHP

# gdb -q -ex "b *signal_handler" -ex r --args /usr/bin/python2.7-dbg DebugPythonWithGDB_6.py '/usr/bin/python2.7-dbg -c "import time;time.sleep(3600)"'...Breakpoint 1 at 0x8216f2d: file ../Modules/signalmodule.c, line 185.Starting program: /usr/bin/python2.7-dbg DebugPythonWithGDB_6.py /usr/bin/python2.7-dbg\ -c\ \"import\ time\;time.sleep\(3600\)\"[Thread debugging using libthread_db enabled]Using host libthread_db library "/lib/i386-linux-gnu/i686/cmov/libthread_db.so.1".Parent = 10284Child = 10288[do_more() begin 0]Child = 10289Breakpoint 1, signal_handler (sig_num=17) at ../Modules/signalmodule.c:185185 {(gdb) py-bt#10 Frame 0xb7c20034, for file DebugPythonWithGDB_6.py, line 21, in do_more (count=0)os.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )#13 Frame 0xb7cb37dc, for file DebugPythonWithGDB_6.py, line 76, in main (prog='DebugPythonWithGDB_6.py', args=['/usr/bin/python2.7-dbg -c "import time;time.sleep(3600)"'], count=0, child=)do_more( count )#16 Frame 0xb7cbe49c, for file DebugPythonWithGDB_6.py, line 81, in ()main( os.path.basename( sys.argv[0] ), sys.argv[1:] )(gdb) bt 7#0 signal_handler (sig_num=17) at ../Modules/signalmodule.c:185#1#2 0xb7fdcd3c in __kernel_vsyscall ()#3 0xb7db25eb in __sigprocmask (how=how@entry=2, set=0x0, set@entry=0xbffff0d4, oset=oset@entry=0x0) at ../sysdeps/unix/sysv/linux/sigprocmask.c:57#4 0xb7dc2084 in do_system (line=line@entry=0xb7cbf9e4 "printf \"Child = %u\\n\" $$;/bin/sleep 1") at ../sysdeps/posix/system.c:161#5 0xb7dc2380 in __libc_system (line=line@entry=0xb7cbf9e4 "printf \"Child = %u\\n\" $$;/bin/sleep 1") at ../sysdeps/posix/system.c:184#6 0xb7fa9bfb in system (line=0xb7cbf9e4 "printf \"Child = %u\\n\" $$;/bin/sleep 1") at pt-system.c:28(More stack frames follow...)

查看#4的system.c:161，这个位置已经在waitpid( pid, &status, 0 )之后:  sigprocmask( SIG_SETMASK, &omask, (sigset_t *)NULL )  其作用是取消对SIGCHLD的屏蔽(阻塞)。 此时内存布局如下:

PHP

内存高址方向fpstate // ESP+0x2DC output/x *(struct _fpstate *)($esp+0x2dc)retcode // ESP+0x2D4 x/3i $esp+0x2d4extramask // ESP+0x2D0 x/1wx $esp+0x2d0fpstate_unused // ESP+0x60 output/x *(struct _fpstate *)($esp+0x60)sigcontext_ia32 // ESP+8 output/x *(struct sigcontext *)($esp+8)sig // ESP+4 信号值，信号句柄***形参pretcode // ESP RetAddr=__kernel_sigreturn// hexdump $esp 0x2dc内存低址方向

PHP

(gdb) x/2wa $esp0xbfffea6c: 0xb7fdcd18 0x11(gdb) x/3i $esp+0x2d40xbfffed40: pop eax0xbfffed41: mov eax,0x770xbfffed46: int 0x80(gdb) output/x *(struct sigcontext *)($esp+8){gs = 0x33,__gsh = 0x0,fs = 0x0,__fsh = 0x0,es = 0x7b,__esh = 0x0,ds = 0x7b,__dsh = 0x0,edi = 0xb7f2a000,esi = 0x8,ebp = 0x1,esp = 0xbfffeff0,ebx = 0x2,edx = 0x0,ecx = 0xbffff0d4,eax = 0x0,trapno = 0x1,err = 0x0,eip = 0xb7fdcd3c,cs = 0x73,__csh = 0x0,eflags = 0x246,esp_at_signal = 0xbfffeff0,ss = 0x7b,__ssh = 0x0,fpstate = 0xbfffed50,oldmask = 0x0,cr2 = 0x0}

因为是单形参信号句柄，没有siginfo，无法在用户态获知信号源。但我分析此时的信号源不是10289号子进程，而是10288 号子进程。10288产生SIGCHLD时，SIGCHLD信号已被屏蔽(阻塞)，只能保持在内核态的未决信号链上。之后待10289产生SIGCHLD 时，sigpending.signal中相应位已经置位，10289产生的SIGCHLD被丢弃，不会进入内核态的未决信号链。SIGCHLD信号的屏 蔽(阻塞)被取消后，从内核态的未决信号链上取出10288产生的SIGCHLD进行处理。于是断点***。  如果完全理解了前述实验结果及分析，就会发现DebugPythonWithGDB_6.py存在竞争条件。subprocess.Popen()对应的 子进程投递SIGCHLD信号时，父进程有两种可能:

PHP

1) os.system()调用sigprocmask( SIG_BLOCK, &sa.sa_mask, &omask )之前2) os.system()调用sigprocmask( SIG_BLOCK, &sa.sa_mask, &omask )之后

情况1)会触发OSError异常，情况2)不会触发OSError异常。执行: $ python  DebugPythonWithGDB_6.py ‘python -c “import time;time.sleep(3600)”‘  有时会因OSError异常而终止，有时就一直循环执行下去。出现这种差异，正是竞争环境的表征。 小结一下:  假设针对SIGCHLD安装了Python级信号句柄，其调用os.waitpid( -1, os.WNOHANG  )回收子进程。如果别处会调用os.system()，则必须在os.waitpid()外侧捕捉OSError异常。不建议这种方式的混用。  对waitpid()的分析到此就结束了，说点调试过程中出现的其他问题。 意外地发现Ctrl-C无法终止情况2)，而我已经调用:  signal.signal( signal.SIGINT, signal.SIG_DFL ) 这是因为do_system()中一上来就调用了:

PHP

sa.sa_handler = SIG_IGN;sigaction( SIGINT, &sa, &intr );

导致Ctrl-C暂时失效，直至do_system()结束。假设DebugPythonWithGDB_6.py已经出 现情况2)，查看它的信号处理方式:

PHP

# ps auwx | grep pythonroot 10355 0.0 0.5 8116 5812 pts/0 S+ 15:57 0:00 python DebugPythonWithGDB_6.py python -c "import time;time.sleep(3600)"root 10389 0.0 0.0 0 0 pts/0 Z+ 15:57 0:00 [python]root 10393 0.0 0.0 2936 852 pts/1 R+ 15:57 0:00 grep python# stap -DMAXACTION=10000 -g /usr/share/doc/systemtap-doc/examples/process/psig.stp -x 1035510355: pythonHUP defaultINT ignored // 不是预期的defaultQUIT ignoredILL defaultTRAP defaultABRT defaultBUS defaultFPE defaultKILL defaultUSR1 defaultSEGV defaultUSR2 defaultPIPE ignoredALRM defaultTERM defaultSTKFLT defaultCHLD blocked,caught 0x818a480 0...

上面显示SIGINT的处理方式是ignored，其实是ignored、default交叉出现，但我们 基本上不可能看到default。 $ vi DebugPythonWithGDB_7.py

PHP

#!/usr/bin/env python# -*- encoding: utf-8 -*-import sys, os, subprocess, shlex, tracebackdef do_more ( count ) :print '[do_more() begin %u]' % countos.system( r'printf "Child = %u\n" $$;/bin/sleep 1' )print '[do_more() end %u]' % countdef main ( prog, args ) :if 0 == len( args ) :print 'Usage: %s ' % progelse :sys.stdout.write( "Parent = %u\n" % os.getpid() )count = 0while True :child = subprocess.Popen \(shlex.split( args[0] ),close_fds = True,cwd = "/tmp")sys.stdout.write( "Child = %u\n" % child.pid )child.kill()do_more( count )count += 1if '__main__' == __name__ :try :main( os.path.basename( sys.argv[0] ), sys.argv[1:] )except KeyboardInterrupt :pass

$ python DebugPythonWithGDB_7.py ‘python -c “import time;time.sleep(3600)”‘ DebugPythonWithGDB_7.py没有显式调用wait()，它一直循环执行下去。我以为subprocess.Popen()会生成一堆僵尸进程。从另一个终端查看相关进程，发现始终只有一个僵尸进程，很快就被回收了。这个现象挺奇特，只能假设有隐式wait()存在。

PHP

# gdb -q -ex "b *waitpid" -ex r --args /usr/bin/python2.7-dbg DebugPythonWithGDB_7.py '/usr/bin/python2.7-dbg -c "import time;time.sleep(3600)"'...Parent = 14508Child = 14512[do_more() begin 0]Child = 14513[do_more() end 0]Breakpoint 1, waitpid () at ../sysdeps/unix/syscall-template.S:8181 T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)(gdb) py-bt#4 Frame 0xb7c21034, for file /usr/lib/python2.7/subprocess.py, line 1363, in _internal_poll (self=, _deadstate=2147483647, _waitpid=, _WNOHANG=1, _os_error=, _ECHILD=10)pid, sts = _waitpid(self.pid, _WNOHANG)#8 Frame 0xb7c6549c, for file /usr/lib/python2.7/subprocess.py, line 762, in __del__ (self=, _maxint=2147483647)self._internal_poll(_deadstate=_maxint)#18 Frame 0xb7cb37dc, for file DebugPythonWithGDB_7.py, line 22, in main (prog='DebugPythonWithGDB_7.py', args=['/usr/bin/python2.7-dbg -c "import time;time.sleep(3600)"'], count=1, child=)cwd = "/tmp"#21 Frame 0xb7cbe49c, for file DebugPythonWithGDB_7.py, line 31, in ()main( os.path.basename( sys.argv[0] ), sys.argv[1:] )(gdb) bt 9#0 waitpid () at ../sysdeps/unix/syscall-template.S:81#1 0x081f80a3 in posix_waitpid (self=0x0, args=(14512, 1)) at ../Modules/posixmodule.c:6207#2 0x080bc300 in PyCFunction_Call (func=, arg=(14512, 1), kw=0x0) at ../Objects/methodobject.c:81#3 0x08149d0b in call_function (pp_stack=0xbfffebd4, oparg=2) at ../Python/ceval.c:4033#4 0x081454ec in PyEval_EvalFrameEx (f=Frame 0xb7c21034, for file /usr/lib/python2.7/subprocess.py, line 1363, in _internal_poll (self=, _deadstate=2147483647, _waitpid=, _WNOHANG=1, _os_error=, _ECHILD=10), throwflag=0) at ../Python/ceval.c:2679#5 0x08147a77 in PyEval_EvalCodeEx (co=0xb7c60448, globals={'STDOUT': -2, '_has_poll': True, 'gc': , 'check_call': , 'mswindows': False, 'select': , 'list2cmdline': , '__all__': ['Popen', 'PIPE', 'STDOUT', 'call', 'check_call', 'check_output', 'CalledProcessError'], 'errno': , '_demo_posix': , '__package__': None, 'PIPE': -1, '_cleanup': , '_eintr_retry_call': , 'call': , '__doc__': 'subprocess - Subprocesses with accessible I/O streams\n\nThis module allows you to spawn processes, connect to their\ninput/output/error pipes, and obtain their return codes. This module\nintends to replace several older modules and functions:\n\nos.system\nos.spawn*\nos.popen*\npopen2.*\ncommands.*\n\nInformation about how the subprocess module can be used to replace these\nmodules and functions can be found below.\n\...(truncated), locals=0x0, args=0xb7c655e4, argcount=1, kws=0xb7c655e8, kwcount=1, defs=0xb7c73a20, defcount=5, closure=0x0) at ../Python/ceval.c:3265#6 0x0814a1e5 in fast_function (func=, pp_stack=0xbfffeef4, n=3, na=1, nk=1) at ../Python/ceval.c:4129#7 0x08149e93 in call_function (pp_stack=0xbfffeef4, oparg=256) at ../Python/ceval.c:4054#8 0x081454ec in PyEval_EvalFrameEx (f=Frame 0xb7c6549c, for file /usr/lib/python2.7/subprocess.py, line 762, in __del__ (self=, _maxint=2147483647), throwflag=0) at ../Python/ceval.c:2679(More stack frames follow...)

调用栈回溯表明:

查看: /usr/lib/python2.7/subprocess.py:1363

PHP

try :_waitpid( self.pid, _WNOHANG )...except _os_error as e :...if e.errno == _ECHILD :## This happens if SIGCLD is set to be ignored or waiting for child# processes has otherwise been disabled for our process. This# child is dead, we can't get the status.## http://bugs.python.org/issue15756#...

考虑这种情形，调用subprocess.Popen()之前做过如下动作之一:

PHP

signal.signal( signal.SIGCHLD, signal.SIG_IGN )signal.signal( signal.SIGCHLD, on_SIGCHLD )

_internal_poll()调用_waitpid()时，在外侧捕捉了_os_error异常，就是对付上述可能。 subprocess.Popen()不是built-in函数，对应很多条PVM指令，不像os.system()是built-in函数，对应单条 PVM指令。前者执行过程中，Python级信号句柄on_SIGCHLD()有很大机会得到执行，_internal_poll()调用 _waitpid()，遭遇_os_error异常的可能性不低。  Popen()对象的析构函数自动调用wait*()，于是Popen()对象离开作用域时自动回收子进程。  Python能够改变变量作用域的是def、class、lamda、global。下面这些并不涉及作用域变更:

PHP

if/elif/elsetry/except/finallyfor/while

DebugPythonWithGDB_7.py中Popen()对象的作用域是main()。尽管没有离开作用域，但对child 变量的重新赋值会触发对前一个Popen()对象的析构。这就解释了为什么始终只有一个僵尸进程。  回顾原始问题与衍生问题，再次表明，掌握对Python解释器的调试技术可以快速排查众多看似神秘实则基础的程序故障。

看完上述内容，你们掌握如何用GDB 排查 Python 程序故障的方法了吗？如果还想学到更多技能或想了解更多相关内容，欢迎关注亿速云行业资讯频道，感谢各位的阅读！