测量 Python 程序的 io 时间和 cpu 时间

https://www.nylas.com/blog/performance/ 我们这边参考了这篇文章做了 Flamechart ，之前用它定位了几个性能瓶颈。当然如果有个能够 dynamic tracing 的工具就更好了： https://openresty.org/posts/dynamic-tracing/

EchoUtopia

2017-04-19 18:56:00 +08:00

timeit 模块可以循环执行某条语句ｎ多次，并测量运行时间。不过我感觉是 io 和还是 cpu 瓶颈自己看代码都能感觉出来吧：）。

monsterxx03

2017-04-19 18:58:30 +08:00

要的是不是这样的 @eclipselu https://github.com/uber/pyflame

非侵入式

nthhdy

2017-04-19 19:28:09 +08:00

@zhangmiaoCHN cpu 部分也可能有比较耗 cpu 的部分，然而网络请求也很多很频繁。最关键的，目前都是串行的，等 io 结果出来再做事。我们的考虑是，如果耗 cpu 的任务能够不用等待 io （我们这个场景下逻辑上是可行的），会节省许多时间。
所以想测量一下 cpu 时间和 io 时间，看看二者的比例到底如何。

nthhdy

2017-04-19 19:29:45 +08:00

@monsterxx03 看起来很牛哦，我先了解一下

pynix

2017-04-19 21:06:15 +08:00

@nthhdy asyncio

guyskk

2017-04-19 23:28:58 +08:00 via Android

用 ab 并发调大一点测一下，看 CPU 能飚到多少， CPU 不高则说明瓶颈在 IO

ryd994

2017-04-20 05:45:49 +08:00 via Android

Linux 下用 time 就好了啊
看看 Wall clock 和 user+kernel 的差距就行

eclipselu

2017-04-20 10:59:54 +08:00

@monsterxx03 对就是这个东西。

nthhdy

2017-04-22 18:41:02 +08:00

@eclipselu @monsterxx03 我试了 pyflame
如果 all 的值是 40000,某一个函数 f 的值是 30000,意思就是,在 40000 次抽样当中,有 30000 次,调用栈里都包含函数 f 的 frame.所以整个调用函数 f 的时间,其实占用了整体时间的 75%.
如果有多个 thread,由于 GIL 的关系,同一时刻只有一个 thread 在运行.所以这个对时间的估计依然成立.
我的理解对吗?

话说回复不能贴图吗?...

monsterxx03

2017-04-22 19:48:36 +08:00 via iPhone

@nthhdy 没错，它还有个--thread 选项，虽然只有一个 thread 在跑，还是能看到快照时候其他 thread 在干嘛。

你的 idle 时间怎么样? io 和 c 库调用它没法探测，我的因为是 web 应用，大量时间都在 io, 所以 idle 时间特别长， python 部分只能凑合看下，大致和逻辑复杂度对得上。

nthhdy

2017-05-01 21:26:00 +08:00

@monsterxx03 我在火焰图上没看到 idle. top 显示的 idle 还是比较高的,因为我的程序主要慢在,io 太多,且 io 和 cpu 是串行的,cpu 在等待 io.所以 cpu 利用率很低.

所以我打算引入 gevent 了.用 coroutine 先把 cpu 占满.
引入 gevent 之后,pyflame 还能用吗?我还没有试呢.
按照我的理解,greenlet 的实现,是自己维护了以及 process 运行的必要环境,比如各种堆栈;switch 时在自己维护的环境和真实环境中相互 copy.所以 pyflame 应当还是可以 work 的.这个理解对吗?

monsterxx03

2017-05-02 16:11:16 +08:00

@nthhdy 我就是在 gevent 上 perf 的，估计你看到的会和我差不多，很长的 idle 和 gevent 等待 task 的时间，不是很明白，我发 issue 问过，但没理我: https://github.com/uber/pyflame/issues/64

中间那部分才是真正的业务逻辑, 大致能和 cpu 耗时对得上。

nthhdy

2017-05-03 14:56:23 +08:00

@monsterxx03 我没有 idle，但是 wait 很长，像你的图右侧一样。不知中间的那部分是否有参考性。
没有 google 到什么解释。大概只能从二者的原理入手来理解了吧。

nthhdy

2017-05-03 18:01:17 +08:00

我感觉这个测量是靠谱的
greenlet 虽然把 call stack 弄得“支离破碎”，但很有可能，在每个时刻对解释器来说是能够还原出当前线程的信息的。
所以说，图最右侧的是真正的 io 时间。这段时间内，gevent 发现，所有协程都阻塞住，没有任何一个能够继续往下走。
你那张图，如果用 top 观测 cpu rate，应该在 20%左右。当然也有可能不止，因为图上的 idle 也有可能在 run cpu，只是 pyflame 没法测它。

当然我说的不一定对。python 实现，greenlet，pyflame 的机制还要了解更多才知道。