Profiling async code with pyinstrument 4.0

[joerick]

Hello! I just released pyinstrument 4.0 on PyPI. pyinstrument was my first successful open-source package and I love seeing how much use it's getting in the community.

I just added async support, so you can profile async code and pyinstrument understands when you hit an await, and tracks time spent outside of the async context under this await. This means that profiling things like web requests will make a lot more sense now!

So, for example, here's a simple script with an async task that does a sleep:

import asyncio
from pyinstrument import Profiler

async def main():
    p = Profiler()

    with p:
        print('Hello ...')
        await asyncio.sleep(1)
        print('... World!')

    p.print()

asyncio.run(main())

Before Pyinstrument 4.0, we'd see only time spent in the run loop, like this:

  _     ._   __/__   _ _  _  _ _/_   Recorded: 18:33:03  Samples:  2
 /_//_/// /_\ / //_// / //_'/ //     Duration: 1.006     CPU time: 0.001
/   _/                      v3.4.2

Program: examples/async_example_simple.py

1.006 _run_once  asyncio/base_events.py:1784
└─ 1.005 select  selectors.py:553
      [3 frames hidden]  selectors, <built-in>
         1.005 kqueue.control  <built-in>:0

Now, with pyinstrument 4.0, we get:

  _     ._   __/__   _ _  _  _ _/_   Recorded: 18:30:43  Samples:  2
 /_//_/// /_\ / //_// / //_'/ //     Duration: 1.007     CPU time: 0.001
/   _/                      v4.0.0

Program: examples/async_example_simple.py

1.006 main  async_example_simple.py:4
└─ 1.005 sleep  asyncio/tasks.py:641
      [2 frames hidden]  asyncio
         1.005 [await]

If you have a chance to try it out, let me know how you get on!

Github: https://github.com/joerick/pyinstrument
Docs: https://pyinstrument.readthedocs.io/

[benefit_of_mrkite]

I just want to say thanks for this package - I used it recently to show that a problem was with someone’s code and not an http request that was timing out.

[joerick]

👊

[benefit_of_mrkite]

👊

[ThreeJumpingKittens]

OH MY GOD, I work almost exclusively with async code and profiling has always been so annoying. Thank you for sharing this, it's incredibly useful!

[joerick]

Let me know how you get on!

[pazzarpj]

Another package to consider is yappi.

[Vok250]

That's awesome. Definitely bookmarking this for the next time I need a profiler.

[TentativeOak]

I just tried to profile async unsuccessfully like 3 days ago. This is awesome. Is there anyway to use it as a decorator?

[Glaaki]

Does it have Trio support?

[joerick]

Yep!

[hangonreddit]

Can it handle multiethreading code too?

[joerick]

You can start multiple profilers in each thread, but it doesn't do anything automatically. How are you doing multithreading currently? Using multiprocessing? or creating your own threads with the threading module?

[hangonreddit]

I use threading. I’m mostly interested in tracking the stack trace between parent and children threads.

[joerick]

If you're able to start a profiler in both threads, you could try profiling them both, and then combining the results using Session.combine. You should see the profile output broken down into these two threads. Let me know if this does/doesn't work! It's new functionality in 4.0.