Allow Profile() to be used as a context manager
I often find it useful to profile small sections to code in a running application to pinpoint a known bottleneck. The cProfile and profile modules don't make this easy as they stand, requiring the section of code to be wrapped into a single statement with can be called as a string using exec(). This always feels a bit clumsy to me, so my idea is simply to provide __enter__ and __exit__ methods to cProfile.Profile() and profile.Profile(). From a quick look at the code it seems that this should be very easy for cProfile, and slightly less easy for profile (I can't quite figure out how to deal with the set_cmd() line, or how important it is - maybe someone can help?). Any major objections to this? David
On Wed, Jan 25, 2012 at 8:36 AM, David Townshend <aquavitae69@gmail.com>wrote:
[...] Any major objections to this?
At first this sounded like a good idea but 2 things pop to mind: 1. How does one get the pstat profiling output from the context manager? Will printing out the results be the only option? 2. Usually when I profile I don't want to touch the code at all so eventually if I'll use this context manager it'll be more akin to with profile.Profiler(): main() Which isn't much of a win over profile.run('main()') Now if you're talking about a reentrant profiler, that's interesting: profiler = profile.Profiler() while is_working: with profiler: do_hard_task() do_a_hard_but_i_dont_care_now_task() with profiler: do_a_diff_hard_task() and then I can call whatever method is there to get the pstat. If this is the vision then it sounds awesome. Yuval
On Wed, Jan 25, 2012 at 10:19 AM, Yuval Greenfield <ubershmekel@gmail.com>wrote:
profile = cProfile.Profile() with profile: do_something() profile.dump_stats(filename) Perhaps it would be a good idea to provide a convenience function (like run()), so that: with cProfile.do(filename): do_something() I don't like calling the function do(), but I can't think of anything better off-hand, and it illustrates my point.
I agree, but this isn't the use case.
And this is the use case! I'm not entirely sure how re-entrancy would be dealt with by the profiler though. From what I read in the source code it looks like it would all accumulate, and this is certainly the way I would expect it to behave, but I'd need to run a few tests to be sure.
On Wed, Jan 25, 2012 at 7:47 PM, David Townshend <aquavitae69@gmail.com> wrote:
If __enter__() returns self (as is recommended when you don't have anything more context specific to return), then the following would also work: with cProfile.Profile() as profile: do_something() profile.dump_stats(filename) Assuming the re-entrancy question can be answered adequately, this sounds like a reasonable idea to me. Cheers, Nick. -- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia
On 1/25/12 8:19 AM, Yuval Greenfield wrote:
<shameless-advertisement> You may want to take a look at my kernprof script mentioned elsewhere in the thread: http://packages.python.org/line_profiler/ http://pypi.python.org/pypi/line_profiler/ Besides adding the context manager to Profile, it is a generic "runner" script that will run your script under the profiler and dump the results to a file. In the normal use case of profiling the entire script, you don't have to modify your code at all: [line_profiler]$ kernprof.py -v pystone.py Pystone(1.1) time for 50000 passes = 0.918603 This machine benchmarks at 54430.5 pystones/second Wrote profile results to pystone.py.prof 1100070 function calls in 0.929 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.929 0.929 <string>:1(<module>) 50000 0.140 0.000 0.322 0.000 pystone.py:137(Proc1) 50000 0.029 0.000 0.029 0.000 pystone.py:153(Proc2) 50000 0.036 0.000 0.048 0.000 pystone.py:164(Proc3) 50000 0.015 0.000 0.015 0.000 pystone.py:174(Proc4) 50000 0.013 0.000 0.013 0.000 pystone.py:181(Proc5) 50000 0.033 0.000 0.043 0.000 pystone.py:188(Proc6) 150000 0.034 0.000 0.034 0.000 pystone.py:207(Proc7) 50000 0.100 0.000 0.126 0.000 pystone.py:212(Proc8) 150000 0.035 0.000 0.035 0.000 pystone.py:225(Func1) ... But if you do want to use the context manager or the decorator, then there is a flag to the script that injects the Profile instance into the builtins. Then you can use "@profile" or "with profile:" to only enable the profiler at certain points (and multiple points as in your use case above). These are the only modifications you need to make. The stats dumping is handled by kernprof. [line_profiler]$ grin -A10 '@profile' pystone.py pystone.py: 164 : @profile 165 + def Proc3(PtrParOut): 166 + global IntGlob 167 + 168 + if PtrGlb is not None: 169 + PtrParOut = PtrGlb.PtrComp 170 + else: 171 + IntGlob = 100 172 + PtrGlb.IntComp = Proc7(10, IntGlob) 173 + return PtrParOut 174 + 182 : @profile 183 + def Proc5(): 184 + global Char1Glob 185 + global BoolGlob 186 + 187 + Char1Glob = 'A' 188 + BoolGlob = FALSE 189 + 190 + def Proc6(EnumParIn): 191 + EnumParOut = EnumParIn 192 + if not Func3(EnumParIn): [line_profiler]$ kernprof.py -v --builtin pystone.py Pystone(1.1) time for 50000 passes = 1.08921 This machine benchmarks at 45904.8 pystones/second Wrote profile results to pystone.py.prof 350000 function calls in 0.192 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 100000 0.116 0.000 0.123 0.000 kernprof.py:73(disable_by_count) 50000 0.042 0.000 0.055 0.000 pystone.py:164(Proc3) 50000 0.013 0.000 0.013 0.000 pystone.py:182(Proc5) 50000 0.013 0.000 0.013 0.000 pystone.py:209(Proc7) 100000 0.007 0.000 0.007 0.000 {method 'disable' of '_lsprof.Profiler' objects} </shameless-advertisement> -- Robert Kern "I have come to believe that the whole world is an enigma, a harmless enigma that is made terrible by our own mad attempt to interpret it as though it had an underlying truth." -- Umberto Eco
shameless-advertisement noted! It looks like a useful tool, but I had something rather simpler in mind, and something included in the stdlib. I think adding a decorator too is a good idea, but as pointed out there is already a patch for this. David On Wed, Jan 25, 2012 at 1:37 PM, Robert Kern <robert.kern@gmail.com> wrote:
Il 25 gennaio 2012 07:36, David Townshend <aquavitae69@gmail.com> ha scritto:
Related: http://bugs.python.org/issue9285 --- Giampaolo http://code.google.com/p/pyftpdlib/ http://code.google.com/p/psutil/ http://code.google.com/p/pysendfile/
On 1/25/12 6:36 AM, David Townshend wrote:
I've done this in my kernprof.py script, which I use as a convenient generic profiling script. I subclass cProfile.Profile to add enable_by_count()/disable_by_count() methods that allow nesting. enable_by_count() increments a counter and only calls the enable() method the first time. disable_by_count() decrements the counter and only calls disable() when it hits 0 again. __enter__() and __exit__() just call these methods. I also add a __call__() method that lets a Profile instance act as a decorator, which I actually find somewhat more useful than the context manager. https://bitbucket.org/robertkern/line_profiler/src/tip/kernprof.py#cl-57 -- Robert Kern "I have come to believe that the whole world is an enigma, a harmless enigma that is made terrible by our own mad attempt to interpret it as though it had an underlying truth." -- Umberto Eco
On Wed, Jan 25, 2012 at 8:28 PM, David Townshend <aquavitae69@gmail.com> wrote:
No, because the two profiling blocks aren't overlapping - the count drops to zero between them so the profiler will be disabled for that period. Cheers, Nick. -- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia
On Wed, Jan 25, 2012 at 8:36 AM, David Townshend <aquavitae69@gmail.com>wrote:
[...] Any major objections to this?
At first this sounded like a good idea but 2 things pop to mind: 1. How does one get the pstat profiling output from the context manager? Will printing out the results be the only option? 2. Usually when I profile I don't want to touch the code at all so eventually if I'll use this context manager it'll be more akin to with profile.Profiler(): main() Which isn't much of a win over profile.run('main()') Now if you're talking about a reentrant profiler, that's interesting: profiler = profile.Profiler() while is_working: with profiler: do_hard_task() do_a_hard_but_i_dont_care_now_task() with profiler: do_a_diff_hard_task() and then I can call whatever method is there to get the pstat. If this is the vision then it sounds awesome. Yuval
On Wed, Jan 25, 2012 at 10:19 AM, Yuval Greenfield <ubershmekel@gmail.com>wrote:
profile = cProfile.Profile() with profile: do_something() profile.dump_stats(filename) Perhaps it would be a good idea to provide a convenience function (like run()), so that: with cProfile.do(filename): do_something() I don't like calling the function do(), but I can't think of anything better off-hand, and it illustrates my point.
I agree, but this isn't the use case.
And this is the use case! I'm not entirely sure how re-entrancy would be dealt with by the profiler though. From what I read in the source code it looks like it would all accumulate, and this is certainly the way I would expect it to behave, but I'd need to run a few tests to be sure.
On Wed, Jan 25, 2012 at 7:47 PM, David Townshend <aquavitae69@gmail.com> wrote:
If __enter__() returns self (as is recommended when you don't have anything more context specific to return), then the following would also work: with cProfile.Profile() as profile: do_something() profile.dump_stats(filename) Assuming the re-entrancy question can be answered adequately, this sounds like a reasonable idea to me. Cheers, Nick. -- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia
On 1/25/12 8:19 AM, Yuval Greenfield wrote:
<shameless-advertisement> You may want to take a look at my kernprof script mentioned elsewhere in the thread: http://packages.python.org/line_profiler/ http://pypi.python.org/pypi/line_profiler/ Besides adding the context manager to Profile, it is a generic "runner" script that will run your script under the profiler and dump the results to a file. In the normal use case of profiling the entire script, you don't have to modify your code at all: [line_profiler]$ kernprof.py -v pystone.py Pystone(1.1) time for 50000 passes = 0.918603 This machine benchmarks at 54430.5 pystones/second Wrote profile results to pystone.py.prof 1100070 function calls in 0.929 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.929 0.929 <string>:1(<module>) 50000 0.140 0.000 0.322 0.000 pystone.py:137(Proc1) 50000 0.029 0.000 0.029 0.000 pystone.py:153(Proc2) 50000 0.036 0.000 0.048 0.000 pystone.py:164(Proc3) 50000 0.015 0.000 0.015 0.000 pystone.py:174(Proc4) 50000 0.013 0.000 0.013 0.000 pystone.py:181(Proc5) 50000 0.033 0.000 0.043 0.000 pystone.py:188(Proc6) 150000 0.034 0.000 0.034 0.000 pystone.py:207(Proc7) 50000 0.100 0.000 0.126 0.000 pystone.py:212(Proc8) 150000 0.035 0.000 0.035 0.000 pystone.py:225(Func1) ... But if you do want to use the context manager or the decorator, then there is a flag to the script that injects the Profile instance into the builtins. Then you can use "@profile" or "with profile:" to only enable the profiler at certain points (and multiple points as in your use case above). These are the only modifications you need to make. The stats dumping is handled by kernprof. [line_profiler]$ grin -A10 '@profile' pystone.py pystone.py: 164 : @profile 165 + def Proc3(PtrParOut): 166 + global IntGlob 167 + 168 + if PtrGlb is not None: 169 + PtrParOut = PtrGlb.PtrComp 170 + else: 171 + IntGlob = 100 172 + PtrGlb.IntComp = Proc7(10, IntGlob) 173 + return PtrParOut 174 + 182 : @profile 183 + def Proc5(): 184 + global Char1Glob 185 + global BoolGlob 186 + 187 + Char1Glob = 'A' 188 + BoolGlob = FALSE 189 + 190 + def Proc6(EnumParIn): 191 + EnumParOut = EnumParIn 192 + if not Func3(EnumParIn): [line_profiler]$ kernprof.py -v --builtin pystone.py Pystone(1.1) time for 50000 passes = 1.08921 This machine benchmarks at 45904.8 pystones/second Wrote profile results to pystone.py.prof 350000 function calls in 0.192 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 100000 0.116 0.000 0.123 0.000 kernprof.py:73(disable_by_count) 50000 0.042 0.000 0.055 0.000 pystone.py:164(Proc3) 50000 0.013 0.000 0.013 0.000 pystone.py:182(Proc5) 50000 0.013 0.000 0.013 0.000 pystone.py:209(Proc7) 100000 0.007 0.000 0.007 0.000 {method 'disable' of '_lsprof.Profiler' objects} </shameless-advertisement> -- Robert Kern "I have come to believe that the whole world is an enigma, a harmless enigma that is made terrible by our own mad attempt to interpret it as though it had an underlying truth." -- Umberto Eco
shameless-advertisement noted! It looks like a useful tool, but I had something rather simpler in mind, and something included in the stdlib. I think adding a decorator too is a good idea, but as pointed out there is already a patch for this. David On Wed, Jan 25, 2012 at 1:37 PM, Robert Kern <robert.kern@gmail.com> wrote:
Il 25 gennaio 2012 07:36, David Townshend <aquavitae69@gmail.com> ha scritto:
Related: http://bugs.python.org/issue9285 --- Giampaolo http://code.google.com/p/pyftpdlib/ http://code.google.com/p/psutil/ http://code.google.com/p/pysendfile/
On 1/25/12 6:36 AM, David Townshend wrote:
I've done this in my kernprof.py script, which I use as a convenient generic profiling script. I subclass cProfile.Profile to add enable_by_count()/disable_by_count() methods that allow nesting. enable_by_count() increments a counter and only calls the enable() method the first time. disable_by_count() decrements the counter and only calls disable() when it hits 0 again. __enter__() and __exit__() just call these methods. I also add a __call__() method that lets a Profile instance act as a decorator, which I actually find somewhat more useful than the context manager. https://bitbucket.org/robertkern/line_profiler/src/tip/kernprof.py#cl-57 -- Robert Kern "I have come to believe that the whole world is an enigma, a harmless enigma that is made terrible by our own mad attempt to interpret it as though it had an underlying truth." -- Umberto Eco
On Wed, Jan 25, 2012 at 8:28 PM, David Townshend <aquavitae69@gmail.com> wrote:
No, because the two profiling blocks aren't overlapping - the count drops to zero between them so the profiler will be disabled for that period. Cheers, Nick. -- Nick Coghlan | ncoghlan@gmail.com | Brisbane, Australia
participants (5)
-
David Townshend -
Giampaolo Rodolà -
Nick Coghlan -
Robert Kern -
Yuval Greenfield