py-spy not showing child function calls in flame graph

[synapticarbors]

I was attempting to use py-spy to profile a monitoring tool that has a number of different threads that do things like read from external APIs, parse results and store them to a database, etc at some fixed interval. My hope was to identify hotspots and a recent performance regression. The experience of installing and using py-spy was fantastically easy and I was able to get a flame graph for the program without issues. When I look at the flame graph though, I see the functions listed that are the target for each thread, but in most cases, none of the child functions that they call are listed. For each of these cases the line number it points to is the time.sleep() call within the target function rather than any of the actual work that it does between sleeps.

A given target function might look something like:

def aux_jobs(self, delta_t, name):
        last = None
        while self.is_running:
            if last is None or (datetime.datetime.utcnow() - last).total_seconds() > delta_t:
                logger.debug('Running aux jobs')
                last = datetime.datetime.utcnow()
                self.refresh_dao()
                self.update_mappings()
                self.fetch_non_focus_data()
                self.check_completed_tasks()
                self.calculate_stats()
                self.update_session_data()
                self.session.update_processes_seen(name)
            else:
                diff = delta_t - (datetime.datetime.utcnow() - last).total_seconds() - 1
                if diff > 0:
                    time.sleep(diff)
                else:
                    time.sleep(self.env.params['busy_loop_pause'])

The line number points to the time.sleep(diff), but then I don't see any of the sub-calls (e.g. self.update_mappings(), self.calculate_stats(), etc) below aux_jobs. I expect the work part of the function to take on the order of 50-200 milliseconds in total.

It looks like threads that are just waiting on data from a multiprocessing.queue and don't have explicit calls to time.sleep() show their calls all of the way down.

I've tried extending the duration out to 5 minutes and increasing the sampling rate to 200 samples per second, but I don't see any difference.

Is this to be expected given how py-spy works, or am I missing something? I can post the flame graph if that would be useful.

[benfred]

Hmm - I'm guessing that the time.sleep call takes the most amount of time and is crowding out the actual work.

There is some code in the the flame graph generation that limits traces to a minimum of 2px (https://github.com/benfred/py-spy/blob/v0.1.10/src/flamegraph.rs#L88). I'm wondering if the time.sleep call is hit so much more often that the other calls just don't show up since they would be less than 2px in the output.

You could change the rate to something much higher (1000 or 5000 samples per second - py-spy will warn you if it can't keep up) and try again, but that might not change the relative proportion. Turning off showing line numbers might help in this case (--function argument) - since will allow things to coalesce more.

I think we really should have better idle detection: we should be able to filter out calls to time.sleep entirely from the output since no work is being done. Right now there are some heuristics to match common idle states, but it shouldn't be too crazy to actually get the thread status from the OS

[synapticarbors]

I was able to get the information I needed with pyflame using the -x/--exclude-idle flag. I was fortunate that this application was running on linux so I could use pyflame, but it would be fantastic for py-spy to include this capability in the future since pyflame does not run on MacOS or Windows (which I often find myself working on).

Thanks again for your help.

[benfred]

I created a new issue to track better idle detection #92 and I'm going to close this issue.

The pyflame option you used is filtering down to stack frame that hold on to the GIL. This isn't perfect either (extensions can release the GIL while doing work etc), but I'm glad it helped you out here.

Also, I pushed out a beta version with some UI changes that might help you out: pip install py-spy==0.2.0.dev1 and then py-spy --serve -- python myprogram.py will launch an embedded web server that has an option to filter down to just the GIL (and lets you select the time range of the flame chart). It's still a work in progress but I'd be interested in hearing your thoughts.

[synapticarbors]

Thanks for investigating this. I'll try to checkout the --server feature soon.