Python 代码调试二三事

最新推荐文章于 2024-04-17 18:32:53 发布

gt9000

最新推荐文章于 2024-04-17 18:32:53 发布

阅读量667

点赞数

前言

借着机器学习的东风，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)()
----> 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 ()
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

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 方面具有非常大的想象空间。

原文链接

https://mp.weixin.qq.com/s/Mlhrp2E390EMD0ZfSaNFKw

服务推荐

gt9000

关注

0
点赞
踩
1

收藏

觉得还不错? 一键收藏
0
评论
Python 代码调试二三事

文章内容前言借着机器学习的东风，Python 近年来大热，一举冲入最受欢迎编程语言榜前三。同时，Python 已经在 Web、运维、科学计算、游戏等领域广泛应用，很多人使用它来构建原型、实现周边模块、做实验、写性能要求不高的业务逻辑、作为胶水语言完成系统串联，亦有不少公司使用 Python 来开发大型应用。如今，拿 Python 写的代码越来越多，有代码的地方就有 bug。虽然 bug fr...
复制链接

扫一扫