🚴 Call stack profiler for Python. Shows you why your code is slow!

Joe Rickerby

Last update: Jan 1, 2023

Related tags

Monitoring python profile django performance profiler

Overview

pyinstrument

Pyinstrument is a Python profiler. A profiler is a tool to help you 'optimize' your code - make it faster. It sounds obvious, but to get the biggest speed increase you should focus on the slowest part of your program. Pyinstrument helps you find it!

Installation

pip install pyinstrument

Pyinstrument supports Python 2.7 and 3.3+.

To run Pyinstrument from a git checkout, there's a build step. Take a look at Contributing for more info.

How to use it

Profile a Python script

Call Pyinstrument directly from the command line. Instead of writing python script.py, type pyinstrument script.py. Your script will run as normal, and at the end (or when you press ^C), Pyinstrument will output a colored summary showing where most of the time was spent.

Here are the options you can use:

Usage: pyinstrument [options] scriptfile [arg] ...

Options:
  --version             show program's version number and exit
  -h, --help            show this help message and exit
  --load-prev=ID        Instead of running a script, load a previous report
  -m MODULE_NAME        run library module as a script, like 'python -m
                        module'
  -o OUTFILE, --outfile=OUTFILE
                        save to <outfile>
  -r RENDERER, --renderer=RENDERER
                        how the report should be rendered. One of: 'text',
                        'html', 'json', or python import path to a renderer
                        class
  -t, --timeline        render as a timeline - preserve ordering and don't
                        condense repeated calls
  --hide=EXPR           glob-style pattern matching the file paths whose
                        frames to hide. Defaults to '*/lib/*'.
  --hide-regex=REGEX    regex matching the file paths whose frames to hide.
                        Useful if --hide doesn't give enough control.
  --show-all            (text renderer only) show external library code
  --unicode             (text renderer only) force unicode text output
  --no-unicode          (text renderer only) force ascii text output
  --color               (text renderer only) force ansi color text output
  --no-color            (text renderer only) force no color text output

Protip: -r html will give you a interactive profile report as HTML - you can really explore this way!

Profile a specific chunk of code

Pyinstrument also has a Python API. Just surround your code with Pyinstrument, like this:

from pyinstrument import Profiler

profiler = Profiler()
profiler.start()

# code you want to profile

profiler.stop()

print(profiler.output_text(unicode=True, color=True))

(You can omit the unicode and color flags if your output/terminal does not support them.)

Protip: To explore the profile in a web browser, use profiler.open_in_browser(). To save this HTML for later, use profiler.output_html().

Profile a web request in Django

To profile Django web requests, add pyinstrument.middleware.ProfilerMiddleware to MIDDLEWARE_CLASSES in your settings.py.

Once installed, add ?profile to the end of a request URL to activate the profiler. Your request will run as normal, but instead of getting the response, you'll get pyinstrument's analysis of the request in a web page.

If you're writing an API, it's not easy to change the URL when you want to profile something. In this case, add PYINSTRUMENT_PROFILE_DIR = 'profiles' to your settings.py. Pyinstrument will profile every request and save the HTML output to the folder profiles in your working directory.

If you want to show the profiling page depending on the request you can define PYINSTRUMENT_SHOW_CALLBACK as dotted path to a function used for determining whether the page should show or not. You can provide your own function callback(request) which returns True or False in your settings.py.

def custom_show_pyinstrument(request):
    return request.user.is_superuser


PYINSTRUMENT_SHOW_CALLBACK = "%s.custom_show_pyinstrument" % __name__

Profile a web request in Flask

A simple setup to profile a Flask application is the following:

from flask import Flask, g, make_response, request
app = Flask(__name__)

@app.before_request
def before_request():
    if "profile" in request.args:
        g.profiler = Profiler()
        g.profiler.start()


@app.after_request
def after_request(response):
    if not hasattr(g, "profiler"):
        return response
    g.profiler.stop()
    output_html = g.profiler.output_html()
    return make_response(output_html)

This will check for the ?profile query param on each request and if found, it starts profiling. After each request where the profiler was running it creates the html output and returns that instead of the actual response.

Profile something else?

I'd love to have more ways to profile using Pyinstrument - e.g. other web frameworks. PRs are encouraged!

How is it different to `profile` or `cProfile`?

Statistical profiling (not tracing)

Pyinstrument is a statistical profiler - it doesn't track every function call that your program makes. Instead, it's recording the call stack every 1ms.

That gives some advantages over other profilers. Firstly, statistical profilers are much lower-overhead than tracing profilers.

	Django template render × 4000	Overhead
Base	`████████████████` 0.33s

pyinstrument	`████████████████████` 0.43s	30%
cProfile	`█████████████████████████████` 0.61s	84%
profile	`██████████████████████████████████...██` 6.79s	2057%

But low overhead is also important because it can distort the results. When using a tracing profiler, code that makes a lot of Python function calls invokes the profiler a lot, making it slower. This distorts the results, and might lead you to optimise the wrong part of your program!

Full-stack recording

The standard Python profilers profile and cProfile show you a big list of functions, ordered by the time spent in each function. This is great, but it can be difficult to interpret why those functions are getting called. It's more helpful to know why those functions are called, and which parts of user code were involved.

For example, let's say I want to figure out why a web request in Django is slow. If I use cProfile, I might get this:

151940 function calls (147672 primitive calls) in 1.696 seconds

   Ordered by: cumulative time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    1.696    1.696 profile:0(<code object <module> at 0x1053d6a30, file "./manage.py", line 2>)
        1    0.001    0.001    1.693    1.693 manage.py:2(<module>)
        1    0.000    0.000    1.586    1.586 __init__.py:394(execute_from_command_line)
        1    0.000    0.000    1.586    1.586 __init__.py:350(execute)
        1    0.000    0.000    1.142    1.142 __init__.py:254(fetch_command)
       43    0.013    0.000    1.124    0.026 __init__.py:1(<module>)
      388    0.008    0.000    1.062    0.003 re.py:226(_compile)
      158    0.005    0.000    1.048    0.007 sre_compile.py:496(compile)
        1    0.001    0.001    1.042    1.042 __init__.py:78(get_commands)
      153    0.001    0.000    1.036    0.007 re.py:188(compile)
  106/102    0.001    0.000    1.030    0.010 __init__.py:52(__getattr__)
        1    0.000    0.000    1.029    1.029 __init__.py:31(_setup)
        1    0.000    0.000    1.021    1.021 __init__.py:57(_configure_logging)
        2    0.002    0.001    1.011    0.505 log.py:1(<module>)

It's often hard to understand how your own code relates to these traces.

Pyinstrument records the entire stack, so tracking expensive calls is much easier. It also hides library frames by default, letting you focus on your app/module is affecting performance.

  _     ._   __/__   _ _  _  _ _/_   Recorded: 14:53:35  Samples:  131
 /_//_/// /_\ / //_// / //_'/ //    Duration: 3.131     CPU time: 0.195
/   _/                    v3.0.0b3

Program: examples/django_example/manage.py runserver --nothreading --noreload

3.131 <module>  manage.py:2
└─ 3.118 execute_from_command_line  django/core/management/__init__.py:378
      [473 frames hidden]  django, socketserver, selectors, wsgi...
         2.836 select  selectors.py:365
         0.126 _get_response  django/core/handlers/base.py:96
         └─ 0.126 hello_world  django_example/views.py:4

'Wall-clock' time (not CPU time)

Pyinstrument records duration using 'wall-clock' time. When you're writing a program that downloads data, reads files, and talks to databases, all that time is included in the tracked time by pyinstrument.

That's really important when debugging performance problems, since Python is often used as a 'glue' language between other services. The problem might not be in your program, but you should still be able to find why it's slow.

How does it work?

Pyinstrument interrupts the program every 1ms and records the entire stack at that point. It does this using a C extension and PyEval_SetProfile, but only taking readings every 1ms. Check out this blog post for more info.

You might be surprised at how few samples make up a report, but don't worry, it won't decrease accuracy. The default interval of 1ms is a lower bound for recording a stackframe, but if there is a long time spent in a single function call, it will be recorded at the end of that call. So effectively those samples were 'bunched up' and recorded at the end.

Known issues

Profiling code inside a Docker container can cause some strange results, because the gettimeofday syscall that pyinstrument uses is slow in that environment. See #83
When using pyinstrument script.py where script.py contains a class serialized with pickle, you might encounter errors because the serialisation machinery doesn't know where __main__ is. See this issue for workarounds

Changelog

v3.3.0

Fixed issue with pyinstrument -m module, where pyinstrument wouldn't find modules in the current directory.
Dropped support for Python 2.7 and 3.5. Old versions will remain available on PyPI, and pip should choose the correct one automatically.

v3.2.0

Added the ability to track time in C functions. Minor note - Pyinstrument will record time spent C functions as 'leaf' functions, due to a limitation in how Python records frames. Python -> C -> Python is recorded as Python -> Python, but Python -> Python -> C will be attributed correctly. (#103)

v3.1.2

Fix <__array_function__ internals> frames appearing as app code in reports

v3.1.1

Added support for timeline mode on HTML and JSON renderers
Released as a tarball as well as a universal wheel

v3.1.0

Added PYINSTRUMENT_SHOW_CALLBACK option on the Django middleware to add a condition to showing the profile (could be used to run pyinstrument on a live server!)
Fixed bug in the Django middleware where file would not be written because of a unicode error

v3.0.3

Fixed bug with the Django middleware on Windows where profiling would fail because we were trying to put an illegal character '?' in the profile path. (#66)

v3.0.2

Add --show and --show-regex options, to mark certain files to be displayed. This helps to profile inside specific modules, while hiding others. For example, pyinstrument --show '*/sympy/*' script.py.

v3.0.1

Fix #60: pass all arguments after -m module_name to the called module
Fix crash during HTML/JSON output when no frames were captured.

v3.0.0

Pyinstrument will now hide traces through libraries that you're using by default. So instead of showing you loads of frames going through the internals of something external e.g. urllib, it lets you focus on your code.

Before After

To go back to the old behaviour, use --show-all on the command line.
'Entry' frames of hidden groups are shown, so you know which call is the problem
Really slow frames in the groups are shown too, e.g. the 'read' call on the socket
Application code is highlighted in the console
Additional metrics are shown at the top of the trace - timestamp, number of samples, duration, CPU time

Hidden code is controlled by the --hide or --hide-regex options - matching on the path of the code files.

  --hide=EXPR           glob-style pattern matching the file paths whose
                        frames to hide. Defaults to '*/lib/*'.
  --hide-regex=REGEX    regex matching the file paths whose frames to hide.
                        Useful if --hide doesn't give enough control.

Outputting a timeline is supported from the command line.

  -t, --timeline        render as a timeline - preserve ordering and don't
                        condense repeated calls

Because there are a few rendering options now, you can load a previous profiling session using --load-prev - pyinstrument keeps the last 10 sessions.
Hidden groups can also call back into application code, that looks like this:
(internal) When recording timelines, frame trees are completely linear now, allowing for the creation of super-accurate frame charts.
(internal) The HTML renderer has been rewritten as a Vue.js app. All the console improvements apply to the HTML output too, plus it's interactive.
(internal) A lot of unit and integration tests added!

Yikes! See #49 for the gory details. I hope you like it.

v2.3.0

Big refactor!
- Recorders have been removed. The frame recording is now internal to the Profiler object. This means the 'frame' objects are more general-purpose, which paves the way for...
- Processors! These are functions that mutate the tree to sculpt the output. They are used by the renderers to filter the output to the correct form. Now, instead of a time-aggregating recorder, the profiler just uses timeline-style recording (this is lower-overhead anyway) and the aggregation is done as a processing step.
- The upshot of this is that it's now way easier to alter the tree to filter stuff out, and do more advanced things like combining frames that we don't care about. More features to come that use this in v3.0!
Importlib frames are removed - you won't see them at all. Their children are retained, so imports are just transparent.
Django profile file name is now limited to a hundred of characters (#50)
Fix bug with --html option (#53)
Add --version command line option

v2.2.1

Fix crash when using on the command line.

v2.2.0

Added support for JSON output. Use pyinstrument --renderer=json scriptfile.py. PR
@iddan has put together an interactive viewer using the JSON output!
When running pyinstrument --html and you don't pipe the output to a file, pyinstrument will write the console output to a temp file and open that in a browser.

v2.1.0

Added support for running modules with pyinstrument via the command line. The new syntax is the -m flag e.g. pyinstrument -m module_name! PR

v2.0.4

Fix crashes due to multi-threaded use of pyinstrument. The fix is in the C extension, over at https://github.com/joerick/pyinstrument_cext/pull/3

v2.0.3

Pyinstrument can now be used in a with block.

For example:

profiler = pyinstrument.Profiler()
with profiler:
    # do some work here...
print(profiler.output_text())

Middleware fix for older versions of Django

v2.0.2

Fix for max recursion error when used to profile programs with a lot of frames on the stack.

v2.0.1

Ensure license is included in the sdist.

v2.0.0

Pyinstrument uses a new profiling mode. Rather than using signals, pyintrument uses a new statistical profiler built on PyEval_SetProfile. This means no more main thread restriction, no more IO errors when using Pyinstrument, and no need for a separate more 'setprofile' mode!
Renderers. Users can customize Pyinstrument to use alternative renderers with the renderer argument on Profiler.output(), or using the --renderer argument on the command line.
Recorders. To support other use cases of Pyinstrument (e.g. flame charts), pyinstrument now has a 'timeline' recorder mode. This mode records captured frames in a linear way, so the program execution can be viewed on a timeline.

v0.13

pyinstrument command. You can now profile python scripts from the shell by running $ pyinstrument script.py. This is now equivalent to python -m pyinstrument. Thanks @asmeurer!

v0.12

Application code is highlighted in HTML traces to make it easier to spot
Added PYINSTRUMENT_PROFILE_DIR option to the Django interface, which will log profiles of all requests to a file the specified folder. Useful for profiling API calls.
Added PYINSTRUMENT_USE_SIGNAL option to the Django interface, for use when signal mode presents problems.

Contributing

To run pyinstrument from the git repo or a source checkout, you must first run

python setup.py build

This compiles the Javascript code needed for the HTML output. You will need node installed (Node isn't required for the pip install as the Javascript is already pre-built in the wheel).

To setup a dev environment, do:

virtualenv --python=python3 env
. env/bin/activate
pip install -r requirements-dev.txt

To get some sample output:

pyinstrument examples/wikipedia_article_word_count.py

To run the tests:

pytest

Comments

feature request: dump and analyze

It is cool to print beautiful callstacks after we stop the profiler and call output_text/html. However, this only gives users one angle to look at data: full-depth (the whole callstack is printed) and caller-based (caller are parents, and callee functions are children on the tree).

In many cases, it is useful if we can analyze the same profiling data from different angles. For example:

(1) callee-based: for development in a big software framework, new functions are part of the framework, and are often at the bottom or at most in the middle of the call stack. If the profiler can only print callstack as caller-based, it would take a lot of time to find the data people care about.

(2) reduced callstack depth:if I only want a big picture, I may want to filter the results with an option like "depth=1" or "depth=2" etc, to print only functions at the top or bottom of the callstack. This option should work in either caller-based or callee-based stack. I know in web UI, the stack tree and fold and expand so it doesn't have to be changed, but the text mode doesn't have this option, and if we want to generate reports, we need to process text output.

In order to do this, we might want to separate result display into two steps. Step1: dump the data. Step 2: process the data.

Step 1 conceptually works as it does now: when profiler is stopped, it "dump" profiling data into a user specified or default file name.

Step 2: this requires a new tool that can understand the dump and display callstacks as a user desires.

So the point is to give users more angles to analyze without having to profile the same application multiple times.

Any thoughts?
enhancement

opened by codelol 14

caught AssertionError: Please raise an issue at https://github.com/joerick/pyinstrument/issues and let me know how you caused this error!

version: 4.1.1 I've been able to write a pytest scenario reproducing the error:

app code:

#!/usr/bin/env python3
from typing import Callable

from fastapi import FastAPI
from pyinstrument import Profiler
from starlette.requests import Request
from starlette.responses import Response


class ProfilingMiddleware:
    """ middleware that profiles request """

    def __init__(self, profiler_interval: float = 0.0001, ):
        self._profiler = Profiler(interval=profiler_interval)

    async def __call__(self, request: Request, call_next: Callable) -> Response:
        """ profile request """
        self._profiler.start()
        try:
            response = await call_next(request)
        finally:
            self._profiler.stop()
            output = self._profiler.output_text(color=True)
            print(output)
        return response


def create_app() -> FastAPI:
    """ application factory """
    app = FastAPI()

    @app.post('/')
    def endpoint():
        """ endpoint example """
        print('inside endpoint')
        return {}

    app.middleware('http')(ProfilingMiddleware())

    return app


APP = create_app()

test code:

from fastapi.testclient import TestClient

from app import APP

client = TestClient(APP)


def test_case() -> None:
    """ test 2 requests lead to an error while 1 passes """
    client.post(url='/')

    client.get(url='/dfhjhjkdfs')  # no matter which request you send you get the error (tried switching method/url etc)

executing the test leads to the following:

=================================================================================================================== test session starts ====================================================================================================================
platform darwin -- Python 3.9.6, pytest-6.2.5, py-1.11.0, pluggy-1.0.0 -- /Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/bin/python
cachedir: .pytest_cache
rootdir: /Users/erezm/repos/ec-notification-service, configfile: pytest.ini, testpaths: .
plugins: anyio-3.5.0, pythonpath-0.7.3
collected 1 item                                                                                                                                                                                                                                           

tests/feature_test/test_app_routes.py::test_case FAILED                                                                                                                                                                                              [100%]

========================================================================================================================= FAILURES =========================================================================================================================
________________________________________________________________________________________________________________________ test_case _________________________________________________________________________________________________________________________
Traceback (most recent call last):
  File "/Users/erezm/repos/ec-notification-service/tests/feature_test/test_app_routes.py", line 12, in test_case
    client.get(url='/dfhjhjkdfs')
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/requests/sessions.py", line 555, in get
    return self.request('GET', url, **kwargs)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/testclient.py", line 468, in request
    return super().request(
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/requests/sessions.py", line 542, in request
    resp = self.send(prep, **send_kwargs)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/requests/sessions.py", line 655, in send
    r = adapter.send(request, **kwargs)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/testclient.py", line 266, in send
    raise exc
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/testclient.py", line 263, in send
    portal.call(self.app, scope, receive, send)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/anyio/from_thread.py", line 240, in call
    return cast(T_Retval, self.start_task_soon(func, *args).result())
  File "/Users/erezm/.pyenv/versions/3.9.6/lib/python3.9/concurrent/futures/_base.py", line 445, in result
    return self.__get_result()
  File "/Users/erezm/.pyenv/versions/3.9.6/lib/python3.9/concurrent/futures/_base.py", line 390, in __get_result
    raise self._exception
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/anyio/from_thread.py", line 187, in _call_func
    retval = await retval
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/fastapi/applications.py", line 208, in __call__
    await super().__call__(scope, receive, send)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/applications.py", line 112, in __call__
    await self.middleware_stack(scope, receive, send)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/middleware/errors.py", line 181, in __call__
    raise exc
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/middleware/errors.py", line 159, in __call__
    await self.app(scope, receive, _send)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/starlette/middleware/base.py", line 55, in __call__
    response = await self.dispatch_func(request, call_next)
  File "/Users/erezm/repos/ec-notification-service/src/app.py", line 24, in __call__
    output = self._profiler.output_text(color=True)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/profiler.py", line 295, in output_text
    return self.output(
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/profiler.py", line 323, in output
    return renderer.render(session)
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/renderers/console.py", line 34, in render
    frame = self.preprocess(session.root_frame())
  File "/Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/lib/python3.9/site-packages/pyinstrument/session.py", line 145, in root_frame
    assert root_frame is None, ASSERTION_MESSAGE
AssertionError: Please raise an issue at https://github.com/joerick/pyinstrument/issues and let me know how you caused this error!
------------------------------------------------------------------------------------------------------------------- Captured stdout call -------------------------------------------------------------------------------------------------------------------
inside endpoint

  _     ._   __/__   _ _  _  _ _/_   Recorded: 19:21:02  Samples:  15
 /_//_/// /_\ / //_// / //_'/ //     Duration: 0.002     CPU time: 0.002
/   _/                      v4.1.1

Program: /Users/erezm/.local/share/virtualenvs/ec-notification-service-6WygbirR/bin/pytest -k test_app_routes -vv

0.002 run_forever  asyncio/base_events.py:583
|- 0.001 _run_once  asyncio/base_events.py:1815
|     [49 frames hidden]  asyncio, starlette, fastapi, anyio, t...
|        0.000 __call__  starlette/middleware/base.py:20
|        `- 0.000 __call__  app.py:17
|           `- 0.000 stop  pyinstrument/profiler.py:136
|                 [3 frames hidden]  pyinstrument
`- 0.000 [self]  


=================================================================================================================== slowest 5 durations ====================================================================================================================
0.07s call     tests/feature_test/test_app_routes.py::test_case
0.00s setup    tests/feature_test/test_app_routes.py::test_case
0.00s teardown tests/feature_test/test_app_routes.py::test_case
================================================================================================================= short test summary info ==================================================================================================================
FAILED tests/feature_test/test_app_routes.py::test_case - AssertionError: Please raise an issue at https://github.com/joerick/pyinstrument/issues and let me know how you caused this error!
==================================================================================================================== 1 failed in 0.32s =====================================================================================================================

note that the test passes if a single request is issued.

my environment:

Package            Version
------------------ ---------
anyio              3.5.0
asgiref            3.4.1
astroid            2.8.6
attrs              21.4.0
certifi            2021.10.8
charset-normalizer 2.0.10
click              8.0.3
fastapi            0.70.0
gunicorn           20.0.4
h11                0.12.0
idna               3.3
iniconfig          1.1.1
isort              5.10.1
lazy-object-proxy  1.7.1
mccabe             0.6.1
ntplib             0.4.0
packaging          21.3
pip                21.3.1
platformdirs       2.4.1
pluggy             1.0.0
prometheus-client  0.11.0
py                 1.11.0
pydantic           1.9.0
pyinstrument       4.1.1
pylint             2.11.1
pyparsing          3.0.6
pytest             6.2.5
pytest-pythonpath  0.7.3
python-multipart   0.0.5
redis              3.5.3
requests           2.26.0
setuptools         59.8.0
six                1.16.0
sniffio            1.2.0
starlette          0.16.0
starlette-exporter 0.8.2
texel-common       0.8.12
texel-logging      0.1.3
toml               0.10.2
typing_extensions  4.0.1
urllib3            1.26.8
uvicorn            0.15.0
wheel              0.37.1
wrapt              1.13.3

running on macOS 12.1 (though it reproduced on ubuntu machines as well)

opened by erez-marmor 12

Contributing instructions not working in a vanilla environment

Hello,

I thought I'd sit down this evening and knock out #119 but I was stopped when the Contributing instructions didn't work for me. After 20 minutes of troubleshooting I figured maybe the community here may have some quick insight to get me up and running.

I'm running with pyenv, created and activated an environment with Python 3.9.0 and I'm using node v15.5.0.

Here is the output of python setup.py build running in my local directory:


(pyinstrument) ➜  pyinstrument git:(master)  python setup.py build
running build
running build_py
7.3.0
Running command: npm install

added 1482 packages, removed 7 packages, and audited 1657 packages in 23s

17 vulnerabilities (10 low, 1 moderate, 6 high)

To address all issues, run:
  npm audit fix

Run `npm audit` for details.
Running command: npm run build

> [email protected] build
> vue-cli-service build

node:internal/modules/cjs/loader:928
  throw err;
  ^

Error: Cannot find module 'json-parse-even-better-errors'
Require stack:
- /Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/read-pkg/node_modules/parse-json/index.js
- /Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/read-pkg/index.js
- /Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/@vue/cli-service/lib/Service.js
- /Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/@vue/cli-service/bin/vue-cli-service.js
    at Function.Module._resolveFilename (node:internal/modules/cjs/loader:925:15)
    at Function.Module._load (node:internal/modules/cjs/loader:769:27)
    at Module.require (node:internal/modules/cjs/loader:997:19)
    at require (node:internal/modules/cjs/helpers:92:18)
    at Object.<anonymous> (/Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/read-pkg/node_modules/parse-json/index.js:3:18)
    at Module._compile (node:internal/modules/cjs/loader:1108:14)
    at Object.Module._extensions..js (node:internal/modules/cjs/loader:1137:10)
    at Module.load (node:internal/modules/cjs/loader:973:32)
    at Function.Module._load (node:internal/modules/cjs/loader:813:14)
    at Module.require (node:internal/modules/cjs/loader:997:19) {
  code: 'MODULE_NOT_FOUND',
  requireStack: [
    '/Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/read-pkg/node_modules/parse-json/index.js',
    '/Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/read-pkg/index.js',
    '/Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/@vue/cli-service/lib/Service.js',
    '/Users/steven.tartakovsky/code/pyinstrument/html_renderer/node_modules/@vue/cli-service/bin/vue-cli-service.js'
  ]
}
npm ERR! code 1
npm ERR! path /Users/steven.tartakovsky/code/pyinstrument/html_renderer
npm ERR! command failed
npm ERR! command sh -c vue-cli-service build

npm ERR! A complete log of this run can be found in:
npm ERR!     /Users/steven.tartakovsky/.npm/_logs/2021-02-14T02_01_54_525Z-debug.log
Traceback (most recent call last):
  File "/Users/steven.tartakovsky/code/pyinstrument/setup.py", line 70, in <module>
    setup(
  File "/Users/steven.tartakovsky/.pyenv/versions/pyinstrument/lib/python3.9/site-packages/setuptools/__init__.py", line 165, in setup
    return distutils.core.setup(**attrs)
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/distutils/core.py", line 148, in setup
    dist.run_commands()
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/distutils/dist.py", line 966, in run_commands
    self.run_command(cmd)
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/distutils/dist.py", line 985, in run_command
    cmd_obj.run()
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/distutils/command/build.py", line 135, in run
    self.run_command(cmd_name)
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/distutils/cmd.py", line 313, in run_command
    self.distribution.run_command(command)
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/distutils/dist.py", line 985, in run_command
    cmd_obj.run()
  File "/Users/steven.tartakovsky/code/pyinstrument/setup.py", line 38, in run
    self.check_call(['npm', 'run', 'build'], cwd=HTML_RENDERER_DIR)
  File "/Users/steven.tartakovsky/code/pyinstrument/setup.py", line 14, in check_call
    subprocess.check_call(args, **popen_kwargs)
  File "/Users/steven.tartakovsky/.pyenv/versions/3.9.0/lib/python3.9/subprocess.py", line 373, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command '['npm', 'run', 'build']' returned non-zero exit status 1.

opened by startakovsky 12

skip hidden frames

fixes #190

updated version of #211. It was easier to just start a new PR than it was to resolve the conflicts after the py 3.11 updates. From the original PR:

This adds a generic "hidden" property to the frame record objects. Currently this is only set to true if the frame has tracebackhide==True in it's locals dict, as discussed in https://github.com/joerick/pyinstrument/issues/190. Also adds a default processor that hides any frames with .hidden==True.

Not sure if this is the right approach overall, and very not sure if the changes to the c extension were the right ones. @joerick Feedback would be much appreciated.

I also added the .devcontainer dir that I came up with while developing these changes. This allows for developing pyinstrument in a container when using vscode (and maybe other ides?). Specifically, this allowed me to do stuff like simultaneously debug the python and c extension code (even though I'm developing on a mac), which was super useful. Dunno if you want this in the repo, I can remove it if you prefer.

opened by telamonian 10
Added asyncio support to cell magic

The current version of the pyinstrument magic does not support async code at all. It doesn't matter whether you have async_mode set to enabled or disabled, it will break because it will try to run in a new event loop.

This seems to be a known upstream issue but I don't think anyone is working on it: https://github.com/ipython/ipython/issues/11314

This modification is certainly very hacky, but it's working quite well for me and I don't foresee any issues with it. If it does cause issues, it doesn't do anything when using --async_mode=disabled :)

opened by wolph 10
Add support for IPython/Jupyter notebook magics
Example usage (works in ipython/notebook/lab):

%load_ext pyinstrument

%%pyinstrument def a(): b() c() def b(): d() def c(): d() def d(): e() def e(): time.sleep(1) a()

Extra care is taken to not profile jupyter running the code, which is the majority of the complexity of this commit.

Fixes: #153
opened by mlucool 10
Asyncio applications have a mysterious [SELF] function

The first function is labelled as [SELF] and i'm not sure how to interpret it. Is it how long the event loop took to get back to the function or something else?

For context, i'm creating a profiler before and closing it after every request in Sanic. Its a Flask-like asyncio powered web framework.

opened by AggressivelyMeows 10
Add option to lookup and run program from path

Uses runpy.run_path & shutil.which. Implements #97. Any comments on the implementation welcome.

Not sure about the name of the option (--path currently), and it would be good to include a test for it too, I assume. Hence marked as draft.

opened by chrish42 9
Feature request: multiple renderings

For the profiling workflow I'm creating, it would be super useful to be able to ask for multiple renderings of a report. For example, an HTML render to show to humans, and a JSON one for post-processing scripts to work from.

I'd be more than happy to do a pull request. The only thing that would need a bit of discussion beforehand is how to represent that in the command-line interface.

opened by chrish42 9

AssertionError when use flask+gunicorn+gevent

Hai ! I encount this AssertionError when I use pyinstrument to hook my flask app like the examples/flask_hello.py said.

AssertionError: Please raise an issue at http://github.com/pyinstrument/issues and let me know how you caused this error!

This error doesn't happen every time I send request. Instead, several consecutive requests occur once. Then Nginx will return 500 status code.

Here is the full trackback stack from gunicorn error.log file:

[2020-01-22 04:34:28 +0800] [26251] [ERROR] Error handling request /v2/services/xxxx/xxxx/get?key1=value1&key2=value2&key3=value3&__profile__
Traceback (most recent call last):
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/gunicorn/workers/base_async.py", line 55, in handle
    self.handle_request(listener_name, req, client, addr)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/gunicorn/workers/ggevent.py", line 143, in handle_request
    super().handle_request(listener_name, req, sock, addr)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/gunicorn/workers/base_async.py", line 106, in handle_request
    respiter = self.wsgi(environ, resp.start_response)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 2463, in __call__
    return self.wsgi_app(environ, start_response)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/werkzeug/middleware/proxy_fix.py", line 228, in __call__
    return self.app(environ, start_response)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 2449, in wsgi_app
    response = self.handle_exception(e)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 1866, in handle_exception
    reraise(exc_type, exc_value, tb)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/_compat.py", line 39, in reraise
    raise value
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 2446, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 1952, in full_dispatch_request
    return self.finalize_request(rv)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 1969, in finalize_request
    response = self.process_response(response)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/flask/app.py", line 2266, in process_response
    response = handler(response)
  File "/home/pyserver/www/wsgi.py", line 44, in after_request
    output_html = g.profiler.output_html()
  File "</home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/vendor/decorator.py:decorator-gen-9>", line 2, in output_html
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/util.py", line 37, in caller
    return func(*args, **kwargs)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/profiler.py", line 101, in output_html
    return renderers.HTMLRenderer().render(self.last_session)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/renderers/html.py", line 23, in render
    session_json = self.render_json(session)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/renderers/html.py", line 69, in render_json
    return json_renderer.render(session)
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/renderers/jsonrenderer.py", line 36, in render
    frame = self.preprocess(session.root_frame())
  File "/home/pyserver/.pyenv/versions/3.6.6/envs/envpy36/lib/python3.6/site-packages/pyinstrument/session.py", line 77, in root_frame
    assert root_frame is None, ASSERTION_MESSAGE
AssertionError: Please raise an issue at http://github.com/pyinstrument/issues and let me know how you caused this error!

Here is my gunicorn.conf.py file

import os
import multiprocessing

chdir = WSGI_APP_ROOT

daemon = True
accesslog = os.path.join(LOG_DIR, "access.log")
errorlog  = os.path.join(LOG_DIR, "error.log")

pidfile = os.path.join(RUN_DIR, "gunicorn.pid")

user  = 33  # www-data
group = 33  # www-data

bind = [ "unix:" + os.path.join(RUN_DIR, "gunicorn.sock") ]

workers = multiprocessing.cpu_count() * 2 + 1
worker_class = "gevent"
worker_connections = 1024
threads = multiprocessing.cpu_count() * 3 

timeout = 15
graceful_timeout = 15
keepalive = 5

Here is my wsgi.py module

PYINSTRUMENT_HOOK          = True
PYINSTRUMENT_PROFILE_FIELD = "__profile__"

from gevent.monkey import patch_all
patch_all()

import os
from werkzeug.middleware.proxy_fix import ProxyFix
from v2.app import create_app

app = create_app("development")

if PYINSTRUMENT_HOOK:

    from flask import g, request, make_response
    from pyinstrument import Profiler

    @app.before_request
    def before_request():
        if PYINSTRUMENT_PROFILE_FIELD in request.args:
            g.profiler = Profiler()
            g.profiler.start()

    @app.after_request
    def after_request(response):
        if not hasattr(g, "profiler"):
            return response
        g.profiler.stop()
        output_html = g.profiler.output_html()
        return make_response(output_html)

app.wsgi_app = ProxyFix(app.wsgi_app, x_for=1)

The requirements.txt

Flask==1.1.1
Werkzeug==0.15.4 
greenlet==0.4.15
gevent==1.4.0
gunicorn==20.0.4
pyinstrument==3.1.0

The pyenv version

Python 3.6.6

opened by zhongxinghong 9

Getting IOError

rahul@rahul-desktop { ~/pycharm-workspace/ceres_new }-> python -m pyinstrument ceres/sim/sim_definition.py Traceback (most recent call last): File "/usr/lib/python2.7/runpy.py", line 162, in run_module_as_main "main", fname, loader, pkg_name) File "/usr/lib/python2.7/runpy.py", line 72, in run_code exec code in run_globals File "/home/rahul/src/pyinstrument/pyinstrument/main.py", line 135, in main() File "/home/rahul/src/pyinstrument/pyinstrument/main.py", line 79, in main exec(code, globs, None) File "/home/rahul/src/pyinstrument/pyinstrument/main.py", line 25, in exec exec("exec code in globs, locs") File "", line 1, in File "ceres/sim/sim_definition.py", line 48, in main() File "ceres/sim/sim_definition.py", line 31, in main from aglyph.assembler import Assembler File "/usr/local/lib/python2.7/dist-packages/aglyph/init.py", line 61, in platform.platform())) File "/usr/lib/python2.7/platform.py", line 1576, in platform system,node,release,version,machine,processor = uname() File "/usr/lib/python2.7/platform.py", line 1273, in uname processor = _syscmd_uname('-p','') File "/usr/lib/python2.7/platform.py", line 1029, in _syscmd_uname output = string.strip(f.read()) IOError: [Errno 4] Interrupted system call Alarm clock

opened by rahul-paul 9
Fix show all

fixes #223

This PR address the hide/show bug that @joerick pointed out in #223. I'll open separate issues for the other discussed in that issue.

This turned out to be more complex than I would have thought for rendering related junk. In part this was because the --show-all cmd line option was initially busted. Passing --show-all on the cmd line will now ensure that show_all=True gets passed to the kwargs of the Renderer's constructor. I also fixed the behavior of the base Render's constructor when show_all=True. This together appears to fix the bug pointed out in #223. @joerick Can you please test this PR out when you have a sec and let me know if that part also seems fixed to you?

opened by telamonian 0

`FileNotFoundError` when calling profile.output_text

Apologies - I'm having trouble making a minimal reproducible example for this issue, but here's what I'm seeing:

In certain situations, when trying to render pyinstrument output as text I get a FileNotFoundError. In post mortem debugging the stack looks like:

-> ] = profile.output_text(unicode=True, color=True)
  <python path>/pyinstrument/profiler.py(295)output_text()
-> return self.output(
  <python path>/pyinstrument/profiler.py(323)output()
-> return renderer.render(session)
  <python path>/pyinstrument/renderers/console.py(51)render()
-> result += self.render_frame(self.root_frame)
  <python path>/pyinstrument/renderers/console.py(137)render_frame()
-> result += self.render_frame(child, indent=c_indent, child_indent=cc_indent)
  <python path>/pyinstrument/renderers/console.py(137)render_frame()
-> result += self.render_frame(child, indent=c_indent, child_indent=cc_indent)
  <python path>/pyinstrument/renderers/console.py(137)render_frame()
-> result += self.render_frame(child, indent=c_indent, child_indent=cc_indent)
  <python path>/pyinstrument/renderers/console.py(118)render_frame()
-> libraries=truncate(", ".join(frame.group.libraries), 40),
> <python path>/pyinstrument/frame.py(349)libraries()
-> if frame.file_path_short:
  <python path>/pyinstrument/frame.py(160)file_path_short()
-> candidate = os.path.relpath(self.file_path, path)
  <python path>/python3.9/posixpath.py(473)relpath()
-> path_list = [x for x in abspath(path).split(sep) if x]
  <python path>/python3.9/posixpath.py(380)abspath()
-> cwd = os.getcwd()

So, I don't entirely understand why os.getcwd() is failing but I don't think that's due to pyinstrument.

What is maybe strange to me is the Frame triggering the issue looks like:

Frame(identifier=Int64HashTable.factorize<built-in>0, time=0.002000, len(children)=0), group=FrameGroup(len(frames)=29)

And if I look on https://github.com/joerick/pyinstrument/blob/main/pyinstrument/frame.py#L160,

(Pdb) self.file_path
'<built-in>'
(Pdb) self._identifier_parts
['Int64HashTable.factorize', '<built-in>', '0']

Which makes me think that pyinstrument shouldn't be trying loop through sys.path and immediately set self._file_path_short = None. Is that the intended behavior here?

opened by gerrymanoim 0

option for CPU time

Pyinstrument records duration using ‘wall-clock’ time. When you’re writing a program that downloads data, reads files, and talks to databases, all that time is included in the tracked time by pyinstrument.

That’s really important when debugging performance problems, since Python is often used as a ‘glue’ language between other services.

In the other 50% of python programs out there, CPU efficiency is important. Sure, for a synchronous Python program, CPU and wall time are basically the same, and pyinstrument can be used to find the places consuming CPU.

However, for async programs, since pyinstrument only offers wall time, it cannot be used to find what code is consuming CPU. For this use case, attributing time to sleep() or network blocking is unwanted.

opened by belm0 0
Followup for IPython integration
I got some feedback from the guys I implemented #217 for:

For:

$ cat profiler.py import time def D(): time.sleep(0.7) def C(): __tracebackhide__ = True time.sleep(0.1) D() def B(): __tracebackhide__ = True time.sleep(0.1) C() def A(): time.sleep(0.1) B() A()

Profiler output:

1.004 <module> <string>:1 1.004 run_path runpy.py:245 1.001 _run_module_code runpy.py:89 1.001 _run_code runpy.py:63 1.001 <module> profiler.py:1 1.001 A profiler.py:16 0.700 D profiler.py:3 0.700 sleep None [2 frames hidden] <built-in> 0.301 sleep None [2 frames hidden] <built-in>

Inside A, we would like to see that a few frames (B&C) were hidden because of __tracebackhide__. We also suggest including a >way to expand hidden nodes in HTML format.

I see, sleep None. Should it be <built-in> instead? [Note: I don't see None in Jupyter notebook].

I'm not entirely sure what of the above is bugs, intended behavior, or new feature requests. The request for expandable hidden nodes in html format seems like a reasonable new feature. I can start looking into making that happen.

As for "Inside A, we would like to see that a few frames (B&C) were hidden because of __tracebackhide__", I think what they mean is that when a frame is hidden due to the __tracebackhide__ rule, the output should explicitly say that.

@joerick Can you please clarify exactly what the above example profiling output is currently saying about the hidden frames? I assume the first [2 frames hidden] <built-in> line is refering to the B and C scopes. Is that right? In that case, the <built-in> label is a bug, and should say <ipython built-in> (or something) instead. What does the second repeat of the [2 frames hidden] <built-in> refer to?
opened by telamonian 1

Having issues profiling FastAPI calls

First, thanks so much for your hard work on this great library. It is a fantastic addition to the python ecosystem!

I am implementing profiling in FastAPI as a middleware, listening for a header val or query arg like the example shows. My middleware setup is a little different, but is added to the call stack just the same

"""Middleware that enables on-demand app profiling when a profile header is passed."""

from fastapi import Request, Response
from fastapi.responses import HTMLResponse, PlainTextResponse
from pyinstrument import Profiler, renderers
from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint

from app.utils import ErrorReporter, Logger

PROFILING_INTERVAL = 0.001  # 1 millisecond
PROFILING_ASYNC_MODE = "enabled"


class ProfilingMiddleware(BaseHTTPMiddleware):
    """Middleware that enables on-demand app profiling when a profile header is passed."""

    async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response:
        """Middleware that enables on-demand app profiling when a profile header is passed."""
        try:
            profiling = self.should_profile(request)
            if profiling:
                profiler = Profiler(interval=PROFILING_INTERVAL, async_mode=PROFILING_ASYNC_MODE)
                profiler.start()
                await call_next(request)
                profiler.stop()
                return HTMLResponse(profiler.output_html())

        except Exception as exc:  # pylint: disable=broad-except
            ErrorReporter.report(exc)
            Logger.error(f"Could not profile endpoint: {str(exc)}")

        response = await call_next(request)
        return response

    @staticmethod
    def should_profile(request: Request) -> bool:
        """Return true if the profiling header or query param was passed."""
        return request.headers.get("X-Profile", False) or request.query_params.get("profile", False)

The profiling works -- in that it is added to the app call stack, is enabled, detects code, renders output. However, there is no useful output that I can get. Here are some examples, in html, and speedscope formats:

Screen Shot 2022-10-25 at 4 48 31 PM Screen Shot 2022-10-25 at 4 54 16 PM Screen Shot 2022-10-25 at 5 00 19 PM Screen Shot 2022-10-25 at 5 03 12 PM

So what is custom_route_logger you ask? It is the official FastAPI way to subclass the Request object, and is defined async, like this:

    def get_route_handler(self) -> Callable:
        """Use a custom route handler."""
        original_route_handler = super().get_route_handler()

        async def custom_route_handler(request: Request) -> Response:
            request = REDACTEDRequest(request.scope, request.receive)
            return await original_route_handler(request)

        return custom_route_handler

I know the problem comes from this async, and because it is ASGI middleware, I cannot take the async away. But I also cannot profile inside the application as-is.

The goal is to get a single profile of application code on a given api call. My question is, is there some sort of async setup I missed here, or is this an impossible task?

opened by coneybeare 6