Check the processing time and the number of calls for each process in python (cProfile)

Introduction

When analyzing data, my own code is often slow. There is also a method of measuring the time by using the time function on an ad hoc basis, but this time I would like to use Profiling.

Easy to use

1. Grant the cProfile command at runtime

python -m cProfile -o File name to write profile to.prof File name for which you want to measure the processing time.py

2. Create code to look inside the prof file

import pstats


if __name__ == "__main__":
    sts = pstats.Stats("hoge.prof")
    sts.strip_dirs().sort_stats("cumtime").print_stats(30)

3. Execute the above py file

Mon Jun 15 02:22:15 2020    hoge.prof

         415990 function calls (415842 primitive calls) in 0.742 seconds

   Ordered by: cumulative time
   List reduced from 350 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
      7/1    0.000    0.000    0.742    0.742 {built-in method builtins.exec}
        1    0.000    0.000    0.742    0.742 hoge.py:1(<module>)
        1    0.052    0.052    0.734    0.734 hoge.py:54(main)
    13338    0.337    0.000    0.337    0.000 {built-in method builtins.print}
    13337    0.013    0.000    0.284    0.000 {built-in method strptime}
    13337    0.022    0.000    0.269    0.000 _strptime.py:574(_strptime_datetime)
    13337    0.136    0.000    0.248    0.000 _strptime.py:318(_strptime)
    13339    0.008    0.000    0.056    0.000 _strptime.py:26(_getlang)
    13339    0.010    0.000    0.048    0.000 locale.py:571(getlocale)
    13339    0.007    0.000    0.027    0.000 locale.py:467(_parse_localename)
    11983    0.019    0.000    0.023    0.000 hoge.py:41(nxt_hash)
    13339    0.014    0.000    0.020    0.000 locale.py:384(normalize)
    13337    0.020    0.000    0.020    0.000 {method 'match' of 're.Pattern' objects}
    13338    0.011    0.000    0.016    0.000 hoge.py:11(read_files)
    13337    0.013    0.000    0.013    0.000 {method 'groupdict' of 're.Match' objects}
    13339    0.011    0.000    0.011    0.000 {built-in method _locale.setlocale}
     11/4    0.000    0.000    0.010    0.002 <frozen importlib._bootstrap>:978(_find_and_load)
     11/4    0.000    0.000    0.010    0.002 <frozen importlib._bootstrap>:948(_find_and_load_unlocked)
     11/4    0.000    0.000    0.009    0.002 <frozen importlib._bootstrap>:663(_load_unlocked)
      6/4    0.000    0.000    0.009    0.002 <frozen importlib._bootstrap_external>:722(exec_module)
    13337    0.009    0.000    0.009    0.000 {method 'split' of 'str' objects}
    13337    0.008    0.000    0.008    0.000 {method 'format' of 'str' objects}
    40114    0.008    0.000    0.008    0.000 {method 'get' of 'dict' objects}
     16/4    0.000    0.000    0.008    0.002 <frozen importlib._bootstrap>:211(_call_with_frames_removed)
    26674    0.004    0.000    0.004    0.000 {method 'keys' of 'dict' objects}
    26675    0.004    0.000    0.004    0.000 {method 'toordinal' of 'datetime.date' objects}
    27406    0.004    0.000    0.004    0.000 {built-in method builtins.isinstance}
27111/27083    0.004    0.000    0.004    0.000 {built-in method builtins.len}
     2947    0.003    0.000    0.003    0.000 {method 'hexdigest' of '_hashlib.HASH' objects}
    13682    0.003    0.000    0.003    0.000 {method 'rstrip' of 'str' objects}

argument of sort_stats

Reference

The arguments of print_stats are listed up to the top K.

・ Ncalls: Number of calls -Tottime: Total time spent on the function of interest (excluding that time if another call is made internally) ・ Cumtime: Calculation time including internal call of tottime