Some question about profiling gevent based web application about pyflame

[workingenius]

similar situation. searching for an answer.

[jamespic]

This looks like it might be caused by #62, which is now fixed in master. Could you have a go with the latest build?

If not, could you post a snippet that'll reproduce the issue, and I'll see if I can get to the bottom of it. Greenlets can wreak havoc on stack inspection, so it might just be that, but I'll see if I can make sense of it either way.

[monsterxx03]

Thanks for reply, I tested with pyflame 1.3.1.

The right gevent part disappeared. Now I only have IDLE part and my logic part.

And so as my last part in the question. Did my logic part only means CPU usage of my call stack?

If my python function is waiting for IO (eg: calling rpc server via socket), if pyflame do snapshot on it, the sample will be in IDLE?

I did a test, a simple http server, just sleeping for long time:

import gevent
from gevent import pywsgi

def hello_world(env, start_response):
    gevent.sleep(1000)
    start_response('200 OK', [('Content-Type', 'text/html')])
    return ["<b>hello world</b>"]

pywsgi.WSGIServer(('127.0.0.1', 8001), hello_world).serve_forever()

A simple client to call this server:

import requests
print requests.get('http://127.0.0.1:8001')

Then use pyflame to profile client, 100% sample in IDLE.

Seems my assumption is right. My original guess is pyflame will see something like sock.recv

[jamespic]

@monsterxx03 As a rough approximation, yes. With the latest version of PyFlame, by default IO should show up as (idle).

More precisely, any time when it's not executing Python code is listed as (idle), which often means IO, although some CPU-intensive native code such as numerical libraries would show up as (idle).

Even more precisely still, it's about the global interpreter lock. CPython protects the internals of the interpreter with a single lock, the GIL, and anything that needs to interact with Python objects has to acquire this lock for safety (code that doesn't currently need it, because it's waiting for stuff like IO or pure C calculations, can release it until it needs it again). By default, PyFlame will only profile the thread that holds the GIL, and will report time as (idle) if no thread currently does.

This issue was caused by some refactoring we did to add the --threads flag, which allows PyFlame to profile all threads, not just the one with the GIL. When we first implemented this, there was a bug, #62, which meant that when you were running in the default (not --threads) mode, it would only profile when something held the GIL, but it would profile all threads (including ones waiting for IO, or otherwise not holding the GIL), not just the one with the GIL.

So in your case, the gevent code that was waiting for IO would be spuriously added to the timings whenever something held the GIL.

Hopefully this should be sorted now, but if you can find a test case that still triggers it, I'll take a look.

[monsterxx03]

Thanks so much, much clear now.

The gevent problem has been fixed in my case, I'll close this issue.