Skip to content
This repository was archived by the owner on Dec 9, 2021. It is now read-only.

Show sampling statistics - #3

Open
mgedmin wants to merge 1 commit into
blopker:masterfrom
mgedmin:stats
Open

Show sampling statistics#3
mgedmin wants to merge 1 commit into
blopker:masterfrom
mgedmin:stats

Conversation

@mgedmin

@mgedmin mgedmin commented Dec 1, 2015

Copy link
Copy Markdown

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.

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

mgedmin commented Dec 1, 2015

Copy link
Copy Markdown
Author

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

@mgedmin

mgedmin commented Dec 1, 2015

Copy link
Copy Markdown
Author

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

mgedmin commented Dec 1, 2015

Copy link
Copy Markdown
Author

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.

@blopker

blopker commented Dec 1, 2015

Copy link
Copy Markdown
Owner

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!

@mgedmin

mgedmin commented Dec 2, 2015

Copy link
Copy Markdown
Author

Ok, I'll keep it split then :)

Or do you want it even more fine-grained?

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants