Python性能分析

分析一个程序的性能时基本归纳为四个方面:

  • 程序运行的快吗
  • 性能瓶颈在哪
  • 使用了多少内存
  • 哪里有内存泄露

下面介绍一些性能分析工具.

基本时间分析

time

time 是linux下可以测量程序运行时间的程序.执行结果有三个部分(详细用法可以查询(man time):

  • real:值表示从程序开始到程序执行结束时所消耗的时间,包括CPU的用时
  • user:值表示程序本身,以及它所调用的库中的子例程使用的时间
  • sys:是由程序直接或间接调用的系统调用执行的时间

如果 sys + user远远小于real的话,就有可能是由于io等待导致的.


In [27]:
%%writefile slow_app.py

import sys
import time


def mock_download():
    for i in range(5):
        time.sleep(1)


def mock_database():
    for i in range(20):
        time.sleep(0.1)


def mock_calcate():
    for i in range(100000000):
        pass


def main():
    mock_download()
    mock_database()
    mock_calcate()


if __name__ == "__main__":
    sys.exit(main())


Overwriting slow_app.py

In [13]:
!time -p python slow_app.py


real 8.72
user 1.66
sys 0.00

上面可以初步看到程序本身执行时间很短,大部分时间在等待写什么. 只能看到一个大概,不能定位到具体代码.

contextmanager

使用python的上下文管理器机制对代码进行耗时度量:

  • __enter__:记录开始时间
  • __exit__: 记录结束时间

In [1]:
%%writefile timer.py

import time


class Timer(object):
    def __init__(self, verbose=False):
        self.verbose = verbose
    
    def __enter__(self):
        self.start = time.time()
        return self
    
    def __exit__(self, *args):
        self.end = time.time()
        self.secs = self.end - self.start
        self.msecs = self.secs * 1000  # millisecs
        if self.verbose:
            print('elapsed time: %f ms', self.msecs)


Overwriting timer.py

In [2]:
from timer import Timer
with Timer() as t:
    for i in range(1000000):
        pass
print('elasped time %s s',t.secs)


elasped time %s s 0.04282546043395996

可以将耗时写到日志里,这样在写代码的时候对关键的逻辑处(数据库、网络等)进行如上改写,然后通过分析日志排查性能问题. 当然也可以扩展一下将每次性能数据写入数据库分析.

line_profiler

line_profiler可以分析每一行代码的执行耗时信息.

  • 为了使用line_profiler,使用pip install line_profiler进行安装. 安装成功后可以看到叫做kernprof的可执行程序.
  • 在使用工具测试代码性能的时候, 需要给函数加上@profile装饰器.(不需要显示import任何模块,kernprof会自动注入的)

In [28]:
%%writefile slow_app_for_profiler.py

import sys
import time

@profile
def mock_download():
    for i in range(5):
        time.sleep(1)

@profile
def mock_database():
    for i in range(20):
        time.sleep(0.1)


@profile
def main():
    mock_download()
    mock_database()

if __name__ == "__main__":
    sys.exit(main())


Writing slow_app_for_profiler.py

In [29]:
!pip install line_profiler


Requirement already satisfied: line_profiler in /usr/local/lib/python3.6/site-packages
Requirement already satisfied: IPython>=0.13 in /usr/local/lib/python3.6/site-packages (from line_profiler)
Requirement already satisfied: simplegeneric>0.8 in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: setuptools>=18.5 in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: pexpect; sys_platform != "win32" in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: decorator in /root/.local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: prompt-toolkit<2.0.0,>=1.0.4 in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: pickleshare in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: pygments in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: traitlets>=4.2 in /usr/local/lib/python3.6/site-packages (from IPython>=0.13->line_profiler)
Requirement already satisfied: ptyprocess>=0.5 in /usr/local/lib/python3.6/site-packages (from pexpect; sys_platform != "win32"->IPython>=0.13->line_profiler)
Requirement already satisfied: six>=1.9.0 in /usr/local/lib/python3.6/site-packages (from prompt-toolkit<2.0.0,>=1.0.4->IPython>=0.13->line_profiler)
Requirement already satisfied: wcwidth in /usr/local/lib/python3.6/site-packages (from prompt-toolkit<2.0.0,>=1.0.4->IPython>=0.13->line_profiler)
Requirement already satisfied: ipython-genutils in /usr/local/lib/python3.6/site-packages (from traitlets>=4.2->IPython>=0.13->line_profiler)

In [30]:
!kernprof -l -v slow_app_for_profiler.py


Wrote profile results to slow_app_for_profiler.py.lprof
Timer unit: 1e-06 s

Total time: 5.00674 s
File: slow_app_for_profiler.py
Function: mock_download at line 5

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     5                                           @profile
     6                                           def mock_download():
     7         6           31      5.2      0.0      for i in range(5):
     8         5      5006712 1001342.4    100.0          time.sleep(1)

Total time: 2.01799 s
File: slow_app_for_profiler.py
Function: mock_database at line 10

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    10                                           @profile
    11                                           def mock_database():
    12        21          226     10.8      0.0      for i in range(20):
    13        20      2017764 100888.2    100.0          time.sleep(0.1)

Total time: 7.02506 s
File: slow_app_for_profiler.py
Function: main at line 16

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    16                                           @profile
    17                                           def main():
    18         1      5006790 5006790.0     71.3      mock_download()
    19         1      2018268 2018268.0     28.7      mock_database()

-l选项告诉kernprof注入@profile到脚本里. -v告诉kernprof显示执行结果到控制台.

  • Line #:行号.
  • Hits: 这行代码运行次数.
  • Time: 这一行总耗时
  • Per Hit: 本行代码执行一次耗时.
  • % Time:本行耗时占总耗时(函数耗时)百分比.
  • Line Contents: 代码

从结果可以很清楚的看到每一行的耗时, 这个对于一般的脚本很方便, 但是对于django项目怎么办呢:

大概瞄了一眼django-devserver使用的是LineProfiler,我们可以在代码层面加入LineProfiler.

memory_profiler

memory_profiler 分析每一行内存消耗.


In [26]:
!pip install  memory_profiler psutil


Requirement already satisfied: memory_profiler in /usr/local/lib/python3.6/site-packages
Requirement already satisfied: psutil in /root/.local/lib/python3.6/site-packages

In [31]:
!python -m memory_profiler slow_app_for_profiler.py


Filename: slow_app_for_profiler.py

Line #    Mem usage    Increment   Line Contents
================================================
     5   26.695 MiB    0.000 MiB   @profile
     6                             def mock_download():
     7   26.695 MiB    0.000 MiB       for i in range(5):
     8   26.695 MiB    0.000 MiB           time.sleep(1)


Filename: slow_app_for_profiler.py

Line #    Mem usage    Increment   Line Contents
================================================
    10   26.695 MiB    0.000 MiB   @profile
    11                             def mock_database():
    12   26.695 MiB    0.000 MiB       for i in range(20):
    13   26.695 MiB    0.000 MiB           time.sleep(0.1)


Filename: slow_app_for_profiler.py

Line #    Mem usage    Increment   Line Contents
================================================
    16   26.695 MiB    0.000 MiB   @profile
    17                             def main():
    18   26.695 MiB    0.000 MiB       mock_download()
    19   26.695 MiB    0.000 MiB       mock_database()


内存泄露