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 · 2755 次点击
    这是一个创建于 1250 天前的主题,其中的信息可能已经有所发展或是发生改变。

    首先声明这个不是我写的,而是替刚注册 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   ·   我们的愿景   ·   实用小工具   ·   5425 人在线   最高记录 6543   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 41ms · UTC 06:45 · PVG 14:45 · LAX 23:45 · JFK 02:45
    Developed with CodeLauncher
    ♥ Do have faith in what you're doing.