Why Python standard library “profile” can’t be context manager like this
1 2 3 4 |
import profile with profile.Profile(): fib(10) |
Zero, what is “profile” module in Python? According to Python 3 Documentation:
profile
, a pure Python module whose interface is imitated bycProfile
, but which adds significant overhead to profiled programs. If you’re trying to extend the profiler in some way, the task might be easier with this module. Originally designed and written by Jim Roskind.
“Making cProfile / profile as a context manager” is a long-term problem since 2010 [1],and not yet resolve. The last message on bpo is a cryptic assertion make profile can’t work. Basically what we will do is to add __enter__
and __end__
magic methods into profile’s class Profile, then it can act like a context manager:
1 2 3 4 5 6 7 8 |
class Profile: def __enter__(self): sys.setprofile(self.dispatcher) return self def __exit__(self): sys.setprofile(None) self.print_stats() return False |
1 2 |
with profile.Profile(): profile_this_function() |
But this won’t work, if you try it yourself, you will find that it will pop out a strange assertion error like this:
1 2 3 4 5 6 7 8 9 10 |
Traceback (most recent call last): File “tests.py”, line 3, in <module> with profile.Profile(): File “/home/linux/Python/cpython/Lib/profile.py”, line 202, in __enter__ return self File “/home/linux/Python/cpython/Lib/profile.py”, line 236, in trace_dispatch_i if self.dispatch[event](self, frame, t): File “/home/linux/Python/cpython/Lib/profile.py”, line 320, in trace_dispatch_return assert frame is self.cur[–2].f_back, (“Bad return”, self.cur[–3]) AssertionError: (‘Bad return’, (‘profile’, 0, ”)) |
How could it be? the same trick work with cProfile, but not profile?
First, we will need to know how python profiler works. When we want to add a profiler to python program, we will need to use “sys.setprofile” to hook up the profiler and python. Then in each event (call, exception, return, c_call, c_exception, c_return) in python, it will call your profiler to profile. When it call your profiler, it will pass three arguments to the profiler, frame
, event and arg.
Then your profile will deal with different event, and calculate the time for it.
“profile” module’s class “Profile” is designed to be a pure python profiler, it have a fast dispatcher to dispatch each event to the relative function.
1 2 3 4 5 6 7 8 9 10 11 |
def trace_dispatch_i(self, frame, event, arg): timer = self.timer t = timer() – self.t – self.bias if event == “c_call”: self.c_func_name = arg.__name__ if self.dispatch[event](self, frame, t): self.t = timer() else: self.t = timer() – t # put back unrecorded delta |
Second, the profiler has a self-maintained frame stack, to record the parent frame for return purpose. This frame stack is build as a 6-item tuple, which is:
1 2 3 4 5 6 7 8 |
(0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7f1e5ed0a260>, None) [0]: parent time [1]: internal time [2]: external time [–3]: Name of the function that corresponds to this frame(fake code object) [–2]: Acutal frame [–1]: Our parent 6–tuple (corresponds to frame.f_back) |
The above 6-tuple is the initial tuple for the profile.Profile() instance when created. You can see, the -3 item is ('profile', 0, 'profile')
which represent to filename, line number and code object name. The -2 item is a fake frame and -1 is None, indicate that there is no parent, which mean that this is the most top frame that we can return here.
And why we need this, this initial tuple is used to be a sentinel, tell profiler this is the most top of the profiler, and can’t return anymore.
To simulate a deep call like this:
1 2 3 4 5 6 7 8 9 10 11 12 13 |
import sys import profile def bar(n): return n def foo(n): return bar(n) pr = profile.Profile() sys.setprofile(pr.dispatcher) foo(10) sys.setprofile(None) |
It will build the synthetic frame stack like this:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
call (0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7efd21316538>, None) call (1.7982999999999194e–05, 0, 0, (‘tests.py’, 7, ‘foo’), <frame object at 0x7efd212a3058>, (0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7efd21316538>, None)) return (4.986999999997965e–06, 0, 0, (‘tests.py’, 4, ‘bar’), <frame object at 0x7efd211da5e0>, (1.7982999999999194e–05, 0, 0, (‘tests.py’, 7, ‘foo’), <frame object at 0x7efd212a3058>, (0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7efd21316538>, None))) return (1.7982999999999194e–05, 4.986999999997965e–06, 3.284000000006171e–06, (‘tests.py’, 7, ‘foo’), <frame object at 0x7efd212a3058>, (0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7efd21316538>, None)) c_call (0, 1.7982999999999194e–05, 1.2263999999997943e–05, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7efd21316538>, None) |
You must observe the last item, which I have move to start at newline, is the profiler synthetic frame stack. When each call is made, it will record a parent 6-tuple in it.
So in this limitation, if we return at the last frame, which is the tuple that I show it above, I’ll show it again here:
1 |
call (0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7efd21316538>, None) |
Then this return will trigger a “bad return”, because you can’t return to a None parent, that is an illegal operation.
The Main Problem
We can now return to our main problem: “Why can’t we let profile as a context manager?” here is the code:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
import sys import profile def bar(n): return n def foo(n): return bar(n) def profiler_helper(pr): sys.setprofile(pr.dispatcher) pr = profile.Profile() profiler_helper(pr) sys.setprofile(pr.dispatcher) foo(10) sys.setprofile(None) |
Can you tell where get wrong?
Yes, when we get into profiler_helper, the profiler still not hook on python, so the synthetic frame stack it still look like this:
1 |
(0, 0, 0, (‘profile’, 0, ‘profiler’), <profile.Profile.fake_frame object at 0x7f12fe206670>, None) |
And then we got a return from profiler_helper (we must return back, this function is done), this time, the profiler is hook to python, therefore our dispatcher is work! Then it will try to return, meet our sentinel and raise a AssertionError that says “Bad Return”.
The Fix
Our fix is very easy, just need to add a simulate call to simulate that we call the profiler_helper:
1 2 3 4 5 |
def __enter__(self): frame = sys._getframe(1) # Get helper function frame object self.dispatch[‘call’](self, frame, 0) sys.setprofile(self.dispatcher) return self |
Then the problem solve, now we can return it correctly!
[1]: bpo-9285: Add a profile decorator to profile and cProfile
[2]: bpo-30113: Allow helper functions to wrap sys.setprofile
Leave a Reply