调试及性能分析
调试代码
打印语句
[!tip]
“最有效的 debug 工具就是细致的分析,配合恰当位置的打印语句” — Brian Kernighan, Unix 新手入门。
使用日志
将日志写入文件、socket 或者甚至是发送到远端服务器而不仅仅是标准输出
日志可以支持严重等级(例如 INFO, DEBUG, WARN, ERROR 等)
对于新发现的问题,很可能日志中已经包含了可以帮助您定位问题的足够的信息
包含日志的例程序: $ python logger.py # Raw output as with just prints $ python logger.py log # Log formatted output $ python logger.py log ERROR # Print only ERROR levels and above $ python logger.py color # Color formatted output
以彩色文本显示终端信息时可读性更好
echo -e "\e[38;2;255;0;0mstring\e[0m"
会打印红色的字符串string
可以使用支持更加广泛的 16 色,例如:”\e[31; 1mstring\e[0m “。
#!/usr/bin/env bash for R in $(seq 0 20 255); do for G in $(seq 0 20 255); do for B in $(seq 0 20 255); do printf "\e[38;2;${R};${G};${B}m█\e[0m"; done done done
第三方日志系统
构建大型软件系统,您很可能会使用到一些依赖,有些依赖会作为程序单独运行。如 Web 服务器、数据库或消息代理都是此类常见的第三方依赖。
系统交互的时候,阅读它们的日志是非常必要的,因为仅靠客户端侧的错误信息可能并不足以定位问题。
大多数的程序都会将日志保存在您的系统中的某个地方
UNIX 系统来说,程序的日志通常存放在
/var/log
NGINX web 服务器就将其日志存放于
/var/log/nginx
系统开始使用 system log,您所有的日志都会保存在这里
大多数(但不是全部的)Linux 系统都会使用
systemd
,这是一个系统守护进程控制您系统中的很多东西,例如哪些服务应该启动并运行。
systemd
会将日志以某种特殊格式存放于/var/log/journal
,您可以使用journalctl
命令显示这些消息。
logger
- 如果您希望将日志加入到系统日志中,您可以使用
logger
这个 shell 程序。
多数的编程语言都支持向系统日志中写日志。
logger "Hello Logs"
# On macOS
log show --last 1m | grep Hello
# On Linux
journalctl --since "1m ago" | grep Hello
- 需要对
journalctl
和log show
的结果进行大量的过滤,那么此时可以考虑使用它们自带的选项对其结果先过滤一遍再输出 - 像
lnav
这样的工具,它为日志文件提供了更好的展现和浏览方式
调试器
[!note]
调试器是一种可以允许我们和正在执行的程序进行交互的程序,它可以做到:
- 当到达某一行时将程序暂停;
- 一次一条指令地逐步执行程序;
- 程序崩溃后查看变量的值;
- 满足特定条件时暂停程序;
- 其他高级功能。
Python 的调试器是
pdb
.pdb
支持的命令进行简单的介绍:- l(ist) - 显示当前行附近的 11 行或继续执行之前的显示;
- s(tep) - 执行当前行,并在第一个可能的地方停止;
- n(ext) - 继续执行直到当前函数的下一条语句或者 return 语句;
- b(reak) - 设置断点(基于传入的参数);
- p(rint) - 在当前上下文对表达式求值并打印结果。还有一个命令是 pp ,它使用
pprint
打印; - r(eturn) - 继续执行直到当前函数返回;
- q(uit) - 退出调试器。
ipdb
是一种增强型的pdb
,它使用IPython
作为 REPL 并开启了 tab 补全、语法高亮、更好的回溯和更好的内省,同时还保留了pdb
模块相同的接口。
专门工具
程序需要执行一些只有操作系统内核才能完成的操作时,它需要使用 系统调用。有一些命令可以帮助您追踪您的程序执行的系统调用。
在 Linux 中可以使用
strace
,在 macOS 和 BSD 中可以使用dtrace
。对
stat
系统调用进行追踪对结果。若需要深入了解strace
,这篇文章 值得一读。# On Linux sudo strace -e lstat ls -l > /dev/null 4 # On macOS sudo dtruss -t lstat64_extended ls -l > /dev/null
[!tip]
有些情况下,我们需要查看网络数据包才能定位问题。像
tcpdump
和 Wireshark 这样的网络数据包分析工具可以帮助您获取网络数据包的内容并基于不同的条件进行过滤。
静态分析
静态分析 工具就可以帮我们找到问题。静态分析会将程序的源码作为输入然后基于编码规则对其进行分析并对代码的正确性进行推理。
下面这段 Python 代码中存在几个问题。 首先,我们的循环变量 foo
覆盖了之前定义的函数 foo
。最后一行,我们还把 bar
错写成了 baz
,因此当程序完成 sleep
(一分钟)后,执行到这一行的时候便会崩溃。
import time
def foo():
return 42
for foo in range(5):
print(foo)
bar = 1
bar *= 0.2
time.sleep(60)
print(baz)
使用 pyflakes
分析代码的时候,我们会得到与这两处 bug 相关的错误信息。mypy
则是另外一个工具,它可以对代码进行类型检查。
对于shell
介绍了
shellcheck
,这是一个类似的工具,但它是应用于 shell 脚本的。
在 vim 中,有 ale
或 syntastic
可以帮助您做同样的事情。 在 Python 中, pylint
和 pep8
是两种用于进行风格检查的工具,而 bandit
工具则用于检查安全相关的问题。
[!tip]
对于风格检查和代码格式化,还有以下一些工具可以作为补充:用于 Python 的
black
、用于 Go 语言的gofmt
、用于 Rust 的rustfmt
或是用于 JavaScript, HTML 和 CSS 的prettier
。这些工具可以自动格式化您的代码,这样代码风格就可以与常见的风格保持一致。
性能分析
鉴于 过早的优化是万恶之源,您需要学习性能分析和监控工具,它们会帮助您找到程序中最耗时、最耗资源的部分,这样您就可以有针对性的进行性能优化。
计时
打印两处代码之间的时间即可发现问题。下面这个例子中,我们使用了 Python 的
time
模块。import time, random n = random.randint(1, 10) * 100 # 获取当前时间 start = time.time() # 执行一些操作 print("Sleeping for {} ms".format(n)) time.sleep(n/1000) # 比较当前时间和起始时间 print(time.time() - start) # Output # Sleeping for 500 ms # 0.5713930130004883
[!tip]
执行时间(wall clock time)也可能会误导您,因为您的电脑可能也在同时运行其他进程,也可能在此期间发生了等待。
对于工具来说,需要区分真实时间、用户时间和系统时间。
用户时间 + 系统时间代表了您的进程所消耗的实际 CPU
- 真实时间 Real - 从程序开始到结束流失掉的真实时间,包括其他进程的执行时间以及阻塞消耗的时间(例如等待 I/O 或网络);
- 用户时间 User - CPU 执行用户代码所花费的时间;
- 系统时间 Sys - CPU 执行系统内核代码所花费的时间。
例如,试着执行一个用于发起 HTTP 请求的命令并在其前面添加
time
前缀。$ time curl https://missing.csail.mit.edu &> /dev/null real 0m2.561s user 0m0.015s sys 0m0.012s
性能分析工具
提及性能分析工具的时候,通常指的是 CPU 性能分析工具。 CPU 性能分析工具有两种: 追踪分析器(tracing)及采样分析器(sampling)。
追踪分析器 会记录程序的每一次函数调用,而采样分析器则只会周期性的监测(通常为每毫秒)您的程序并记录程序堆栈。
python
在 Python 中,使用
cProfile
模块来分析每次函数调用所消耗的时间。 在下面的例子中,我们实现了一个基础的 grep 命令:#!/usr/bin/env python import sys, re def grep(pattern, file): with open(file, 'r') as f: print(file) for i, line in enumerate(f.readlines()): pattern = re.compile(pattern) match = pattern.search(line) if match is not None: print("{}: {}".format(i, line), end="") if __name__ == '__main__': times = int(sys.argv[1]) pattern = sys.argv[2] for i in range(times): for file in sys.argv[3:]: grep(pattern, file)
$ python -m cProfile -s tottime grep.py 1000 '^(import|\s*def)[^,]*$' *.py [omitted program output] ncalls tottime percall cumtime percall filename:lineno(function) 8000 0.266 0.000 0.292 0.000 {built-in method io.open} 8000 0.153 0.000 0.894 0.000 grep.py:5(grep) 17000 0.101 0.000 0.101 0.000 {built-in method builtins.print} 8000 0.100 0.000 0.129 0.000 {method 'readlines' of '_io._IOBase' objects} 93000 0.097 0.000 0.111 0.000 re.py:286(_compile) 93000 0.069 0.000 0.069 0.000 {method 'search' of '_sre.SRE_Pattern' objects} 93000 0.030 0.000 0.141 0.000 re.py:231(compile) 17000 0.019 0.000 0.029 0.000 codecs.py:318(decode) 1 0.017 0.017 0.911 0.911 grep.py:3(<module>) [omitted lines]
通过它的输出我们可以知道,IO 消耗了大量的时间,编译正则表达式也比较耗费时间。
正则表达式只需要编译一次,可以将其移动到 for 循环外面来改进性能。
- 更加符合直觉的显示分析信息的方式是包括每行代码的执行时间,这也是 行分析器 的工作。
#!/usr/bin/env python import requests from bs4 import BeautifulSoup # 这个装饰器会告诉行分析器 # 我们想要分析这个函数 @profile def get_urls(): response = requests.get('https://missing.csail.mit.edu') s = BeautifulSoup(response.content, 'lxml') urls = [] for url in s.find_all('a'): urls.append(url['href']) if __name__ == '__main__': get_urls()
使用
line_profiler
,它会基于行来显示时间:$ kernprof -l -v a.py Wrote profile results to urls.py.lprof Timer unit: 1e-06 s Total time: 0.636188 s File: a.py Function: get_urls at line 5 Line # Hits Time Per Hit % Time Line Contents ============================================================== 5 @profile 6 def get_urls(): 7 1 613909.0 613909.0 96.5 response = requests.get('https://missing.csail.mit.edu') 8 1 21559.0 21559.0 3.4 s = BeautifulSoup(response.content, 'lxml') 9 1 2.0 2.0 0.0 urls = [] 10 25 685.0 27.4 0.1 for url in s.find_all('a'): 11 24 33.0 1.4 0.0 urls.append(url['href'])
内存
- C 或者 C++ 这样的语言,内存泄漏会导致您的程序在使用完内存后不去释放它
- 使用类似 Valgrind 这样的工具来检查内存泄漏问题。
对于python
Python 这类具有垃圾回收机制的语言,内存分析器也是很有用的,因为对于某个对象来说,只要有指针还指向它,那它就不会被回收。
memory-profiler 是如何工作的(注意装饰器和
line-profiler
类似)。
@profile def my_func(): a = [1] * (10 ** 6) b = [2] * (2 * 10 ** 7) del b return a if __name__ == '__main__': my_func()
$ python -m memory_profiler example.py Line # Mem usage Increment Line Contents ============================================== 3 @profile 4 5.97 MB 0.00 MB def my_func(): 5 13.61 MB 7.64 MB a = [1] * (10 ** 6) 6 166.20 MB 152.59 MB b = [2] * (2 * 10 ** 7) 7 13.61 MB -152.59 MB del b 8 13.61 MB 0.00 MB return a
事件分析
使用 strace
调试代码的时候,您可能会希望忽略一些特殊的代码并希望在分析时将其当作黑盒处理。perf
命令将 CPU 的区别进行了抽象,它不会报告时间和内存的消耗,而是报告与您的程序相关的系统事件。
例如,
perf
可以报告不佳的缓存局部性(poor cache locality)、大量的页错误(page faults)或活锁(livelocks)。下面是关于常见命令的简介:
perf list
- 列出可以被 pref 追踪的事件;perf stat COMMAND ARG1 ARG2
- 收集与某个进程或指令相关的事件;perf record COMMAND ARG1 ARG2
- 记录命令执行的采样信息并将统计数据储存在perf.data
中;perf report
- 格式化并打印perf.data
中的数据。
可视化
对于采样分析器来说,常见的显示 CPU 分析数据的形式是 火焰图,火焰图会在 Y 轴显示函数调用关系,并在 X 轴显示其耗时的比例。
火焰图同时还是可交互的,您可以深入程序的某一具体部分,并查看其栈追踪
调用图和控制流图可以显示子程序之间的关系,它将函数作为节点并把函数调用作为边。将它们和分析器的信息(例如调用次数、耗时等)放在一起使用时,调用图会变得非常有用,它可以帮助我们分析程序的流程。
在 Python 中您可以使用 pycallgraph
来生成这些图片。
资源监控
通用监控
最流行的工具要数 htop
, 了,它是 top
的改进版。htop
可以显示当前运行进程的多种统计信息。htop
有很多选项和快捷键,常见的有:<F6>
进程排序、 t
显示树状结构和 h
打开或折叠线程。
glances
,它的实现类似但是用户界面更好。
如果需要合并测量全部的进程, dstat
是也是一个非常好用的工具,它可以实时地计算不同子系统资源的度量数据,例如 I/O、网络、 CPU 利用率、上下文切换等等;
I/O 操作
iotop
可以显示实时 I/O 占用信息而且可以非常方便地检查某个进程是否正在执行大量的磁盘读写操作;
磁盘使用
df
可以显示每个分区的信息,而du
则可以显示当前目录下每个文件的磁盘使用情况( d isk u sage)。-h
选项可以使命令以对人类(h uman)更加友好的格式显示数据;ncdu
是一个交互性更好的du
,它可以让您在不同目录下导航、删除文件和文件夹;
内存使用
free
可以显示系统当前空闲的内存。内存也可以使用htop
这样的工具来显示;
打开文件
lsof
可以列出被进程打开的文件信息。 当我们需要查看某个文件是被哪个进程打开的时候,这个命令非常有用;
网络连接和配置
ss
能帮助我们监控网络包的收发情况以及网络接口的显示信息。ss
常见的一个使用场景是找到端口被进程占用的信息。如果要显示路由、网络设备和接口信息,您可以使用ip
命令。- 注意,
netstat
和ifconfig
这两个命令已经被前面那些工具所代替了。
网络使用
专用工具
只需要对黑盒程序进行基准测试,并依此对软件选择进行评估。
类似 hyperfine
这样的命令行可以帮您快速进行基准测试。例如,我们在 shell 工具和脚本那一节课中我们推荐使用 fd
来代替 find
。我们这里可以用 hyperfine
来比较一下它们。
例如,下面的例子中,我们可以看到 fd
比 find
要快 20 倍。
$ hyperfine --warmup 3 'fd -e jpg' 'find . -iname "*.jpg"'
Benchmark #1: fd -e jpg
Time (mean ± σ): 51.4 ms ± 2.9 ms [User: 121.0 ms, System: 160.5 ms]
Range (min … max): 44.2 ms … 60.1 ms 56 runs
Benchmark #2: find . -iname "*.jpg"
Time (mean ± σ): 1.126 s ± 0.101 s [User: 141.1 ms, System: 956.1 ms]
Range (min … max): 0.975 s … 1.287 s 10 runs
Summary
'fd -e jpg' ran
21.89 ± 2.33 times faster than 'find . -iname "*.jpg"'