{"id":2212,"date":"2021-04-28T13:06:48","date_gmt":"2021-04-28T11:06:48","guid":{"rendered":"https:\/\/iww.inria.fr\/sed-sophia\/?p=2212"},"modified":"2021-04-28T13:06:48","modified_gmt":"2021-04-28T11:06:48","slug":"tuning-python-script-performance-with-profiling","status":"publish","type":"post","link":"https:\/\/iww.inria.fr\/sed-sophia\/tuning-python-script-performance-with-profiling\/","title":{"rendered":"Tuning Python script performance with profiling"},"content":{"rendered":"

Profiling<\/em> a program consists in dynamically collecting measures during the program execution : which functions or pieces of code are executed, how many times, the duration of an execution, the call tree, …<\/p>\n

cProfile<\/strong><\/a> is a common profiler for Python programs.<\/p>\n

cProfile<\/em> does deterministic profiling<\/em> – it collects counters for the whole program execution – as opposed to statistical profiling<\/em> that monitors samples of the program execution. py-spy<\/a> (statistical), yappi<\/a> (deterministic), etc. are other options for Python profiling.<\/p>\n

Other options for profiling include system level profiling tools (eg with perf<\/a> for Linux), or advanced commercial multi-langage profilers such as Alinea map<\/a> and Intel Vtune<\/a> for which Inria has licences.<\/p>\n

cProfile lets you easily profile your whole script and save result to an output file (cprofile.out<\/em> here) in pstats format with :<\/p>\n

[user@laptop $] python -m cProfile -o cprofile.out \/path\/to\/my_script.py<\/code><\/pre>\n
For profiling a section of your Python script, simply instrument the code with :<\/p>\n
import cProfile\nprofile = cProfile.Profile()\n# start profiling section\nprofile.enable()\n# place your payload here\nmy_profiled_code_or_function()\n# stop profiling section\nprofile.disable()\n# save collected statistics\nprofile.dump_stats('cprofile.out')<\/code><\/pre>\n
You can then install a profiling data viewer such as snakeviz<\/a> and run it on the profiling data :<\/div>\n
[user@laptop $] snakeviz cprofile.out<\/code><\/pre>\n
A more basic option is to use the pstats module interactive mode :<\/div>\n
[user@laptop $] python -m pstats cprofile.out\nWelcome to the profile statistics browser.\ncprofile.out% stats 5<\/code><\/pre>\n
You may also use the profiling data programatically by further instrumenting your script eg :<\/div>\n
\n
\n
import pstats\nprofile_stats = pstats.Stats(profile)\n# print to stdout top 10 functions sorted by total execution time\nprofile_stats.sort_stats('tottime').print_stats(10)\n# print to stdout top 5 functions sorted by number of time called\nprofile_stats.sort_stats('ncalls').print_stats(5)<\/code><\/pre>\n<\/div>\n<\/div>\n
Here is an example of a snakeviz view for a geomstats<\/a> hypersphere metric norm computation :<\/div>\n
<\/div>\n
 <\/p>\n
\"\"<\/a><\/div>\n
<\/div>\n
 <\/p>\n
… and text output for top 5 functions sorted by total execution time, for the same computation :<\/div>\n
<\/div>\n
Ordered by: internal time\nList reduced from 16 to 5 due to restriction &lt;5&gt;\n\nncalls tottime percall cumtime percall filename:lineno(function)\n20000 0.017 0.000 0.059 0.000 \/user\/mvesin\/home\/.conda\/envs\/geomstats-conda3backends\/lib\/python3.7\/site-packages\/autograd\/tracer.py:35(f_wrapped)\n10000 0.013 0.000 0.013 0.000 {built-in method numpy.core._multiarray_umath.c_einsum}\n20000 0.008 0.000 0.013 0.000 \/user\/mvesin\/home\/.conda\/envs\/geomstats-conda3backends\/lib\/python3.7\/site-packages\/autograd\/tracer.py:65(find_top_boxed_args)\n10000 0.008 0.000 0.026 0.000 {built-in method numpy.core._multiarray_umath.implement_array_function}\n10000 0.005 0.000 0.072 0.000 \/home\/mvesin\/GIT\/geomstats\/mvesin_geomstats\/geomstats\/geometry\/riemannian_metric.py:222(norm)\n\n210006 function calls in 0.072 seconds\n<\/code><\/pre>\n
 <\/p>\n
When analyzing profiling results, you often want to focus on functions with higher cumulative time<\/em> (time spent in function and its sub-functions – those at the top of the call hierarchy) or total time<\/em> (time spent only in function – those where the heavy work takes place). Look also at the number of calls<\/em> of a function (is it long to execute or often called ? does it match what is expected or does it suggest un-needed calls ?) and to the function call hierarchy (who calls who ?).<\/div>\n
 <\/p>\n
You may also want to replay execution step by step with a Python debugger such as pdb<\/a> to help link profiling results with the execution flow.<\/p>\n
cProfile<\/em> profiling was recently used by EPIONE team and SED-SAM recently for jointly tuning geomstats<\/a> performanc. It helped better understanding performance trends<\/a> and gaining significant acceleration for parts of the library.<\/p>","protected":false},"excerpt":{"rendered":"
Profiling a program consists in dynamically collecting measures during the program execution : which functions or pieces of code are executed, how many times, the duration of an execution, the call tree, … cProfile is a common profiler for Python programs. cProfile does deterministic profiling – it collects counters for\u2026<\/p>\n
 Continue reading<\/span><\/i><\/a> <\/p>\n","protected":false},"author":187,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":"","_members_access_role":[],"_members_access_error":""},"categories":[28,111],"tags":[],"class_list":["post-2212","post","type-post","status-publish","format-standard","hentry","category-goodpractices","category-tools"],"_links":{"self":[{"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/posts\/2212","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/users\/187"}],"replies":[{"embeddable":true,"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/comments?post=2212"}],"version-history":[{"count":37,"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/posts\/2212\/revisions"}],"predecessor-version":[{"id":2372,"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/posts\/2212\/revisions\/2372"}],"wp:attachment":[{"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/media?parent=2212"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/categories?post=2212"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/iww.inria.fr\/sed-sophia\/wp-json\/wp\/v2\/tags?post=2212"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}