CodeSnap 0.0.4 我把performance提升了20倍

在上篇文章发布之后,我的CodeSnap项目收获了11个star,让我非常开心。与此同时,我也越来越觉得这个项目本身还是有开发空间的,所以也投入了不少精力在这上面。

先来聊几个话题好了。评论区有人提到了sampling profiler,有一些overhead非常低而且不影响原程序运行的,一般是通过快速的sample从系统stack直接提取数据。对于profiling来说,这其实是个挺不错的方法。这相当于你妈妈想知道你每天玩电脑玩手机和学习的时间占比,就每五分钟进来看你一眼,然后通过看到你做什么事的数据来反推你的用功情况。

这个方法有它明确的优势,就是overhead低,几乎不太打扰原来的代码工作,而且从统计学的角度看可以得到很有价值的结果。

当然这个方法也有他的问题,就是对一切不能从统计学上解决的问题都束手无策。

比如有个函数A,它平时运行的很好,可就是每次在函数B之后马上运行的时候会忽然慢10倍。这种问题用sampling profiler是完全没法解决的。sampling profiler是不知道你的程序具体运行顺序的,它只能从统计学上去推测每个函数占用的时间比例。sample的频率太高,会占用CPU影响程序运行速度。sample频率太低,就会导致统计结果不准确。

或者说,sampling profiler是一个纯粹的profiling工具,专门用来观察函数总体的CPU占用时间情况。

而CodeSnap,首先是一个deterministic profiling tool,从某种意义上说,还是一个debugging tool。CodeSnap和cProfile一样,是hook在函数上的,不会漏掉任何一次函数的执行(和sampling profiler不同)。而和cProfile不同的是,CodeSnap还可以完全展示你程序的执行情况,也就是什么时间执行了什么函数,像一个录像机一样,可以完整地回看你的call stack随时间的变化。

而这,和传统的flame graph是有所不同的。

说了一些题外话,可以开始解释我的标题党了~

在做了0.0.1(其实是0.0.2)版本之后,我意识到一个问题,就是如果不解决overhead的问题,这个工具永远就是一个玩具,最多也就是给刚入门的程序员用着解释程序的运行情况(虽然这也算是功德无量了,请这个目的的也继续使用CodeSnap!)。所以我决定下一步我要先着手减少overhead。

我们老板说过一句话,叫never optimize without profiling。所以第一件事,就是写一个performance test。

我刚开始写的也比较简单,我写了一个fib,一个hanoi,都是几乎只有recursive call的函数,也就是我们面对的worst case。然后写了一个qsort,这是一个函数内有一些代码的recursive function,算是比较差的情况。最后写了一个slow_fib,在代码中用sleep函数强行休息10 us,来模拟比较长的函数,这算是比较好的情况。

在写完之后,我先做了baseline测试,也就是把他们跑一下,看看时间。然后加上CodeSnap再跑一下看看结果。

不测不知道,一测发现,worst case下,CodeSnap引入了大约30-40x的overhead,在比较差的情况下也有15x左右。只有在比较好的时候,才是1.1上下。10x+的overhead确实有点过分了,而解决这个问题其实只有唯一的方案——上C。

python本身的function开销就挺大,里面再记录数据啥的,导致在python优化基本没什么意义。于是就直接上C了。

python对C的支持还是挺友好的,不过虽然我python和C写的都非常多,他们一起写之前却没太接触过。在使用的过程中,也着实踩了不少的坑。C本身我没有问题,但是怎么把它变成一个python module,怎么用setuptools compile,都遇到了一些问题。

在用了C之后,overhead有了明显的下降,但是我依然不满意,于是我就找了第二个baseline——cProfile。我在performance test里把cProfile打开,跑一下,以这个为目标。在我本地跑出来,cProfile的overhead是7x左右(这里大坑,等等说)。

于是我开始一点一点对着cProfile的源代码做大家来找茬,发现需要尽量减少一切和python有关的C函数的调用。在不停地整理我的函数之后,我意识到,我整个函数最耗时的,竟然是get_clocktime,也就是拿timestamp的函数。这令我十分沮丧,我甚至不停地在cProfile里寻找他们的解决方案,最后发现他们其实最终也是用的get_clocktime。我算了一下,这函数竟然占了200 ns左右,我去网上查了很多资料,都说这个函数应该可以到20ns的量级。这10倍的时间都被谁吃了?

在挣扎了许久无果之后,我灵机一动,决定setup一个workflow,让他在github的ubuntu虚拟机上跑一下performance test。看到结果我不禁泪流满面,cProfile的overhead直接跑到了2x,而我经过优化的profiler,overhead跑到了和cProfile一个数量级。

于是乎我发现——WSL的get_clocktime是有performance issue的,无论你选哪个clock,最终只能跑到200 ns左右的时间。

和cProfiler做对比,CodeSnap在函数名上拿了一个它没有的信息,但是它在context上拿了不少CodeSnap没拿的信息,综合起来之后,在worst case下,CodeSnap的performance比cProfile稍差,在qsort里,CodeSnap的overhead就已经比cProfile低了。

fib       (10336, 10336): 0.000721018 vs 0.014787482(20.51)[py] vs 0.001513239(2.10)[c] vs 0.001430837(1.98)[cProfile]
hanoi     (8192, 8192): 0.000545514 vs 0.015095390(27.67)[py] vs 0.001853548(3.40)[c] vs 0.001155430(2.12)[cProfile]
qsort     (10656, 10756): 0.004032004 vs 0.047270921(11.72)[py] vs 0.005407240(1.34)[c] vs 0.008564321(2.12)[cProfile]
slow_fib  (1508, 1508): 0.028207528 vs 0.032685344(1.16)[py] vs 0.027702516(0.98)[c] vs 0.028034424(0.99)[cProfile]

贴一个刚刚在github VM上跑出来的结果。可以看到,在几乎只有function call的hanoi上,CodeSnap有3x的overhead,而cProfile只有2x多一点点。可是在比较差的qsort上,CodeSnap就只有1.34x的overhead了。注意,这1.34x只有0.34是overhead,1是原来程序要运行的时间。也就是说,面对qsort这种function call很密集的算法,CodeSnap也仅仅引入了34%的overhead,对于一个侵入式的profiler来说,已经相当不错了。

而从fib可以看出来,从接近20倍的额外支出,到1倍的额外支出,这个从python到C的优化,让CodeSnap的performance足足好了20倍。

现在的CodeSnap,起码在性能上,已经可以在一些正式的项目上使用了。(bug和support我们再说……)

然后我就发布了0.0.3(当然没人在意)。

搞完了后端,就是前端。

之前的前端我是用的python直接生成纯html,当然有它的好处。不过功能上确实欠缺了一些,而且如果entry多了渲染会很慢。于是我在网上搜了搜,发现了一个叫d3-flamegraph的开源项目。整体给人的感觉很不错,但是这是专门设计给sampling profiler的,有一些很重要的feature是没有的,比如它的call stack位置是不存在offset的,根本没办法体现时间的差别。

于是乎我fork了一份,自己改了一下源代码,重新生成了js文件扔到了CodeSnap里(d3-flamegraph用的是Apache 2.0,和CodeSnap是一个LICENSE,大家注意规范使用开源代码哈)。现在的前端就变得好看多了,而且多了挺多酷炫的功能,可以通过点击zoom了。

在输出的选择上,我依然选择了生成一个纯html文件,这样用户不需要处理多个file。不过这个html文件现在会load一些CDN,也就是说我之前想的纯local的report还是没能搞定,现在的html需要联网才能看。不过都2020年了,大家开发的电脑应该都能上网吧……

我自己带着CodeSnap跑了一下merge sort和quick sort,生成了一份report,当作demo放到了网上,感兴趣的小伙伴可以看一下:minkoder.com/codesnap/r

最近开发热情高涨,感谢大家的支持,如果大家有什么问题也欢迎和我沟通哈!最后当然还是留一下项目地址,万一有人star呢!

https://github.com/gaogaotiantian/codesnapgithub.com

发布于 08-09

文章被以下专栏收录