日拱一卒,麻省理工教你性能分析,火焰图、系统调用栈,黑科技满满

2022-09-21 11:04:52 浏览数 (1)

作者 | 梁唐

出品 | 公众号:Coder梁(ID:Coder_LT)

大家好,日拱一卒,我是梁唐。

今天我们继续麻省理工missing smester,消失的学期的学习。这一次我们继续上一节课的内容,来看看性能分析的部分。

B站视频链接:https://www.bilibili.com/video/BV1x7411H7wa?p=7

和之前一样,这节课的note质量同样非常高。

这次的内容相对来说使用的频率会比debug稍微低一些,可能更多的是后端工程师应用得比较多。经常需要查看系统的性能,以及运行情况,方便做出分析以及优化。前端和算法/数据工程师相对来说用得很少。

日拱一卒,欢迎大家打卡一起学习。

性能分析(profiling)

Profile这个单词原本是画像、侧写的意思,这里指的是对计算机的运行情况做一个画像和侧写,用来了解当前系统的状态。

有的时候,可能我们的代码功能是正确的,但是性能上出了问题。比如说耗光了系统所有的CPU或者是内存。在算法课上,我们会学习使用O这个记号来代表程序复杂度的方法。仓促的开发,简陋的优化是万恶之源。你可以参考这篇文章关于仓促优化的说明:http://wiki.c2.com/?PrematureOptimization。

你需要学习一些profiler(侧写工具)以及监控工具。它们可以帮助你理解你程序的哪一个部分消耗了太多时间/资源,这样你就可以迅速锁定问题以及确定优化方案。

计时

和debug的案例一样,在许多场景当中,打印出程序当中两处位置的时间就足够发现问题。这里是Python当中使用time模块的一个例子:

代码语言:javascript复制
import time, random
n = random.randint(1, 10) * 100

# Get current time
start = time.time()

# Do some work
print("Sleeping for {} ms".format(n))
time.sleep(n/1000)

# Compute time between start and now
print(time.time() - start)

# Output
# Sleeping for 500 ms
# 0.5713930130004883

但是,这里有一个问题,执行时间(wall clock time)很容易误导人。因为你的计算机同时还在运行其他进程或者是在等待阻塞/事件。对于工具来说,它需要区分真实时间、用户时间以及系统时间。总体上来说用户时间和系统时间告诉你,你的进程实际占用了多少CPU时间,你可以参考这篇文章获得更多解释:https://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1

  • 真实时间 - 从程序开始到结束流失掉的真实时间,包括其他进程的执行时间以及阻塞消耗的时间(例如等待 I/O或网络)
  • User - CPU 执行用户代码所花费的时间
  • Sys - CPU 执行系统内核代码所花费的时间

举个例子,试着在命令行运行一个获取HTTP请求的命令,并且在命令之前加上time关键字。在网络不好的时候,你可能会得到下面这样的结果。进程花费了2秒钟才运行结束,然而仅仅只有15毫秒的CPU用户时间,以及12毫秒的CPU内核时间,剩余的时间全部都在等待网络。

侧写工具(Profilers)

CPU

大多数时候,当人们提到侧写工具的时候,通常是在指CPU侧写工具。CPU侧写工具有两种:追踪侧写(tracing)和采样侧写(sampling)。

追踪侧写会记录你程序的每一个函数调用,而采样侧写只会周期性的检测你的程序栈(通常是毫秒级)。它们使用这些记录来进行聚合分析,找出程序在哪些事情上花费了时间。关于这个话题,可以参考这篇文章获取更多细节:

https://jvns.ca/blog/2017/12/17/how-do-ruby---python-profilers-work-

大多数编程语言拥有一些命令行侧写工具,可以用来进行代码分析。它们通常会被集成在IDE当中,但这节课上我们只会聚焦在命令行工具上。

在Python当中,我们可以使用cProfile模块来完成每个函数调用的耗时分析。这里有一个简单的例子,它实现了grep命令:

代码语言:javascript复制
#!/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)

我们可以使用如下的命令来进行代码分析。通过输出结果,我们可以看到IO消耗了最多的时间,但IO部分通常无法优化。另外我们可以发现,编译正则表达式也非常耗时。但正则表达式只需要编译一次,我们可以把它移动到for循环外来进行优化。

代码语言:javascript复制
$ 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]

python中的cProfile(以及其他的一些分析器)可以展示每一个函数调用的时间。这些工具运行的时候非常快,并且如果你在代码当中使用了一些第三方库,那么这些库中的内部函数的调用也会被统计进来。

侧写的时候对每行代码的运行时间进行计时会更加符合直觉,这就是line profiler的功能。

比如,接下来这段Python代码会向这门课的官网发起请求,并且解析返回结果,获取当中所有的URL:

代码语言:javascript复制
#!/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()

如果我们使用Python的cProfile来进行侧写,我们会得到超过2500行的输出,即使我们进行排序也很难完全理解。使用line_profiler的话,我们会得到每一行代码运行的时间:

代码语言:javascript复制
$ 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 这样的语言,内存泄漏会导致你程序当中有一块内存始终无法释放。为了更好地解决我们debug内存问题,我们可以使用一些像是Valgrind这样的工具来定位内存泄漏问题。

对于一些垃圾回收语言,比如Python,使用内存侧写器同样非常有用。因为可以帮助我们定位一些一直没有被回收的对象。下面这个例子展示了memory-profiler是如何工作的(注意装饰器和line-profiler类似)

代码语言:javascript复制
@profile
def my_func():
    a = [1] * (10 ** 6)
    b = [2] * (2 * 10 ** 7)
    del b
    return a

if __name__ == '__main__':
    my_func()
代码语言:javascript复制
$ 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这样的工具进行debug的时候,你可能会想要忽视特定的一些代码,把它们当做是黑盒进行处理。perf命令通过各种方式对CPU进行抽象,它不会报告时间和内存的消耗,但是他会报告你程序当中的系统事件。比如说,perf会报告低缓存局部性(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分析数据的方式是火焰图:https://www.brendangregg.com/flamegraphs.html。它会在Y轴上展示函数调用的层次结构,在X轴上显示耗时的比例。火焰图同时还是可交互的,你可以放大特定的部分并查看堆栈信息。

可以点击这个链接进行尝试:https://www.brendangregg.com/FlameGraphs/cpu-bash-flamegraph.svg

调用图或者是控制流图可以展示子程序之间的关系,它将函数当做是节点,函数之间的调用当做是有向边进行展示。结合侧写信息,比如调用次数、耗时等信息,调用关系图对于阐释程序的流程非常有用。在python当中,你可以使用pycallgraph库来生成它。

资源监控

很多时候,分析程序性能的第一步就是理解它到底消耗了多少资源。程序跑得慢通常是因为资源限制,比如没有足够的内存了,或者是网络连接很慢。

有很多命令行工具可以来展示不同的系统资源,比如CPU使用率、内存使用率、网络、磁盘使用率等等。

  • 通用监控 - 最流行的工具要数 htop,了,它是 top的改进版。htop 可以显示当前运行进程的多种统计信息。htop 有很多选项和快捷键,常见的有:进程排序、 t 显示树状结构和 h 打开或折叠线程。还可以留意一下 glances ,它的实现类似但是用户界面更好。如果需要合并测量全部的进程, dstat 也是一个非常好用的工具,它可以实时地计算不同子系统资源的度量数据,例如 I/O、网络、 CPU 利用率、上下文切换等等
  • I/O 操作 - iotop 可以显示实时 I/O 占用信息而且可以非常方便地检查某个进程是否正在执行大量的磁盘读写操作
  • 磁盘使用 - df 可以显示每个分区的信息,而 du 则可以显示当前目录下每个文件的磁盘使用情况( disk usage)。-h 选项可以使命令以对人类(human)更加友好的格式显示数据;ncdu是一个交互性更好的 du ,它可以让您在不同目录下导航、删除文件和文件夹
  • 内存使用 - free 可以显示系统当前空闲的内存。内存也可以使用 htop 这样的工具来显示
  • 打开文件 - lsof 可以列出被进程打开的文件信息。当我们需要查看某个文件是被哪个进程打开的时候,这个命令非常有用
  • 网络连接和配置 - ss 能帮助我们监控网络包的收发情况以及网络接口的显示信息。ss 常见的一个使用场景是找到端口被进程占用的信息。如果要显示路由、网络设备和接口信息,您可以使用 ip 命令。注意,netstat 和 ifconfig 这两个命令已经被前面那些工具所代替了
  • 网络使用 - nethogs 和 iftop 是非常好的用于对网络占用进行监控的交互式命令行工具

如果你想要测试这些工具,你可以手动使用stress命令来为机器增加负载。

专用工具

有时候,你会想要对黑盒进行性能测试,从而决定应该使用什么工具。像是hypterfine这样的工具可以帮你进行快速测试。比如,我们在shell工具那一课当中推荐使用fd而不是find。我们可以使用hyperfine来对比一下它们。

比如在下面的例子当中,fd运行速度是find的20倍以上。

代码语言:javascript复制
$ 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"'

和debug一样,浏览器也提供了非常好的页面分析工具。让你能够发现时间都消耗在了什么地方(加载、渲染、脚本等等)。可以在使用的浏览器帮助当中查找这部分信息。

练习

  1. 这里有很多已经实现好的排序算法:https://missing.csail.mit.edu/static/files/sorts.py。使用cProfileline_profiler来对比插入排序和快速排序的耗时。每一个算法的瓶颈是多少?使用memory_profiler来检查内存使用,为什么插入排序更优?然后再查看快排的inplace版本。挑战:使用perf来查看每个算法循环次数以及缓存命中和和没命中的情况
  2. 这里有一些计算斐波那契数列的Python代码,对计算每个数字定义了一个函数:
代码语言:javascript复制
#!/usr/bin/env python
def fib0(): return 0

def fib1(): return 1

s = """def fib{}(): return fib{}()   fib{}()"""

if __name__ == '__main__':

    for n in range(2, 10):
        exec(s.format(n, n-1, n-2))
    # from functools import lru_cache
    # for n in range(10):
    #     exec("fib{} = lru_cache(1)(fib{})".format(n, n))
    print(eval("fib9()"))

把代码拷贝进入文件,然后执行它。首先安装依赖pycallgraphgraphviz(如果你能运行dot,说明你已经有了GraphViz)。使用pycallgraph graphviz -- ./fib.py命令运行代码,查看pycallgraph.png文件。fib0被调用了多少次?我们可以通过记忆化对算法进行优化。放开注释的代码,重新生成图片,现在,对于每个fibN函数,分别调用了多少次?

  1. 想要使用的端口被占用是一个非常常见的问题。现在让我们看看怎么样发现是被什么程序占用了。首先,运行python -m http.server 4444来启动一个mini web服务器监听端口4444。在另外一个终端当中运行lsof | grep LISTEN打印出所有正在监听的进程以及端口。找到监听4444的进程id,并使用kill干掉
  2. 限制进程能够使用的资源也是一个很好的办法。试着使用stree -c 3并使用htop对CPU消耗进行可视化。执行taskset --cpu-list 0,2 stress -c 3来进行可视化。stress占用了3个CPU吗?为什么没有?阅读一下man taskset来找答案。挑战:使用cgroups命令来实现同样的效果,试着使用stress -m来限制内存消耗
  3. (进阶)curl ipinfo.io命令发起一个HTTP请求并获取你的公共IP。打开Wireshark:https://www.wireshark.org/尝试抓取curl发起的请求和受到的结果。(提示:可以使用http进行过滤只显示HTTP包)

喜欢本文的话不要忘记三连~

0 人点赞