Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Weird profile on asyncio code #105

Closed
dimaqq opened this issue Mar 28, 2019 · 3 comments
Closed

Weird profile on asyncio code #105

dimaqq opened this issue Mar 28, 2019 · 3 comments

Comments

@dimaqq
Copy link

dimaqq commented Mar 28, 2019

Hi, I've used py-spy --duration 145 --flame profile.svg pytest ... on a codebase where most tests use pytest-asyncio and code under test uses asyncio extensively.

Without py-spy tests use ~95% CPU (~one core), and with py-spy ~170% CPU.

The flame graph looks like this:

Screenshot 2019-03-28 at 17 56 59

The largest contributor is https://github.com/python/cpython/blob/3.7/Lib/concurrent/futures/thread.py#L78

work_item = work_queue.get(block=True)

This is weird, as this looks like a blocking call, and yet process is CPU-bound.

Another option is that py-spy cannot look across Python C library calls, maybe?

Or I'm doing something very wrong?

@dimaqq
Copy link
Author

dimaqq commented Mar 28, 2019

I get same results with and without --nonblocking, with default and reduced --rate, on both Linux (docker, python:3.7.3-stretch container with added caps) and host macOS.

@benfred
Copy link
Owner

benfred commented Mar 30, 2019

Hmm, that's weird =(. Do you have a sample script that has this problem that you can share?

It seems like there are at least 2 problems you've encountered: the work_queue.get(block=True) isn't getting flagged as idle, and we don't see whatever CPU bound work is happening in the flame graph.

By default we only profile the python stack - but we can look across C library calls (they just won't be included in the stack, but if your code goes Python -> C Extension -> Python we will get all the python frames). There is also some work going to profile native extensions (#2) but it is far from stable right now, especially on OSX.

There is also some work happening to get better at detecting idle threads: #92 - once this is finished we should be able to mark the entire thread as idle.

@dimaqq
Copy link
Author

dimaqq commented Apr 1, 2019

I have an idea what could have happened:

  • some code or test called ...loop.run_in_executor(None, ...)
  • this leaves default thread pool executor with 10 active threads (waiting for more work)
  • this is represented by the ~90% block in the flamegraph
  • main thread is busy with actual test/setup/teardown, and that's visible as ~10% on the left in the flamegraph

Agreed that #92 will likely solve this!

@dimaqq dimaqq closed this as completed Apr 1, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants