djdt-flamegraph icon indicating copy to clipboard operation
djdt-flamegraph copied to clipboard

Show sampling statistics

Open mgedmin opened this issue 9 years ago • 5 comments

Background: I was trying to profile a view that took ~5 seconds to render. I saw that my flamegraph contained ~1000 samples where I expected closer to 5000, given the 1ms sampling interval. I decided that I needed to know how accurate the sampling was.

This commit records time.time() deltas between each sample and tries to do statistics with them (min/max/avg/stddev, after discarding outliers). These are shown at the bottom of the flame graph.

All outliers are also shown, and very serious outliers (intervals longer than 10ms where no sampling took place) are shown in bold, with a tooltip that indicates their relative position in time.

This let me see that there was a 2.5 second gap in the profile of my view that takes 5 seconds, i.e. I was only seeing one half of the picture.

mgedmin avatar Dec 01 '15 09:12 mgedmin

Example output: ekrano nuotrauka is 2015-12-01 11-40-38

mgedmin avatar Dec 01 '15 09:12 mgedmin

I have another commit waiting that provides more information about those gaps in the profile: ekrano nuotrauka is 2015-12-01 12-08-23

I don't know if you want it as a separate PR, or if I should join them together.

mgedmin avatar Dec 01 '15 10:12 mgedmin

And finally I have a third commit that fills those profiling gaps with fake samples so that the profiles are no longer distorted. Replicating the 1st stack frame after such a profiling gap seems to give good results -- e.g. in my profile I find it very plausible that psycopg2 and threading.Lock.wait() are ~~holding the GIL and not allowing signal handlers to run~~ blocking in C code, which delays signal handling until the main thread returns to the CPython interpreter loop.

mgedmin avatar Dec 01 '15 10:12 mgedmin

Hey, this is a lot to take in. I may not have time to get through it until later this week. It would help to split this up in to smaller PRs though.

Thanks!

blopker avatar Dec 01 '15 21:12 blopker

Ok, I'll keep it split then :)

Or do you want it even more fine-grained?

mgedmin avatar Dec 02 '15 06:12 mgedmin