用py-spy对Python代码进行剖析

2,493 阅读8分钟

如果你有一个正在运行的Python程序,你可能想了解该代码的实际性能状况如何。这个程序可能是在生产环境中,也可能只是在你的本地机器上。你将想了解运行中的程序在哪里花费时间,以及是否存在任何应该进一步调查改进的 "热点"。你可能正在处理一个行为不端的生产系统,你可能想以一种不引人注意的方式对它进行剖析,而不进一步影响生产性能或需要修改代码。有什么好方法可以做到这一点呢?这篇文章将讨论py-spy,一个允许你对已经运行的 Python 程序进行剖析的工具。

确定性剖析器与抽样剖析器

在之前的文章中,我写了两个确定性剖析器,cProfileline_profiler。这些剖析器在你开发代码并想对代码的某些部分或整个过程进行剖析时很有用。由于它们是确定性的,它们会准确地告诉你一个函数(或者在line_profiler ,一个行)被执行了多少次,以及与你的其他代码相比,它_相对_需要多少时间来执行。因为这些剖析器是在观察过程中运行的,它们在一定程度上减慢了速度,因为它们必须在程序执行的过程中进行记账和计算。对于生产代码来说,修改代码或在启用剖析器的情况下重新启动代码往往不是一个选项。

这时,抽样剖析器就会有帮助。采样剖析器观察一个现有的进程,并使用各种技巧来确定运行中的进程正在做什么。你可以自己手动尝试。例如,在linux上,你可以使用pstack <pid> (或gstack <pid> )命令来查看你的进程正在做什么。在Mac上,你可以执行echo "thread backtrace all" | lldb -p <pid> 来查看类似的东西。输出将是你进程中所有线程的堆栈。这适用于任何进程,而不仅仅是 Python 程序。对于你的Python程序,你会看到底层的C函数,而不是你的Python函数。在某些情况下,以这种方式检查几次堆栈可能会告诉你你的进程是否卡住了,或者哪里慢了,只要你能对自己的代码进行翻译。但是这样做只能提供一个单一的时间样本。由于进程是持续执行的,你的样本可能在你每次运行命令时都会发生变化(除非它被阻断或者你只是碰巧非常幸运)。

采样剖析器和周围的工具在一段时间内对系统进行多次快照,然后为你提供查看这些数据的能力,并了解你的代码在哪里慢。

py-spy

Py-spy 使用系统调用 (process_vm_readv on Linux,vm_read on OSX,ReadProcessMemory on Windows) 来获取调用堆栈,然后将这些信息转化为你在源代码中看到的 Python 函数调用。它每秒采样多次,所以它有很好的机会看到你的程序随着时间的推移将处于各种状态。为了提高速度,它是用Rust编写的。

将 py-spy 纳入你的项目非常简单,它可以通过pip 进行安装。为了向你展示如何使用它,我已经创建了一些示例代码来剖析和观察 py-spy 如何告诉我们一个正在运行的 Python 进程。如果你想跟着做,你可以很容易地复制这些步骤。

首先,我使用py-env和本项目的pyenv-virtualenv 插件设置了一个新的虚拟环境。你可以这样做,也可以用你喜欢的工具设置一个虚拟环境。

# whichever Python version you prefer
pyenv install 3.8.7             
# make our virtualenv (with above version)
pyenv virtualenv 3.8.7 py-spy   
# activate it
pyenv activate py-spy           
# install py-spy
pip install py-spy              
# make sure we pick up the commands in our path
pyenv rehash                    

这就是全部,我们现在有了可用的工具。如果你运行py-spy,你可以看到常用的用法。

$ py-spy
py-spy 0.3.4
Sampling profiler for Python programs

USAGE:
    py-spy <SUBCOMMAND>

OPTIONS:
    -h, --help       Prints help information
    -V, --version    Prints version information

SUBCOMMANDS:
    record    Records stack trace information to a flamegraph, speedscope or raw file
    top       Displays a top like view of functions consuming CPU
    dump      Dumps stack traces for a target program to stdout
    help      Prints this message or the help of the given subcommand(s)

一个例子

为了演示 py-spy,我写了一个简单的长期运行的过程,它将消耗来自加密货币交易所的流媒体价格,并每分钟生成一条记录(这也被称为一个条形图)。该条形图包含过去一分钟的各种信息。条形图包括最高、最低和最后的价格,成交量,以及成交量加权平均价格(VWAP)。现在,代码只记录这些值,但可以扩展到更新一个数据库。虽然它很简单,但它是一个有用的例子,因为加密货币24小时都在交易,并将给我们提供真实世界的数据来工作。

我正在使用Coinbase Pro API for Python来访问来自WebSocket feed的数据。这里有一个初稿,其中留有一些调试代码(还有两种生成VWAP的方法,一种是低效的(_vwap 方法),一种是更高效的)。让我们看看py-spy是否揭示了这段代码使用了多少时间。

这段代码最终将为WebSocket客户端生成一个线程。asyncio循环将为下一个分钟边界设置一个计时器,以告诉客户端记录酒吧数据。它将一直运行,直到你杀死它(例如,用Ctrl-C)。

#!/usr/bin/env python

import argparse
import functools
import datetime
import asyncio
import logging

import arrow
import cbpro


class BarClient(cbpro.WebsocketClient):
    def __init__(self, **kwargs):
        super().__init__(**kwargs)
        self._bar_volume = 0
        self._weighted_price = 0.0
        self._ticks = 0
        self._bar_high = None
        self._bar_low = None
        self.last_msg = {}

        self._pxs = []
        self._volumes = []

    def next_minute_delay(self):
        delay = (arrow.now().shift(minutes=1).floor('minutes') - arrow.now())
        return (delay.seconds + delay.microseconds/1e6)

    def _vwap(self):
        if len(self._pxs):
            wp = sum([x*y for x,y in zip(self._pxs, self._volumes)])
            v = sum(self._volumes)

            return wp/v

    def on_message(self, msg):
        if 'last_size' in msg and 'price' in msg:
            last_size = float(msg['last_size'])
            price = float(msg['price'])
            self._bar_volume += last_size
            self._weighted_price += last_size * price
            self._ticks += 1
            if self._bar_high is None or price > self._bar_high:
                self._bar_high = price
            if self._bar_low is None or price < self._bar_low:
                self._bar_low = price
            self._pxs.append(price)
            self._volumes.append(last_size)
            logging.debug("VWAP: %s", self._vwap())
        self.last_msg = msg
        logging.debug("Message: %s", msg)

    def on_bar(self, loop):
        if self.last_msg is not None:
            if self._bar_volume == 0:
                self.last_msg['vwap'] = None
            else:
                self.last_msg['vwap'] = self._weighted_price/self._bar_volume
            self.last_msg['bar_bar_volume'] = self._bar_volume
            self.last_msg['bar_ticks'] = self._ticks
            self.last_msg['bar_high'] = self._bar_high
            self.last_msg['bar_low'] = self._bar_low
            last = self.last_msg.get('price')
            if last:
                last = float(last)
            self._bar_high = last
            self._bar_low = last
            logging.info("Bar: %s", self.last_msg)
        self._bar_volume = 0
        self._weighted_price = 0.0
        self._ticks = 0
        self._pxs.clear()
        self._volumes.clear()
        // reschedule
        loop.call_at(loop.time() + self.next_minute_delay(),
                     functools.partial(self.on_bar, loop))
        
def main():
    argparser = argparse.ArgumentParser()
    argparser.add_argument("--product", default="BTC-USD",
                           help="coinbase product")
    argparser.add_argument('-d', "--debug", action='store_true',
                           help="debug logging")
    args = argparser.parse_args()

    cfg = {"format": "%(asctime)s - %(levelname)s -  %(message)s"}
    if args.debug:
        cfg["level"] = logging.DEBUG
    else:
        cfg["level"] = logging.INFO

    logging.basicConfig(**cfg)

    client = BarClient(url="wss://ws-feed.pro.coinbase.com",
                       products=args.product,
                       channels=["ticker"])

    loop = asyncio.get_event_loop()
    loop.call_at(loop.time() + client.next_minute_delay(), functools.partial(client.on_bar, loop))
    loop.call_soon(client.start)

    try:
        loop.run_forever()
    finally:
        loop.close()

if __name__ == '__main__':
    main()

运行这个例子

为了运行这段代码,你需要安装一些额外的模块。cbpro模块是Coinbase APIs的一个简单的Python包装器。Arrow是一个很好的库,用来做日期时间逻辑。

pip install arrow cbpro

现在,你可以用调试日志来运行代码,希望能看到一些信息,这取决于交易所的繁忙程度。

 ./coinbase_client.py -d
2021-03-14 17:20:12,828 - DEBUG -  Using selector: KqueueSelector
-- Subscribed! --

2021-03-14 17:20:13,059 - DEBUG -  Message: {'type': 'subscriptions', 'channels': [{'name': 'ticker', 'product_ids': ['BTC-USD']}]}
2021-03-14 17:20:13,060 - DEBUG -  VWAP: 60132.57

剖析这个例子

现在,让我们回顾一下 py-spy 的命令。首先,使用dump命令将给我们一个快速的堆栈视图,翻译成Python函数。

这里有一个简短的附带说明,如果你使用的是Mac,你需要以sudo身份运行py-spy。在Linux上,这取决于你的安全设置。另外,由于我使用的是pyenv,我需要使用-E 标志将我的环境传递给sudo,这样它就可以在路径中找到正确的Python解释器和py-spy脚本。我在我的shell中使用ps 命令获得了我的进程的id(在我的例子中是97520)。

py-spy dump

 sudo -E py-spy dump -p 97520
Process 97520: /Users/mcw/.pyenv/versions/py-spy/bin/python ./coinbase_client.py -d
Python v3.8.7 (/Users/mcw/.pyenv/versions/3.8.7/bin/python3.8)

Thread 0x113206DC0 (idle): "MainThread"
    select (selectors.py:558)
    _run_once (asyncio/base_events.py:1823)
    run_forever (asyncio/base_events.py:570)
    main (coinbase_client.py:107)
    <module> (coinbase_client.py:113)
Thread 0x700009CAA000 (idle): "Thread-1"
    read (ssl.py:1101)
    recv (ssl.py:1226)
    recv (websocket/_socket.py:80)
    _recv (websocket/_core.py:427)
    recv_strict (websocket/_abnf.py:371)
    recv_header (websocket/_abnf.py:286)
    recv_frame (websocket/_abnf.py:336)
    recv_frame (websocket/_core.py:357)
    recv_data_frame (websocket/_core.py:323)
    recv_data (websocket/_core.py:310)
    recv (websocket/_core.py:293)
    _listen (cbpro/websocket_client.py:84)
    _go (cbpro/websocket_client.py:41)
    run (threading.py:870)
    _bootstrap_inner (threading.py:932)
    _bootstrap (threading.py:890)

你可以看到有两个线程在运行。一个在读取数据,另一个在运行循环中的select 。这只是在我们的程序被卡住的时候对剖析有用。不过有一个非常好的功能是,如果你给了它--locals 选项,它将显示任何局部变量,这对调试非常有帮助!

py-spy top

下一个要尝试的命令是top

sudo -E py-spy top -p 97520

这将带来一个与unix的top 命令非常相似的界面。在你的程序运行和 py-spy 收集样本的过程中,它将向你显示它所花费的时间。下面是我在30秒后的截图。

py-spy top output

py-spy记录

最后,你可以用 py-spy 记录数据,以便日后分析或输出。有一个原始格式、speedscope格式和一个flamegraph输出。你可以指定你想收集数据的时间(以秒为单位),或者只是让它收集数据,直到你用Ctrl-C退出程序。例如,这个命令将生成一个有用的小SVG文件flamegraph,你可以在网络浏览器中与之互动。

sudo -E py-spy record -p 97520 --output py-spy.svg

你还可以将数据以speedscope格式导出,然后上传到speedscope网络工具中进行进一步分析。这是一个很好的工具,可以互动地看到你的代码如何执行。

我鼓励你自己运行这段代码,玩玩speedscope工具和SVG输出,但这里有两个屏幕截图,有助于解释它是如何工作的。第一个视图是整体的SVG输出。如果你把鼠标悬停在单元格上,就会显示功能细节。你可以看到,大部分时间是在WebSocket客户端_listen 方法中度过的。但是on_message 方法显示在它的右边(用箭头指定)

py-spy svg输出

如果我们点击它,我们会得到一个详细的视图。

py-spy svg详细输出

在我的例子中,我看到我的列表理解和记录中不需要的_vwap 方法在配置文件中显示得相当高。我可以很容易地删除这个方法(以及我所追踪的额外的价格和数量),因为VWAP可以只用一个运行中的产品和总数量来计算(正如我在代码中已经做的那样)。同样有趣的是,当脚本在调试模式下运行时,记录需要多少时间呢?

总结

综上所述,我鼓励你在你的一些代码中尝试使用py-spy。如果你试图预测你的代码将在哪里花费时间,你的正确性如何?是否有任何让你吃惊的发现?也许可以将 py-spy 的输出与像 line_profiler 这样的确定性剖析器进行比较。

我希望这个关于 py-spy 的概述对你有所帮助,并希望你能在诊断自己代码的性能问题时部署这个工具。

The postProfiling Python code with py-spyappeared first onwrighters.io.