分享一下自己的做的 Python profiling/debugging/logging 工具 VizTracer - V2EX
V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
推荐学习书目
Learn Python the Hard Way
Python Sites
PyPI - Python Package Index
http://diveintopython.org/toc/index.html
Pocoo
值得关注的项目
PyPy
Celery
Jinja2
Read the Docs
gevent
pyenv
virtualenv
Stackless Python
Beautiful Soup
结巴中文分词
Green Unicorn
Sentry
Shovel
Pyflakes
pytest
Python 编程
pep8 Checker
Styles
PEP 8
Google Python Style Guide
Code Style from The Hitchhiker's Guide
laike9m
V2EX    Python

分享一下自己的做的 Python profiling/debugging/logging 工具 VizTracer

  •  4
     
  •   laike9m
    laike9m 2020-10-26 11:38:00 +08:00 3658 次点击
    这是一个创建于 1816 天前的主题,其中的信息可能已经有所发展或是发生改变。

    首先声明这个不是我写的,而是替刚注册 V2 还不能发帖的朋友发的。当然我觉得 VizTracer 确实不错,比其它的火焰图库更符合直觉。 他的账号:@gaogaotiantian

    下面是正文。


    小伙伴们大家好~今天来分享一下我这几个月做的开源项目 VizTracer 。先把地址给了。

    https://github.com/gaogaotiantian/viztracer

    VizTracer 的核心功能是帮助你理解你的代码到底在干什么。它会 trace 你的 python code,记录每一次函数运行和返回的时间点,最后生成一个 html 文件把整个运行结果可视化,大概长这个样子:

    viztracer

    可能有些同学用过一些代码运行可视化的库,比如 gprof2dot 或者 snakeviz 之类,也可能大家觉得这个图和 flamegraph 也就是火焰图很像,但是 VizTracer 带来的信息和一切 profiler 是不太一样的。

    如果仔细观察的话能看出来,VizTracer 的横轴是时间,它记录了所有事件(函数)发生的顺序,谁调用的谁,每一次运行的时间,而不是单纯地某个函数一共占了多少时间,或者是总结性的函数关系图。VizTracer 展示的数据是一切以 cProfile 为基础的库都没法展示的,因为 cProfile 压根就没记录这些数据。相比起这些"profiler",VizTracer 更像一个 logging tool 。

    先简单说一下 VizTracer 怎么用吧。在设计之初,我的理念就是要让工具尽可能地好上手,所以 VizTracer 的使用其实特别容易:

    pip install viztracer viztracer your_script.py 

    是不是超级简单。基本上你只需要把原来的

    python your_script.py arg1 arg2 

    变成

    viztracer your_script.py arg1 arg2 

    就行了。

    在运行之后,VizTracer 会在当前目录下生成一个result.html文件,用 chrome 打开它即可。我自己生成了一些demo,感兴趣的同学可以看一下。

    除了最基础的记录函数 entry/exit 的功能之外,VizTracer 还有很多其他 loggin 功能,比较有趣的事,这里面有大量的功能是可以不改源代码就完成的。

    举个例子,你可以让 VizTracer 记录每个函数的 arguments 和 return value,只需要

    viztracer --log_return_value --log_function_args your_script.py 

    或者你可以让 VizTracer 记录任何符合某些 RegEx 的变量

    viztracer --log_var <regex1> <regex2> --run your_script.py 

    这个的效果是,如果有一个变量的名称符合<regex1>或者<regex2>,VizTracer 就会在这个变量每次被 assign 之后记录一个 custom event,让你可以在 report 里看到它被改成什么值了。(这里增加了--run是为了去歧义,--log_var可以 take 任意多的值)

    另外 VizTracer 还提供了一些 filter 功能,让你可以不记录你不感兴趣的内容。比如你可以只记录某些文件里的函数

    viztracer --include_files ./src --run your_script.py 

    其实还有很多很多 feature,欢迎大家去试用一下,这里只介绍了开箱即用的不改代码的一少部分 feature,还有一些 custom event 可以修改源代码来更精确地记录数据的变化。

    最后其实我想提一句的是,VizTracer 是我很认真对待的一个项目,不是当作玩具做的,我写了比较详细的文档(所有的 feature 都介绍了),test coverage 做到了 99.5%+,支持 Linux/MacOS/Windows 。另外为了追求 performance,VizTracer 的核心代码是纯 C 写的(所以只支持 CPython ),产生的 Overhead 和 cProfile 是差不多的,在 worst case 大概是 2x-3x 这个数量级(当然前提是没有 log 太多 custom 的东西)。

    就先介绍到这里吧!欢迎大家试用以及提出宝贵意见哈!有任何问题可以下面留言,也可以直接去 github 给我提 issue~

    第 1 条附言    2020-10-26 13:01:27 +08:00
    顺便一提,作者 @gaogaotiantian 下一期就将作客捕蛇者说和大家聊聊 VizTracer 。在此先预告一下
    https://www.pythonhunter.org/
    17 条回复    2020-10-27 02:33:39 +08:00
    ruanimal
        1
    ruanimal  
       2020-10-26 11:47:33 +08:00
    lz 毅力强,github 基本每天都有 commit
    siluni
        2
    siluni  
       2020-10-26 11:57:31 +08:00
    我是小白用户,刚才试用了一下,几百行代码的 project 跑出来了一个 156MB 的 html...是我用法有问题还是本来就这么大呢
    zouzou0208
        3
    zouzou0208  
       2020-10-26 12:10:50 +08:00
    看了下,做的好棒。
    gaogaotiantian
        4
    gaogaotiantian  
       2020-10-26 12:22:26 +08:00
    @siluni 这是正常的,VizTracer 本身记录的数据非常多,所以 log 会很大。代码的行数几百行可能有很多的 function call,十行代码就可以有几十万个 call 对吧~和 cProfile 不同,VizTracer 对于每个 call 都要单独记录一个 entry,所以文件会比较大~
    siluni
        5
    siluni  
       2020-10-26 12:55:57 +08:00
    @gaogaotiantian 明白了!非常感谢您的作品和回复~已 star
    Ehco1996
        6
    Ehco1996  
       2020-10-26 13:40:55 +08:00
    在运行之后,VizTracer 会在当前目录下生成一个 result.html 文件 -> 换成程序结束之后
    gaogaotiantian
        7
    gaogaotiantian  
       2020-10-26 15:01:23 +08:00
    @Ehco1996 确实应该是结束之后~不过文章似乎已经改不了了~大家应该差不多能理解吧~哈哈~
    no1xsyzy
        8
    no1xsyzy  
       2020-10-26 15:13:57 +08:00
    看起来挺不错的,但其实我一直没搞懂火焰图怎么看(
    gaogaotiantian
        9
    gaogaotiantian  
       2020-10-26 15:17:27 +08:00
    @no1xsyzy 哈~这个不是火焰图,算是 call stack 图吧~核心展示内容是函数之间的调用次序和时间
    THP301
        10
    THP301  
       2020-10-26 15:20:34 +08:00
    这个作品从实用性和易用性都做到了极致,生成的图还非常直观,少有的作品
    gaogaotiantian
        11
    gaogaotiantian  
       2020-10-26 15:23:20 +08:00
    @THP301 谢谢如此高的评价啊~实用性和易用性确实是我做这个项目时候很期望达成的目标~
    frostming
        12
    frostming  
       2020-10-26 15:44:40 +08:00
    在 POSIX getopt 标准里面"--" 可以用来分隔 option 和 positinal args,-- 后面的参数通通当做 positional args 塞给 Python 就好了,这个是有惯例的,个人认为会比--run 好,减少一个记忆点
    frostming
        13
    frostming  
       2020-10-26 15:46:37 +08:00   1
    我看了一下你用的 argparse,这些主流框架都是支持这么弄的,不需要额外的处理代码,如果有需要我可以 pr
    no1xsyzy
        14
    no1xsyzy  
       2020-10-26 15:52:13 +08:00
    @gaogaotiantian 拿主题这张图仔细看了看,结合你这句回复……
    我一直以为火焰图就是 call stack 图,原来不是吗?难怪看不懂……
    好吧,什么时候再去看看火焰图怎么看
    laike9m
        15
    laike9m  
    OP
       2020-10-26 16:16:37 +08:00 via Android
    @no1xsyzy 我也以为是。。
    gaogaotiantian
        16
    gaogaotiantian  
       2020-10-27 02:28:44 +08:00
    @frostming 这是个挺好的建议……我这两天就弄一下,把--run 作为 undocumented feature (为了 backward compatibility ),然后用--为主。
    gaogaotiantian
        17
    gaogaotiantian  
       2020-10-27 02:33:39 +08:00   1
    @no1xsyzy VizTracer 提供的图确实有和火焰图很相似的地方。简单来说,火焰图是一个“总结”性的图,它展示的是某一个函数在这个位置占据的总时间。而 VizTracer 的图是每一次调用都会有一个展示。

    比如说,A 调用了 B 100 次,每次 1ms 。在火焰图上,就是最下面是 A,A 的宽度是 100ms 的 B 加上 A 自己的耗时,A 上面有一个 B,B 的宽度是 100ms 。而 VizTracer 的图上,最下面是 A,A 上面有 100 个 1ms 的 B,每个 B 之间的间隔就是他们被调用之间 A 的耗时。
    关于     帮助文档     自助推广系统     博客     API     FAQ     Solana     901 人在线   最高记录 6679       Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 31ms UTC 20:22 PVG 04:22 LAX 13:22 JFK 16:22
    Do have faith in what you're doing.
    ubao msn snddm index pchome yahoo rakuten mypaper meadowduck bidyahoo youbao zxmzxm asda bnvcg cvbfg dfscv mmhjk xxddc yybgb zznbn ccubao uaitu acv GXCV ET GDG YH FG BCVB FJFH CBRE CBC GDG ET54 WRWR RWER WREW WRWER RWER SDG EW SF DSFSF fbbs ubao fhd dfg ewr dg df ewwr ewwr et ruyut utut dfg fgd gdfgt etg dfgt dfgd ert4 gd fgg wr 235 wer3 we vsdf sdf gdf ert xcv sdf rwer hfd dfg cvb rwf afb dfh jgh bmn lgh rty gfds cxv xcv xcs vdas fdf fgd cv sdf tert sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf shasha9178 shasha9178 shasha9178 shasha9178 shasha9178 liflif2 liflif2 liflif2 liflif2 liflif2 liblib3 liblib3 liblib3 liblib3 liblib3 zhazha444 zhazha444 zhazha444 zhazha444 zhazha444 dende5 dende denden denden2 denden21 fenfen9 fenf619 fen619 fenfe9 fe619 sdf sdf sdf sdf sdf zhazh90 zhazh0 zhaa50 zha90 zh590 zho zhoz zhozh zhozho zhozho2 lislis lls95 lili95 lils5 liss9 sdf0ty987 sdft876 sdft9876 sdf09876 sd0t9876 sdf0ty98 sdf0976 sdf0ty986 sdf0ty96 sdf0t76 sdf0876 df0ty98 sf0t876 sd0ty76 sdy76 sdf76 sdf0t76 sdf0ty9 sdf0ty98 sdf0ty987 sdf0ty98 sdf6676 sdf876 sd876 sd876 sdf6 sdf6 sdf9876 sdf0t sdf06 sdf0ty9776 sdf0ty9776 sdf0ty76 sdf8876 sdf0t sd6 sdf06 s688876 sd688 sdf86