Python and profiling

While working on the Rosalind’s problems, I discover a nice feature of python, the cProfile module, that produce an output like this:

         
5683 function calls (5637 primitive calls) in 0.013 seconds
Ordered by: standard name   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    0.000    0.000    0.000    0.000 :1012(__init__)
    1    0.000    0.000    0.004    0.004 :1018(load_module)
    4    0.000    0.000    0.000    0.000 :1025(get_filename)
    1    0.000    0.000    0.000    0.000 :1030(get_data)
    1    0.000    0.000    0.000    0.000 :1040(path_stats)
    1    0.000    0.000    0.000    0.000 :108(_path_isfile)
    5    0.000    0.000    0.000    0.000 :1257(_path_importer_cache)
    1    0.000    0.000    0.000    0.000 :1274(_get_loader)
    1    0.000    0.000    0.000    0.000 :1299(find_module)
    4    0.000    0.000    0.000    0.000 :1346(find_loader)
    6    0.000    0.000    0.000    0.000 :1446(__enter__)
    6    0.000    0.000    0.000    0.000 :1450(__exit__)
    3    0.000    0.000    0.001    0.000 :1464(_find_module)     
    3/2    0.000    0.000    0.004    0.002 :1500(_find_and_load_unlocked)
    1    0.000    0.000    0.000    0.000 :154(new_module)
    3/2    0.000    0.000    0.005    0.002 :1550(_find_and_load)
    1    0.000    0.000    0.000    0.000 :1587(_handle_fromlist)
    3    0.000    0.000    0.000    0.000 :181(__init__)
    3    0.000    0.000    0.000    0.000 :201(acquire)
    3    0.000    0.000    0.000    0.000 :226(release)
    3    0.000    0.000    0.000    0.000 :266(_get_module_lock)
    3    0.000    0.000    0.000    0.000 :280(cb)
    3/2    0.000    0.000    0.003    0.002 :305(_call_with_frames_removed)
    4    0.000    0.000    0.000    0.000 :34(_relax_case)
    2    0.000    0.000    0.000    0.000 :415(cache_from_source)
    5    0.000    0.000    0.000    0.000 :486(_verbose_message)
    2    0.000    0.000    0.000    0.000 :496(set_package_wrapper)
    2    0.000    0.000    0.000    0.000 :509(set_loader_wrapper)
    1    0.000    0.000    0.004    0.004 :536(module_for_loader_wrapper)
    5/1    0.000    0.000    0.004    0.004 :581(_check_name_wrapper)
    2    0.000    0.000    0.000    0.000 :593(_requires_builtin_wrapper)
    2    0.000    0.000    0.000    0.000 :61(_r_long)
    3    0.000    0.000    0.000    0.000 :643(find_module)
    2    0.000    0.000    0.000    0.000 :654(load_module)
    1    0.000    0.000    0.000    0.000 :700(find_module)
    3    0.000    0.000    0.000    0.000 :74(_path_join)
    1    0.000    0.000    0.000    0.000 :754(_open_registry)
    1    0.000    0.000    0.000    0.000 :761(_search_registry)
    1    0.000    0.000    0.000    0.000 :776(find_module)
    2    0.000    0.000    0.000    0.000 :796(is_package)
    1    0.000    0.000    0.000    0.000 :804(_bytes_from_bytecode)
    1    0.000    0.000    0.004    0.004 :849(_load_module)
    4    0.000    0.000    0.000    0.000 :86(_path_split)
    1    0.000    0.000    0.000    0.000 :934(get_code)
    1    0.000    0.000    0.000    0.000 :98(_path_is_mode_type)
    1    0.000    0.000    0.004    0.004 :996(load_module)
    1    0.000    0.000    0.000    0.000 codecs.py:238(__init__)
    852    0.001    0.000    0.002    0.000 cp1252.py:18(encode)
    1    0.000    0.000    0.000    0.000 cp1252.py:22(decode)
    1    0.000    0.000    0.000    0.000 functools.py:148(__init__)
    3    0.000    0.000    0.000    0.000 functools.py:152(__hash__)
    1    0.000    0.000    0.000    0.000 functools.py:155(_make_key)
    3    0.000    0.000    0.000    0.000 functools.py:167()
    1    0.000    0.000    0.003    0.003 functools.py:241(wrapper)
    1    0.000    0.000    0.000    0.000 locale.py:555(getpreferredencoding)
    1    0.000    0.000    0.003    0.003 re.py:212(compile)
    1    0.000    0.000    0.000    0.000 re.py:230(escape)
    1    0.000    0.000    0.003    0.003 re.py:264(_compile)
    1    0.002    0.002    0.013    0.013 ros_kmp.py:3()
    168    0.000    0.000    0.000    0.000 ros_kmp.py:45()
    212    0.000    0.000    0.000    0.000 ros_kmp.py:5(Find)
    212    0.001    0.000    0.001    0.000 ros_kmp.py:8(Comp)
    4    0.000    0.000    0.000    0.000 sre_compile.py:178(_compile_charset)
    4    0.000    0.000    0.000    0.000 sre_compile.py:207(_optimize_charset)
    2    0.000    0.000    0.000    0.000 sre_compile.py:258(_mk_bitmap)
    ù12/1    0.000    0.000    0.001    0.001 sre_compile.py:32(_compile)
    2    0.000    0.000    0.000    0.000 sre_compile.py:357(_simple)
    1    0.000    0.000    0.000    0.000 sre_compile.py:364(_compile_info)
    2    0.000    0.000    0.000    0.000 sre_compile.py:470(isstring)
    1    0.000    0.000    0.001    0.001 sre_compile.py:473(_code)
    1    0.000    0.000    0.003    0.003 sre_compile.py:488(compile)
    22    0.000    0.000    0.000    0.000 sre_compile.py:51(fixup)
    9    0.000    0.000    0.000    0.000 sre_parse.py:127(__len__)
    36    0.000    0.000    0.000    0.000 sre_parse.py:131(__getitem__)
    2    0.000    0.000    0.000    0.000 sre_parse.py:135(__setitem__)
    14    0.000    0.000    0.000    0.000 sre_parse.py:139(append)
    14/3    0.000    0.000    0.000    0.000 sre_parse.py:141(getwidth)
    1    0.000    0.000    0.000    0.000 sre_parse.py:179(__init__)
    310    0.001    0.000    0.001    0.000 sre_parse.py:184(__next)
    52    0.000    0.000    0.000    0.000 sre_parse.py:203(match)
    281    0.000    0.000    0.001    0.000 sre_parse.py:209(get)
    1    0.000    0.000    0.000    0.000 sre_parse.py:222(tell)
    1    0.000    0.000    0.000    0.000 sre_parse.py:224(seek)
    25    0.000    0.000    0.000    0.000 sre_parse.py:227(isident)
    4    0.000    0.000    0.000    0.000 sre_parse.py:233(isname)
    2    0.000    0.000    0.000    0.000 sre_parse.py:284(_escape)
    6/1    0.000    0.000    0.002    0.002 sre_parse.py:340(_parse_sub)
    9/1    0.000    0.000    0.002    0.002 sre_parse.py:418(_parse)
      1    0.000    0.000    0.000    0.000 sre_parse.py:68(__init__)
      1    0.000    0.000    0.000    0.000 sre_parse.py:702(fix_flags)
      1    0.000    0.000    0.002    0.002 sre_parse.py:714(parse)
      4    0.000    0.000    0.000    0.000 sre_parse.py:73(opengroup)
      4    0.000    0.000    0.000    0.000 sre_parse.py:84(closegroup)
     12    0.000    0.000    0.000    0.000 sre_parse.py:91(__init__)
      1    0.000    0.000    0.003    0.003 string.py:15()
      1    0.000    0.000    0.000    0.000 string.py:162(Formatter)
      1    0.000    0.000    0.000    0.000 string.py:51(_TemplateMetaclass)
      1    0.000    0.000    0.003    0.003 string.py:61(__init__)
      1    0.000    0.000    0.000    0.000 string.py:73(Template)
      2    0.000    0.000    0.000    0.000 {built-in method OpenKey}
      3    0.000    0.000    0.003    0.001 {built-in method __build_class__}
      1    0.000    0.000    0.000    0.000 {built-in method _fix_co_filename}
      1    0.000    0.000    0.000    0.000 {built-in method _getdefaultlocale}
      6    0.000    0.000    0.000    0.000 {built-in method acquire_lock}
      6    0.000    0.000    0.000    0.000 {built-in method allocate_lock}
      1    0.000    0.000    0.000    0.000 {built-in method charmap_decode}
    852    0.001    0.000    0.001    0.000 {built-in method charmap_encode}
      1    0.000    0.000    0.000    0.000 {built-in method compile}
    2/1    0.000    0.000    0.013    0.013 {built-in method exec}
      6    0.000    0.000    0.000    0.000 {built-in method get_ident}
      5    0.000    0.000    0.000    0.000 {built-in method getattr}
     26    0.000    0.000    0.000    0.000 {built-in method getlower}
     13    0.000    0.000    0.000    0.000 {built-in method hasattr}
      1    0.000    0.000    0.000    0.000 {built-in method hash}
      2    0.000    0.000    0.000    0.000 {built-in method init_builtin}
      3    0.000    0.000    0.000    0.000 {built-in method is_builtin}
      1    0.000    0.000    0.000    0.000 {built-in method is_frozen}
     43    0.000    0.000    0.000    0.000 {built-in method isinstance}
     1322/1319    0.000    0.000    0.000    0.000 {built-in method len}
      1    0.000    0.000    0.000    0.000 {built-in method loads}
      4    0.000    0.000    0.000    0.000 {built-in method max}
     28    0.000    0.000    0.000    0.000 {built-in method min}
      1    0.000    0.000    0.000    0.000 {built-in method open}
     20    0.000    0.000    0.000    0.000 {built-in method ord}
    214    0.002    0.000    0.004    0.000 {built-in method print}
      9    0.000    0.000    0.000    0.000 {built-in method release_lock}
      6    0.000    0.000    0.000    0.000 {built-in method stat}
    423    0.000    0.000    0.000    0.000 {method 'append' of 'list' objects}
      1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
      5    0.000    0.000    0.000    0.000 {method 'extend' of 'list' objects}
    212    0.000    0.000    0.000    0.000 {method 'find' of 'str' objects}
      1    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
     10    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
      1    0.000    0.000    0.000    0.000 {method 'items' of 'dict' objects}
      7    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
      2    0.000    0.000    0.000    0.000 {method 'partition' of 'str' objects}
      1    0.000    0.000    0.000    0.000 {method 'read' of '_io.FileIO' objects}
      1    0.000    0.000    0.000    0.000 {method 'read' of '_io.TextIOWrapper' objects}
      4    0.000    0.000    0.000    0.000 {method 'remove' of 'list' objects}
     17    0.000    0.000    0.000    0.000 {method 'rpartition' of 'str' objects}
      2    0.000    0.000    0.000    0.000 {method 'rsplit' of 'str' objects}
      1    0.000    0.000    0.000    0.000 {method 'strip' of 'str' objects}

These informations are very usefull when the execution time matter, since looking at what function/method are called and how many time they are called, you can locate the bottle-neck and try to eliminate them.

For example,  trying to find a  solution for a problem on Rosalind.info the script need about 3 minute to run (with correct result). After some profiling and optimization, the time needed is down to 39 seconds. The problem in that case was to see that a certain function that I write, while giving correct results,  was called way too much time and use too much time.

Optimizing this single function, both in term of numer of calls and execution time, reduce the overall execution time of about 2 minutes.

So the lesson learned here was: profile the code !  
Ok, profiling the code is not always usefull, for example if a software execute fast operations in the order of milliseconds and then wait for user input that are in the order of seconds, but it is always a good way to learn something else.