How to understand this profiling report by py-spy?

[lingvisa]

First, this is not an issue for py-spy, but I hope the author can help me understand what's happening with my profiling in py-spy. This is what happened:

Suddenly my program became extremely slow at one function call 'make_doc' and my program had only minor changes. I don't see why it became so slow. Inside the 'make_doc' there is Cython code which is hard to debug.

I tried to use py-spy to profile and generated 3 screenshots, but didn't get any clue on the slowness. It seems that it indicates the 'getmodule' method in inspect.py takes most time. Is that true? The most time spent on python interpreter code, not on my own code? Please help share your thoughts on profiling. I am on Mac Big Sur 11.2.3

[lingvisa]

Two more notes:

1. I used 'sudo py-spy top -- python wbnlp_api.py --native' to generate the 2nd screenshot and in the make_doc function, there are cython code. But report didn't show how the function perform inside make_doc?

2. The GIL is almost 100%. Does that indicate the cause for the slowness?

[ThyrixYang]

I agree that a detailed instruction or tutorial to read the output is necessary for beginners.

---

1. What is the exact meaning of Owntime and TotalTime in top?
2. What is GIL and active percentage? As asked by @lingvisa, what does their value indicate?

[Jongy]

You can take a look at https://rbspy.github.io/using-flamegraphs/, it's a nice starting point for analyzing flamegraphs.

@ThyrixYang , "active" means time that the process/thread was running on the CPU; "GIL" means the time the thread was owning CPython's GIL. While owning the GIL you're also active, but it's not necessary the other way around: a thread can be active without owning the GIL (for example: a native extension that gets called from Python, releases the GIL and runs some code meanwhile)

[ThyrixYang]

@Jongy Thanks for your kind reply!