Python 代码调试二三事
王维栋
王维栋，网易游戏运维与基础架构部，产品软件设计师，专注于智能监控、性能优化等领域。
前言
借着机器学习的东风，Python 近年来大热，一举冲入最受欢迎编程语言榜前三。同时，Python 已经在 Web、运维、科学计算、游戏等领域广泛应用，很多人使用它来构建原型、实现周边模块、做实验、写性能要求不高的业务逻辑、作为胶水语言完成系统串联，亦有不少公司使用 Python 来开发大型应用。
如今，拿 Python 写的代码越来越多，有代码的地方就有 bug。虽然 bug free 是我们的追求，但有时面对复杂需求、大型系统，我们不得不接受一个事实：我们可能要花一半时间写 bug，再花另一半时间把它们调试好。代码调试占了如此高的工作比重，那么提升它的效率就是一个很有意义的话题了。
Python 是一种强类型动态语言，具有非常活跃的社区和海量的库。所以，我们在使用传统的代码调试方法的同时，还多了一些额外的选择。接下来的章节中我会介绍一些常见的调试方法和 Python 特有的技巧，并分享一些调试的经验。
Print & Logging
Print 和 logging 可以在代码运行过程中暴露出一些变量的值、打印出关键信息，帮助我们观察和跟踪代码的执行过程。
Print Print Print
作为 script programmer，我们在调试时的第一反应是 print here, print there, print everywhere 在写小脚本的时候这样做完全没问题，但当我们开始构建比较复杂的业务模块的时候，print 的问题就显现出来了，格式随意、缺乏时间戳等必要信息、通常只 print 到 stdout，写其他的流或者文件还需要额外的代码。最关键的一点是：看起来一点都不专业。下面是一个简单的例子：
try:
1 / 0
except ZeroDivisionError as e:
print("some text", e)
with open("some.log", 'w') as f:
print("some text", e, file=f)
Logging 的实践与价值
Logging 是比 Print 更规范和「专业」的做法，下面罗列一些 logging 的好处和个人觉得比较有用的实践：
规范格式
我们可以定义好日志的规范格式，包含必要信息，并且有利于后续的日志处理和分析。如下是使用 logging.Formatter 格式化日志的例子：
LOG_FORMAT = '%(asctime)s %(levelname) 8s: [%(filename)s:%(lineno)d] [%(processName)s:%(process)d %(threadName)s] - %(message)s'
DATE_FORMAT = '[%Y-%m-%d %H:%M:%S]'
def get_logger(name):
logger = logging.getLogger(name)
formatter = logging.Formatter(LOG_FORMAT, DATE_FORMAT)
handler = logging.StreamHandler(sys.stdout)
handler.setFormatter(formatter)
logger.addHandler(handler)
return logger
logger = get_logger(__name__)
logger.warning("test msg")
得到这样的日志输出：
[2019-01-09 13:36:26] WARNING: [test1.py:33] [MainProcess:16830 MainThread] - test msg
如果想让日志更易处理，更有表现力，可以尝试结构化的日志，一个使用 logging.Filter 结构化日志的例子：
import json
class JsonLogFilter(logging.Filter):
def filter(self, log):
if isinstance(log.msg, str):
return True
if isinstance(log.msg, (dict, list, tuple)):
log.msg = json.dumps(log.msg)
return True
return False
logger.addFilter(JsonLogFilter())
logger.warning({
"action": "server_start",
"port": 8080,
"engine": {"name": "tornado", "version": "0.1.1"}
})
得到这样的日志输出：
[2019-01-09 13:46:01] WARNING: [test1.py:57] [MainProcess:17549 MainThread] - {"action": "server_start", "port": 8080, "engine": {"name": "tornado", "version": "0.1.1"}}
这样的日志可以很清晰地携带大量信息，后续的日志解析和处理也更方便。
分级
logging 可以定义消息等级，常见的等级：
我们可以通过 logger 的同名成员函数来输出不同等级的日志，设置 logger 或者 logHandler 的 level，来决定什么级别的日志会被输出：
logger.setLevel(logging.ERROR)
stdLogHandler.setLevel(logging.INFO)
这些工作会在后续的日志处理中产生价值，一些实践例子：
把 Error 和 Critical 的日志输出到单独的 Error log 文件，查问题时优先关注它们；
把 Error 和 Critical 日志直接流入报警系统、故障自愈系统等，触发对应策略；
业务发布时关掉 Debug 日志，在排查问题时通过外部配置、RPC 等方式触发进程修改日志等级；
排查问题时，启动一个新的进程，指定 Debug level 的日志，输出 Debug log 来辅助排查；
多种输出流
logging 模块提供了文件、标准输出等多种 logHandler，我们也可以自定义自己的 handler，让日志输出到不同的流。
logger 也可以添加多个 logHandler，并且分别定义 Formatter、Level，让日志同时以不同的方式输出到多个流。
按模块管理
每个 logger 初始化的时候都可以指定名字，我们通常会以模块名作为 logger name，方便后续的管理和日志使用。
例如，我们同时使用了 requests 和 kafka，但我们比较关注 kafka 的日志，requests 只有在 error 的时候才值得关注，可以这样配置：
logging.getLogger('requests').setLevel(logging.ERROR)
logging.getLogger("kafka").setLevel(logging.WARNING)
Logging 准则
通过以上的的介绍，我们已经可以自如地定制日志的输出了，那么什么时候应该输出日志呢？日志太多会影响性能，造成不必要的干扰，难以阅读，日志太少会让我们对进程的执行情况缺乏了解。在实践中，我们应该在生产环境尽可能取得二者平衡。
这里有一些建议：
确保每一次日志输出都是有价值、无歧义、易读的；
Debug 日志尽可能详尽地输出细节信息，例如关键函数的调用、输入、输出，某些关键分支步骤的选择等，在生产环境中关闭，必要时再打开；
一些重要变量的变更、重要函数的调用应该尽量输出日志；
做一些周期性指标统计并通过日志等方式输出，以备监控报警和观察执行情况，例如 QPS、数据吞吐量、任务堆积数等；
CRUD 中的 Create、Update、Delete 通常需要输出 Info log，用作资源操作记录；
对一些可以发生，但大量发生代表可能有严重问题的代码分支，最好输出 Warning 日志，并在后续日志报警中按数量报警，例如：缓存未命中，RPC Retry 等；
可自动恢复的异常通常至少要输出 Warning 日志；
不可恢复的异常视逻辑严重程度输出 Error 或者 Critical 日志，并且要带上堆栈和必要的变量信息；
微服务系统中，确保每条日志都带上可追踪的 session ID；
不要在频繁调用的函数中输出 Info 及以上级别的日志，如果真的需要，可以考虑周期统计输出，或者采样输出；
IDE Debugger
无意挑起 IDE 和编辑器之争，但现代的 IDE 确实提供了更便捷更强大的 Debug 功能，这些功能通常需要我们这些 vim、sublime、emacs 爱好者花费额外的时间才能得到。
对广大 IDE 使用者来说，最便捷的离线调试方法显然就是 IDE Debugger 了，我们以 PyCharm 为例简单介绍下。
PyCharm Debugger 提供了一系列常见的功能：
断点；
step in/out， step over 等操作；
Variables 窗口，查看当前 scope 内的变量，也可以自己添加 Watches；
Frames 窗口，可以切换线程，查看线程的 Frames 链；
Evaluate 窗口，可以直接计算表达式值；
Attach 到已运行的进程，并开启 Debugger；
GDB 系列调试器
仍然有大量程序员是 GDB、PDB、IPDB 系列 Debugger 的用户，这些工具同样能在代码调试过程中产生帮助，以 ipdb（Ipython pdb）为例。
IPDB 调试代码
我们可以直接加载 ipdb，启动进程：
➜ test python3 -m ipdb run.py
> /Users/Valens/PycharmProjects/test/run.py(1)<module>()
----> 1 import time
2 import logging
3 import random
ipdb> r
WARNING:root:handling a big value: 0.8740442611857767
> /Users/Valens/PycharmProjects/test/run.py(18)handle()
17 set_trace()
---> 18 self._last_big_value = data["value"]
19 self._counter += 1
ipdb> p data
{'value': 0.8740442611857767, 'done': True}
ipdb> n
> /Users/Valens/PycharmProjects/test/run.py(19)handle()
18 self._last_big_value = data["value"]
---> 19 self._counter += 1
20 return data
也可以在代码中设置断点，并在断点处停下来，启动 i
Python debugger：
import time
import logging
import random
from ipdb import set_trace
class Processor(object):
def __init__(self):
self._counter = 0
self._last_big_value = float("inf")
def handle(self, data):
data['done'] = True
if data["value"] > 0.8:
logging.warning("handling a big value: %s" % data["value"])
set_trace() # 断点
self._last_big_value = data["value"]
self._counter += 1
return data
def feed(processor):
while True:
time.sleep(random.random())
processor.handle({
"value": random.random()
})
def main():
feed(Processor())
if __name__ == "__main__":
main()
然后执行
➜ test python3 run.py
WARNING:root:handling a big value: 0.844438382990963
> /Users/Valens/PycharmProjects/test/run.py(18)handle()
17 set_trace()
---> 18 self._last_big_value = data["value"]
19 self._counter += 1
ipdb> p data
{'value': 0.844438382990963, 'done': True}
GDB 调试 COREDUMP
GDB 是老牌且功能强大的 Debugger，在后起之秀更加易用的今天，它出场的机会不算多。但当线上进程 Coredump 时，我们的选择并不多，这时候 GDB 的强大之处就显现出来了。
使用 GDB 调试 Python，首先需要准备好必要的包：
libpython 让 GDB 可以调试 Python 代码，包含 py_bt py_print py_up py_down 等一系列 GDB 命令的Python 版本；
python-dbg python debug 扩展，包括 Python 符号文件和 libpython 等工具，在不同发行版的包名可能不一样；
如果你用到了一些 c 扩展的 Python 库，需要解与之相关的栈，可能也需要对应的 dbg 包，例如 python-mysqldb-dbg
通常，如果我们知道一个 Python 进程会 core dump，那可以选择用 python-dbg 运行它（当然会有少量性能的 trade off），等待它 core dump 后，再用 gdb 打开会获得最全面的信息。非 dbg 运行的 Python core dump 也可以如此尝试，但可能因为符号表缺失、版本不一致等原因损失一些信息。
我们准备一个测试，还是刚才熟悉的代码，在 random 数字大于 0.9 时触发一段「神秘代码」，Python 2.7 下的经典 stack overflow bug，让进程因为 Seg Fault 而被内核 core dump 掉。
import time
import logging
import random
class Processor(object):
def __init__(self):
self._counter = 0
self._last_big_value = float("inf")
def handle(self, data):
data['done'] = True
if data["value"] > 0.8:
logging.warning("handling a big value: %s" % data["value"])
self._last_big_value = data["value"]
if data["value"] > 0.9:
raise_seg_fault()
self._counter += 1
return data
def raise_seg_fault():
logging.error("seg fault")
exec'()'*7**6
def feed(processor):
while True:
time.sleep(random.random())
processor.handle({
"value": random.random()
})
def main():
feed(Processor())
if __name__ == "__main__":
main()
跑起~
valens@some-host:~$ python-dbg run.py
WARNING:root:handling a big value: 0.860424864923
WARNING:root:handling a big value: 0.94984309816
ERROR:root:seg fault
Segmentation fault (core dumped)
然后用 gdb 打开 core dump 文件，指定 exec 为 python-dbg
valens@some-host:~$ gdb python-dbg core.python-dbg.some-host.28249
GNU gdb (Debian 7.7.1+dfsg-5) 7.7.1
...
Reading symbols from python-dbg...done.
[New LWP 28249]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `python-dbg run.py`.
Program terminated with signal SIGSEGV, Segmentation fault.
#0 0x0000000000563415 in symtable_visit_expr (st=<error reading variable: Cannot access memory at address 0x7ffdc1083fe8>, e=<error reading variable: Cannot access memory at address 0x7ffdc1083fe0>) at ../Python/symtable.c:1185
跟踪 c 栈
(gdb) bt
#0 0x0000000000563415 in symtable_visit_expr (st=<error reading variable: Cannot access memory at address 0x7ffdc1083fe8>, e=<error reading variable: Cannot access memory at address 0x7ffdc1083fe0>) at ../Python/symtable.c:1185
#1 0x0000000000563bde in symtable_visit_expr (st=0x7f3fe9b00110, e=0x20f8150) at ../Python/symtable.c:1256
跟踪 py 栈和变量
# 列出py栈
(gdb) py-bt
#32710 Frame 0x7f3fe9b17248, for file run.py, line 25, in raise_seg_fault ()
exec'()'*7**6
#32714 Frame 0x7f3fe9b33c60, for file run.py, line 18, in handle (self=<Processor(_counter=19, _last_big_value=<float at remote 0x1b7e620>) at remote 0x7f3fe9b0ba00>, data={'done': True, 'value': <float at remote 0x1b7e620>})
raise_seg_fault()
#32717 Frame 0x7f3fe9aef840, for file run.py, line 32, in feed (processor=<Processor(_counter=19, _last_big_value=<float at remote 0x1b7e620>) at remote 0x7f3fe9b0ba00>)
"value": random.random()
#32720 Frame 0x7f3fe9b887e0, for file run.py, line 37, in main ()
feed(Processor())
#32723 Frame 0x7f3feb29f060, for file run.py, line 41, in <module> ()
main()
# 向上回到frame: handle
(gdb) py-up
#32714 Frame 0x7f3fe9b33c60, for file run.py, line 18, in handle (self=<Processor(_counter=19, _last_big_value=<float at remote 0x1b7e620>) at remote 0x7f3fe9b0ba00>, data={'done': True, 'value': <float at remote 0x1b7e620>})
# 查看这个frame的局部变量
(gdb) py-locals
self = <Processor(_counter=19, _last_big_value=<float at remote 0x1b7e620>) at remote 0x7f3fe9b0ba00>
data = {'done': True, 'value': <float at remote 0x1b7e620>}
# 读一下value
(gdb) p *(PyFloatObject*) 0x1b7e620
$3 = {_ob_next = 0x7f3fe9b10d30, _ob_prev = 0x7f3fe9b33c60, ob_refcnt = 2, ob_type = 0x8b7580 <PyFloat_Type>, ob_fval = 0.94984309816000645}
通过查看 py 栈和 c 栈的调用关系和变量值，大部分的问题都应该能定位了～
Tracers
线上的情况经常是错综复杂的，我们也没办法在写代码和测试阶段就完全预测代码的每一步执行和每个分支。当线上业务出问题通常都会有点难以下手。其实很多 Linux 工具都可以在这时候提供帮助。当然，不仅限于看看 CPU 内存消耗、查查网络链接和 fd 那么简单，这里以 Perf 和 strace 做简单举例，如果大家觉得有用，可以更深入地学习具体用法。
Perf 追踪性能
Perf 是 Linux 下一个非常好用的性能 Profile 工具。在日常用来进行性能优化以外，我们也可以在用它来排查一些线上的问题，当一个数据处理进程消费速度减慢，或者一个 server CPU 暴增时，不妨 Perf 一下，看看进程现在在干嘛，为我们排查和推断问题原因提供依据。
举例：
# perf 进程 6252 10秒，采集call graph信息
perf record -g -p 6252 sleep 10
perf report --stdio
...
89.67% 3.54% python-dbg python2.7-dbg [.] call_function
|
--- call_function
|
|--99.80%-- PyEval_EvalFrameEx
| |
| |--73.81%-- fast_function
| | call_function
| | PyEval_EvalFrameEx
| | |
| | |--72.77%-- fast_function
| | | call_function
| | | PyEval_EvalFrameEx
| | | |
| | | |--54.21%-- fast_function
| | | | call_function
| | | | PyEval_EvalFrameEx
| | | | |
| | | | |--62.17%-- fast_function
| | | | | call_function
| | | | | PyEval_EvalFrameEx
| | | | | |
| | | | | |--56.99%-- fast_function
| | | | | | call_function
| | | | | | PyEval_EvalFrameEx
...
perf report --stdio -g none
# Samples: 3K of event 'cpu-clock'
# Event count (approx.): 839500000
#
# Children Self Command Shared Object Symbol
# ........ ........ .......... .................. .....................................
#
89.67% 0.00% python-dbg libc-2.19.so [.] __libc_start_main
89.67% 0.00% python-dbg python2.7-dbg [.] main
89.67% 0.00% python-dbg python2.7-dbg [.] Py_Main
89.67% 0.00% python-dbg python2.7-dbg [.] PyRun_AnyFileExFlags
89.67% 0.00% python-dbg python2.7-dbg [.] PyRun_SimpleFileExFlags
89.67% 0.00% python-dbg python2.7-dbg [.] PyRun_FileExFlags
89.67% 0.00% python-dbg python2.7-dbg [.] run_mod
89.67% 0.00% python-dbg python2.7-dbg [.] PyEval_EvalCode
89.67% 3.54% python-dbg python2.7-dbg [.] call_function
89.67% 1.28% python-dbg python2.7-dbg [.] fast_function
89.67% 0.95% python-dbg python2.7-dbg [.] PyEval_EvalCodeEx
89.67% 14.80% python-dbg python2.7-dbg [.] PyEval_EvalFrameEx
57.89% 0.09% python-dbg python2.7-dbg [.] ext_do_call
57.74% 0.33% python-dbg python2.7-dbg [.] PyObject_Call
57.65% 0.24% python-dbg python2.7-dbg [.] function_call
19.15% 0.03% python-dbg python2.7-dbg [.] do_call
18.82% 0.06% python-dbg python2.7-dbg [.] type_call
18.55% 0.21% python-dbg python2.7-dbg [.] slot_tp_init
18.20% 0.09% python-dbg python2.7-dbg [.] instancemethod_call
15.78% 1.94% python-dbg python2.7-dbg [.] PyObject_GetAttr
13.94% 0.12% python-dbg python2.7-dbg [.] PyObject_GenericGetAttr
...
Strace 追踪系统调用
有时我们会遇到进程阻塞，这时候可以通过 strace 来追踪系统调用看看进程是不是卡在某处 IO，或者在接收巨量的网络包，以及其他跟系统调用、信号相关的场景。
举例：
# strace -p 1227
Process 1227 attached
select(0, NULL, NULL, NULL, {0, 524306}) = 0 (Timeout)
gettimeofday({1547026076, 550492}, NULL) = 0
write(2, "WARNING:root:handling a big valu"..., 50) = 50
select(0, NULL, NULL, NULL, {0, 195142}) = 0 (Timeout)
Inject Debugger
深究代码调试的本质，是观察代码执行，从中找出不合理的逻辑、未处理的边界情况以及可优化的地方。那么，没有什么比直接进入正在执行的 Python 进程并近距离观察和把玩它的逻辑更方便的了。作为一个动态语言，Python 在 Debug On-the-fly 方面具有非常大的想象空间。
这里夹带私货地介绍一个 Python Inject Debugger：pylane
pylane 通过 gdb trace python 进程，然后在该进程的 python vm 中动态地注入一段 Python 代码，从而对一个运行中的 Python 进程执行一段任意的新逻辑。
作为 Debugger，pylane 最常用的功能是 pylane shell，它对目标进程注入了一个新线程，并在这个线程中启动一个 Python Interpreter，然后连接到终端的 IPython Console。接下来，我们就可以在这个 Console 中访问目标进程中的所有对象。
继续使用上文中的 Processor 代码，用 pylane shell attach 它。
pylane shell <PID>
接下来举几个典型的用例。
友情提醒，在生产环境做任何非规范的变更都有危险，请三思。
查看变量
如果我们需要看到某个内部变量的值，但这个变量没有通过 log 等方式暴露出来，那就可以用 pylane 来直接查看。
pylane shell 4996
# 用内置tools的get_insts方法获取Processor的实例
In [2]: p = tools.get_insts("Processor")[0]
In [3]: p
Out[3]:
<__main__.Processor object at 0x7f3d45c6ad68>
# 在代码运行的同时观察p的属性变化
In [4]: p._counter
Out[4]: 252
In [5]: p._counter
Out[5]: 262
In [6]: p._last_big_value
Out[6]: 0.8872528770214453
查看代码
在源文件存在的情况下，可以直接查看某个 object 的代码。
In [2]: tools.print_source_code(tools.get_classes("Processor")[0])
Out[2]:
class Processor(object):
def __init__(self):
self._counter = 0
self._last_big_value = float("inf")
def handle(self, data):
data['done'] = True
if data["value"] > 0.8:
logging.warning("handling a big value: %s" % data["value"])
self._last_big_value = data["value"]
self._counter += 1
return data
触发函数调用
如果需要调用一次函数，触发某段逻辑，也可以直接调用。
In [4]: p = tools.get_insts("Processor")[0]
In [5]: p.handle({"value": -100})
Out[5]: {'done': True, 'value': -100}
打印线程栈和变量
我们有时会想知道进程目前在干什么，比如任务执行的很慢，进程完全阻塞了的情况。
执行下面的方法打印所有线程的栈和变量：
In [6]: tools.print_threads()
Out[6]:
Thread: MainThread
Stack:
File "/usr/lib/python2.7/threading.py", line 1098, in _exitfunc
t.join()
File "/usr/lib/python2.7/threading.py", line 940, in join
self.__block.wait()
File "/usr/lib/python2.7/threading.py", line 340, in wait
waiter.acquire()
Locals:
{'saved_state': None, 'waiter': <thread.lock object at 0x7fc7c9d062d0>, 'self': <Condition(<thread.lock object at 0x7fc7c9d06290>, 1)>, 'timeout': None}
或者，如果我们知道线程名，可以这样指定：
tools.print_threads(["Thread1", "Thread2"])
排查内存泄露
objgraph 是一个非常好用的 Python 内存排查工具，但它需要入侵代码，如果线上有一个难以复现的内存泄露，用 pylane + objgraph 可以更容易地排查：
先在跑服务的 virtual env 中准备好 objgraph 包，然后打开 pylane shell
In [5]: import objgraph
In [6]: objgraph.growth()
Out[6]:
[('function', 1484, 1484),
('wrapper_descriptor', 1105, 1105),
('builtin_function_or_method', 732, 732),
('method_descriptor', 590, 590),
('dict', 581, 581),
('tuple', 529, 529),
('weakref', 509, 509),
('list', 267, 267),
('getset_descriptor', 234, 234),
('member_descriptor', 229, 229)]
In [7]: objgraph.growth()
Out[7]: [('list', 268, 1)]
修改代码逻辑
如果遇到某个调用比较深的函数执行有问题，我们想知道它每次执行了多久，输入输出是什么，但是之前没有 log 出来，可以 monkey patch 它。
In [2]: p = tools.get_insts("Processor")[0]
In [3]: origin_func, p.handle = p.handle, tools.log_it(p.handle)
接下来可以看到新的 log 了
WARNING:root:handling a big value: 0.821825815755
WARNING:root:func: handle sec_cost: 0.0002 input: (({'done': True, 'value': 0.8218258157546575},), {}) output {'done': True, 'value': 0.8218258157546575}
WARNING:root:func: handle sec_cost: 0.0003 input: (({'done': True, 'value': 0.5901812673170566},), {}) output {'done': True, 'value': 0.5901812673170566}
调试完，回滚即可
In [4]: p.handle = origin_func
显而易见，拥有一个 attach console，我们能做的事情远不止此，我们可以用它来修改运行时配置、开关某个功能、热更新代码，当然，注意安全。
重申：在生产环境做任何非规范的变更都有危险，请三思。
结语
这篇文章是按个人的一些经验和见解写就，旨在分享一些个人常用的代码调试方式和思路。能力和精力有限，如有谬误，欢迎指正。文章中提到了的大部分工具，都是简单介绍，浅尝辄止，它们的更多功能请参阅各个工具的文档。
在套路和工具以外，代码调试更多的还是依靠开发者的知识储备、编码经验和想象力，当然，偶尔也需要一点运气。持续不断地学习，多看大神们的代码，多写，多总结，才能在写代码和调代码的时候更加驾轻就熟，离 bug free 的伟大目标更近一点。
关注我们，获一手游戏运维方案