ZhangHeng's Blog
0%

分析Python程序性能 （译）

发表于 分类于
本文字数： 3k 阅读时长 ≈ 6 分钟

本文用于练习英文阅读，如有侵权，联系删除

原文链接是Itamar Turner-Trauring写的Not just CPU:writing custom profilers for Python

以下为译文
如果你的程序运行缓慢，并且你确定仅部分归因于CPU,你该如何确定代码的那一部分正在等待CPU以外的时间呢？

在本文中，你将学习如何编写自定义的分析器，并帮你精确分析定位代码运行具体消耗的时间。特别的，我们将讨论:

  • 你的程序具体时间消耗情况
  • 分析非CPU等待时间
  • 分析非自愿上下文切换消耗的时间

你的程序在等待什么？

有些时候你的程序时间花费在CPU以外的地方，可能是:

  • 网络通讯.可能包括DNS查询，等待对方响应，等待所有数据加载完成，等等。
  • 硬盘读写. 从硬盘读写数据需要一些延迟，有时会先写入内存缓存，这很快。有时会直接写入硬盘，比较慢。
  • 锁.程序也可能等待线程/进程锁释放
  • 睡眠.有时你的程序会主动等待，比如等待一段时间后重试或退出。

那如何找到这些具体发生了什么操作呢？

技巧＃1 非CPU运行时间

Python 内置的cProfile 分析器可以分析你的程序调用情况，你可以用它分析非CPU时间占用情况。

正如我上一篇文章中所讨论的那样，你的操作系统可以告诉你程序使用了CPU多少秒。

让我们假设有一个单线程程序(多线程程序更难分析和推理),如果你的程序运行共花费了9秒，使用了7.5秒的CPU,这意味着有1.5秒花费在等待上。

首先，构建一个测量非CPU时间的计时器：

1
2
3
4
5
import os

def not_cpu_time():
    times = os.times()
    return times.elapsed - (times.system + times.user)

接着，创建一个使用上面新创建的计时器的分析器。

1
2
3
4
5
6
7
8
import cProfile, pstats

def profile_not_cpu_time(f, *args, **kwargs):
    prof = cProfile.Profile(not_cpu_time)
    prof.runcall(f, *args, **kwargs)
    result = pstats.Stats(prof)
    result.sort_stats("time")
    result.print_stats()

现在，你可以用它分析各种函数。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
from  urllib.request import urlopen

#分析打开一个网页
profile_not_cpu_time(
    lambda: urlopen("https://pythonspeed.com").read())
#结果
    659 function calls (658 primitive calls) in 0.640 seconds
    Ordered by: internal time
    ncalls  tottime  percall  filename:lineno(function)
        3    0.050    0.017   _ssl._SSLSocket.read
        1    0.040    0.040   _socket.getaddrinfo
        1    0.020    0.020   _socket.socket.connect
        1    0.010    0.010   _ssl._SSLSocket.do_handshake
    342    0.010    0.000   find.str
    192    0.010    0.000   append.list

我们可以看到大多数时间花费在了从套接字读取上(read)，但DNS查询(getaddrinfo),TCP握手(connect),以及TLS/SSL握手也需要一些时间。

由于我们小心避免了计算CPU时间，我们可以知道这纯粹是等待时间，不包含CPU占用花费。

注意:为什么会有str.find 和list.append? 他们不需要任何等待，所以这可能是整个程序没有被运行，也可能因为某些其他程序安排的运行，或者是有时需要从swap交换分区加载到内存里。这意味着发生一些时间消耗，但并不算在CPU占用时间里。

技巧#2 主动上下文切换

测量非CPU占用时间可能因为一些不受程序控制的行为，导致结果有些不同。有时DNS查询会变得很慢，有时下载花费的时间会很长。因此我们想使用一个更精准的测量方式，它不受外部条件变化影响。

要做到这一点的方法之一是 测量进程做了多少次需要等待的操作：计算等待次数，而不是等待时间。

这是你如何去做。当你的进程停止使用CPU资源，可能有一下两个原因:
1. 每次作一个不会立刻返回结果的操作,诸如 读取socket(套接字)，sleeping(休眠)等等，他会告诉操作系统:"等返回结果了再唤醒我"这是“主动上下文切换”,CPU可以切换运行其他的程序，直到从socket里读取到了数据，休眠结束等等再切换回来。
2. 被动上下文切换， 这时操作系统暂时停止运行这个进程，以运行其他需要使用CPU的进程。

因此，出于我们的目的，我们想分析主动上下文切换所花费的时间。

你可以使用psutil库去写一个分析器，测量主动上下文切换消耗

1
2
3
4
5
6
7
8
9
10
11
import psutil

_current_process = psutil.Process()

def profile_voluntary_switches(f, *args, **kwargs):
    prof = cProfile.Profile(
        lambda: _current_process.num_ctx_switches().voluntary)
    prof.runcall(f, *args, **kwargs)
    result = pstats.Stats(prof)
    result.sort_stats("time")
    result.print_stats()

你可以再次分析网络请求的代码

1
2
3
4
5
6
7
8
9
10
11
12
13
from  urllib.request import urlopen

#分析打开一个网页
profile_voluntary_switches(
    lambda: urlopen("https://pythonspeed.com").read())

#结果
ncalls  tottime  percall  filename:lineno(function)
     3    7.000    2.333  _ssl._SSLSocket.read
     1    2.000    2.000  _ssl._SSLSocket.do_handshake
     1    2.000    2.000  _socket.getaddrinfo
     1    1.000    1.000  _ssl._SSLContext.set_default_verify_path
     1    1.000    1.000  _socket.socket.connect

现在看到的不是花费的等待时间，而是主动上下文切换发生的次数。

分析所有消耗

使用分析技术会带来一些额外成本:因为额外的开销导致你的程序变慢一些。大多数情况对结果影响不大，因为你没有分析CPU。

通常，你可以分析任何数据。例如:

  • 读操作(psutil.Process().read_count)和写操作(psutil.Process().write_count))数
  • 在Linux上，读写的总字节数( psutil.Process().read_chars)
  • 内存分配分析(这需要一些额外的工作，但也可以使用 jemalloc)

你也可以看psutil的文档进一步了解上面两点。

欢迎关注我的其它发布渠道