Mateusz Mazurek – programista z pasją

Python, architektura, ciekawostki ze świata IT

    • Programowanie Programowanie webowe Utrzymanie oprogramowania

    Profilowanie Pythona z yappi

    Mateusz M. Opublikowane w
    🕑 8 minuty czytania

    Cześć.

    Pewnie każdy z nas spotkał się z programem który działał wolno. Pół biedy jeśli jesteśmy tylko jego użytkownikami, gorzej jeśli jesteśmy jego współautorami. W tym drugim przypadku czeka nas niezwykle interesująca przygoda związana z profilowaniem programu, czyli szukaniem który fragment kodu odpowiada za jego wolne działanie.

    Yappi przybywa z pomocą

    W tym zadaniu może pomóc nam niezwykle prosty i przyjemny w użyciu profiler o nazwie „yappi”. Na początek zainstalujmy go poleceniem pip:

    1
    $ pip install yappi

    Przykład

    Załóżmy, że mamy taki kod:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    import random
    import time
    from typing import List


    def function1():
        for x in range(10):
            print(x)

        function2()


    def function2():
        random_numbers: List[int] = []
        for x in range(100000):
            random_numbers.insert(0, random.randint(1, 10))


    start: float = time.perf_counter()
    function2()
    function1()

    print(f"Program took: {time.perf_counter() - start} seconds")

    Jego uruchomienie pokaże nam, że wykonuje się on około 3 sekund. To dużo jak na wylosowanie 100000 liczb i wypisanie 10 liczb na ekran.

    Oczywiście w tak prostym przykładzie moglibyśmy skorzystać z perf_counter i na piechotę wyprofilować ten kawałek kodu. Problem w tym, że jeśli przytoczę tu bardziej skomplikowany przykład, to zaciemni on odbiór tego co chcę pokazać – czyli profilowania z użyciem yappi. Więc na chwilę uznajmy, że powyższy kawałek kodu jest częścią wielkiego systemu legacy.

    No dobra, to dodajmy do kodu zebranie statystyk yappi:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    import random
    import yappi
    from typing import List


    def function1():
        for x in range(10):
            print(x)

        function2()


    def function2():
        random_numbers: List[int] = []
        for x in range(100000):
            random_numbers.insert(0, random.randint(1, 10))


    yappi.start()

    function2()
    function1()

    yappi.get_func_stats().print_all()

    gdzie rezultat to:

    1
    2
    3
    4
    5
    6
    name                                  ncall  tsub      ttot      tavg      
    ../yappi_testss/main.py:13 function2  2      0.273683  3.911898  1.955949
    ..k/yappi_testss/main.py:6 function1  1      0.000071  1.938713  1.938713
    ..on3.8/random.py:244 Random.randint  200..  0.194136  0.977574  0.000005
    ..3.8/random.py:200 Random.randrange  200..  0.252281  0.783438  0.000004
    ..Random._randbelow_with_getrandbits  200..  0.339139  0.531157  0.000003

    a poszczególne kolumny oznaczają:

    • ncall – ilość wywołań funkcji
    • tsub – ilość czasu spędzonego w danej funkcji wykluczając wywołania funkcji wewnątrz niej
    • ttot – ilość czasu spędzonego w danej funkcji wliczająca wywołania funkcji wewnątrz niej
    • tavg – średni czas spędzony w danej funkcji wliczająca wywołania funkcji wewnątrz niej

    Jak czytać wynik profilowania?

    Przyjrzyjmy się jeszcze raz wynikowi:

    1
    2
    3
    4
    5
    6
    name                                  ncall  tsub      ttot      tavg      
    ../yappi_testss/main.py:13 function2  2      0.273683  3.911898  1.955949
    ..k/yappi_testss/main.py:6 function1  1      0.000071  1.938713  1.938713
    ..on3.8/random.py:244 Random.randint  200..  0.194136  0.977574  0.000005
    ..3.8/random.py:200 Random.randrange  200..  0.252281  0.783438  0.000004
    ..Random._randbelow_with_getrandbits  200..  0.339139  0.531157  0.000003

    Interesują nas trzy pierwsze linijki, bo dwie ostatnie to bebechy funkcji randint. Widzimy tutaj, że funkcja function2 została wykonana dwa razy, funkcja function1 raz i funkcja randint… Dużo razy. Od razu łatwo zauważyć, że czas jaki został poświęcony na funkcję randint jest pomijalny, więc zastanówmy się nad dwoma pierwszymi wierszami.

    Widzimy, że czas spędzony w funkcji function1 wyłączając wywołania innych funkcji (tsub) wewnątrz niej jest bardzo mały, natomiast czas ttot wynosi prawie 2s, czyli około 2/3 całego czasu wykonywania się programu. Potwierdza nam to wiersz mówiący o funkcji function2 – program spędził w niej prawie 4 sekundy. Ale stop, czekaj. Jak to 4 sekundy skoro program wykonywał się około 3? Te 3 sekundy zmierzyliśmy poprawnie, ale przed dodaniem profilowania a ono robi narzut około jednej sekundy, stąd takie a nie inne wyniki.

    Patrząc na podane przez yappi czas możemy dojść do wniosku:

    Funkcja function2 wykonuje się długo ale problemem nie jest randint.

    W takim razie co jest problemem?

    Czekaj, stop!

    Podoba Ci się to co tworzę? Jeśli tak to zapraszam Cię do zapisania się na newsletter:
    a w ramach prezentu otrzymasz całkowicie za darmo, dwa dokumenty PDF „6 (nie zawsze oczywistych) błędów popełnianych podczas nauki programowania” który jest jednym z efektów ponad siedmioletniej pracy i obserwacji rozwoju niejednego programisty oraz „Wstęp do testowania w Pythonie”, będący wprowadzeniem do biblioteki PyTest.
    Jeśli to Cię interesuje to zapraszam również na swoje social media.

    Jak i do ewentualnego postawienia mi kawy :)
    Postaw mi kawę na buycoffee.to

    Profilowanie funkcji wbudowanych

    Dodajmy do naszego wywołania yappi.start() argument 

    builtins=True

    Powie to yappi, żeby profilować również funkcje wbudowane. Odpalamy program i widzimy:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    name                                  ncall  tsub      ttot      tavg      
    ../yappi_testss/main.py:15 function2  2      0.269383  3.930326  1.965163
    ..method 'insert' of 'list' objects>  200..  2.677256  2.677256  0.000013
    ..k/yappi_testss/main.py:8 function1  1      0.000070  1.975958  1.975958
    ..on3.8/random.py:244 Random.randint  200..  0.198297  0.983687  0.000005
    ..3.8/random.py:200 Random.randrange  200..  0.252468  0.785390  0.000004
    ..Random._randbelow_with_getrandbits  200..  0.338203  0.532921  0.000003
    ..bits' of '_random.Random' objects>  319..  0.122377  0.122377  0.000000
    ..hod 'bit_length' of 'int' objects>  200..  0.072341  0.072341  0.000000
    builtins.print                        10     0.000030  0.000030  0.000003

    I tutaj już od razu widać, gdzie jest problem. A dokładniej problemem jest użycie funkcji insert na obiekcie listy. Zerknij jeszcze raz w kod tej funkcji:

    1
    2
    3
    4
    def function2():
        random_numbers: List[int] = []
        for x in range(100000):
            random_numbers.insert(0, random.randint(1, 10))

    Za każdym obiegiem pętli dodajemy element na początku listy co sprawia, że wszystkie wcześniej dodane elementy muszą zostać przesunięte.

    Jeśli specyfikacja pozwala nam dodawać elementy na koniec to możemy po prostu zamienić funkcje insert na append. Jeśli jednak sytuacja z jakiegoś powodu wymaga od nas dodawania elementów na początek, to powinniśmy skorzystać z obiektu deque (double-ended queue czyli lista dwukierunkowa) i metody appendLeft:

    1
    2
    3
    4
    def function2():
        random_numbers: deque[int] = deque()
        for x in range(100000):
            random_numbers.append(random.randint(1, 10))

    co spowoduje znaczne przyśpieszenie wykonywania się programu:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    name                                  ncall  tsub      ttot      tavg      
    ../yappi_testss/main.py:16 function2  2      0.213788  1.212847  0.606424
    ..on3.8/random.py:244 Random.randint  200..  0.179873  0.926948  0.000005
    ..3.8/random.py:200 Random.randrange  200..  0.235202  0.747075  0.000004
    ..k/yappi_testss/main.py:9 function1  1      0.000164  0.608285  0.608285
    ..Random._randbelow_with_getrandbits  200..  0.322786  0.511872  0.000003
    ..bits' of '_random.Random' objects>  319..  0.117625  0.117625  0.000000
    ..d' of 'collections.deque' objects>  200..  0.072111  0.072111  0.000000
    ..hod 'bit_length' of 'int' objects>  200..  0.071462  0.071462  0.000000
    builtins.print                        10     0.000030  0.000030  0.000003

    Pisałem o tym w artykule: Czego nie robić w Pythonie? #3

    Przyśpieszenie będzie również widoczne w czasie wykonywania się programu:

    1
    Program took: 0.16730287100654095 seconds

    Co jeszcze potrafi yappi?

    Za pomocą tej biblioteki można profilować programy wielowątkowe jak i te napisane w asyncio czy gevencie. To spory plus, bo jednak ich zasada działania znacząco różni się od programów synchronicznych. Poza tym yappi pozwala manipulować rezultatem profilowania, czyli po prostu inaczej go posortować czy wyfiltrować tylko te funkcje na których nam zależy.

    Yappi posiada również dwa zegary: CPU i Wall. Ten pierwszy liczy czas wykonywania się wątku (a wiec np nie policzy czasu sleepów) gdzie ten drugi już da sobie z tym radę.

    Popatrzmy na przykład:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    import threading, time, yappi

    def _sleep(how_long: int):
        time.sleep(how_long)

    first_thread = threading.Thread(target=_sleep, args=(1, ))
    second_thread = threading.Thread(target=_sleep, args=(3, ))

    yappi.start()

    for t in (first_thread, second_thread):
        t.start()

    for t in (first_thread, second_thread):
        t.join()

    yappi.get_func_stats().print_all()
    yappi.get_thread_stats().print_all()

    którego rezultatem jest:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    Clock type: CPU
    Ordered by: totaltime, desc

    name                                  ncall  tsub      ttot      tavg      
    ..3.10/threading.py:1064 Thread.join  2      0.000048  0.000446  0.000223
    ..:1102 Thread._wait_for_tstate_lock  2      0.000068  0.000366  0.000183
    ..3.10/threading.py:916 Thread.start  2      0.000030  0.000277  0.000138
    ...10/threading.py:1028 Thread._stop  2      0.000097  0.000223  0.000111
    ..on3.10/threading.py:589 Event.wait  2      0.000024  0.000159  0.000079
    ..64/python3.10/threading.py:942 run  2      0.000034  0.000117  0.000059
    ..10/threading.py:288 Condition.wait  2      0.000043  0.000114  0.000057
    ..ng.py:800 _maintain_shutdown_locks  2      0.000039  0.000101  0.000051
    ..mmazurek/ast_blog/aaaa.py:3 _sleep  2      0.000025  0.000083  0.000042
    ..on3.10/threading.py:810 <listcomp>  2      0.000034  0.000050  0.000025
    ..0/threading.py:1430 current_thread  2      0.000019  0.000025  0.000013
    ..reading.py:264 Condition.__enter__  2      0.000008  0.000011  0.000006
    ..reading.py:279 Condition._is_owned  2      0.000007  0.000011  0.000005
    ..10/threading.py:1183 Thread.daemon  2      0.000010  0.000010  0.000005
    ..hreading.py:267 Condition.__exit__  2      0.000007  0.000009  0.000005
    ..3.10/threading.py:553 Event.is_set  4      0.000009  0.000009  0.000002
    ...py:276 Condition._acquire_restore  2      0.000006  0.000009  0.000004
    ..ing.py:273 Condition._release_save  2      0.000005  0.000007  0.000004

    name           id     tid              ttot      scnt        
    _MainThread    0      140509926287168  0.003699  5        
    Thread         1      140509690459712  0.000172  2        
    Thread         2      140509682067008  0.000065  2

    natomiast jeśli przed yappi.start() dodamy yappi.set_clock_type(„wall”) to nasze statyki pokażą nam więcej prawdy:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    Clock type: WALL
    Ordered by: totaltime, desc

    name                                  ncall  tsub      ttot      tavg      
    ..64/python3.10/threading.py:942 run  2      0.000028  4.003896  2.001948
    ..mmazurek/ast_blog/aaaa.py:3 _sleep  2      0.000017  4.003868  2.001934
    ..3.10/threading.py:1064 Thread.join  2      0.000025  3.002742  1.501371
    ..:1102 Thread._wait_for_tstate_lock  2      0.000044  3.002703  1.501351
    ..3.10/threading.py:916 Thread.start  2      0.000033  0.000409  0.000204
    ..on3.10/threading.py:589 Event.wait  2      0.000012  0.000278  0.000139
    ..10/threading.py:288 Condition.wait  2      0.000017  0.000258  0.000129
    ...10/threading.py:1028 Thread._stop  2      0.000052  0.000095  0.000047
    ..ng.py:800 _maintain_shutdown_locks  2      0.000019  0.000038  0.000019
    ..on3.10/threading.py:810 <listcomp>  2      0.000010  0.000013  0.000006
    ..0/threading.py:1430 current_thread  2      0.000010  0.000012  0.000006
    ...py:276 Condition._acquire_restore  2      0.000007  0.000009  0.000005
    ..hreading.py:267 Condition.__exit__  2      0.000005  0.000005  0.000002
    ..reading.py:279 Condition._is_owned  2      0.000003  0.000004  0.000002
    ..10/threading.py:1183 Thread.daemon  2      0.000003  0.000003  0.000002
    ..3.10/threading.py:553 Event.is_set  4      0.000003  0.000003  0.000001
    ..reading.py:264 Condition.__enter__  2      0.000001  0.000003  0.000002
    ..ing.py:273 Condition._release_save  2      0.000003  0.000003  0.000002

    name           id     tid              ttot      scnt        
    _MainThread    0      140327343785792  3.004685  5        
    Thread         2      140327099819584  3.002720  2        
    Thread         1      140327108212288  1.001260  2

    A co jeśli nie yappi?

    Zawsze można skorzystać z cProfile’a. Jest dostarczony wraz z Pythonem i to jego niewątpliwa zaleta. Można go wywołać tak:

    1
    python -m cProfile nazwa_pliku.py

    i dla pierwszego przykładu dostaniemy:

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    22
    23
    24
    25
    26
    27
    28
    29
    30
    31
    32
    33
    34
    35
    36
    37
    38
    39
    40
    41
    42
    43
    44
    45
    46
    47
    48
    49
    50
    51
    52
    53
    54
    55
    56
    57
    58
    59
    60
    61
    62
    63
    64
    65
    66
    67
    68
    69
    70
    71
    72
    73
    74
    75
    76
    77
    78
    79
    80
    81
    82
    83
    84
    85
    86
    87
    88
    89
    90
    91
    92
    93
    94
    95
    96
    97
    98
    99
    100
    101
    102
    103
    104
    105
    106
    107
    108
    109
    110
    111
    112
    113
    114
    115
    116
    117
    118
    119
    120
    121
    122
    123
    124
             1921445 function calls (1921418 primitive calls) in 3.387 seconds

       Ordered by: standard name

       ncalls  tottime  percall  cumtime  percall filename:lineno(function)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:100(acquire)
          6/1    0.000    0.000    0.002    0.002 <frozen importlib._bootstrap="">:1022(_find_and_load)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:125(release)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:165(__init__)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:169(__enter__)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:173(__exit__)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:179(_get_module_lock)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:198(cb)
         10/1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap="">:233(_call_with_frames_removed)
          110    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:244(_verbose_message)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:357(__init__)
            8    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:391(cached)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:404(parent)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:412(has_location)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:48(_new_module)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:492(_init_module_attrs)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:564(module_from_spec)
          6/1    0.000    0.000    0.002    0.002 <frozen importlib._bootstrap="">:664(_load_unlocked)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:71(__init__)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:746(find_spec)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:826(find_spec)
           30    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:893(__enter__)
           30    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap="">:897(__exit__)
            6    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap="">:921(_find_spec)
          6/1    0.000    0.000    0.002    0.002 <frozen importlib._bootstrap="">:987(_find_and_load_unlocked)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1040(__init__)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1065(get_filename)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1070(get_data)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1089(path_stats)
            4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1163(__init__)
            4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1174(create_module)
            4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1182(exec_module)
           96    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:126(_path_join)
           96    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:128(<listcomp>)
            4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:132(_path_split)
            8    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:134(<genexpr>)
           28    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1356(_path_importer_cache)
            6    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap_external="">:1399(_get_spec)
           30    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:140(_path_stat)
            6    0.000    0.000    0.001    0.000 <frozen importlib._bootstrap_external="">:1431(find_spec)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:150(_path_is_mode_type)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1531(_get_spec)
           22    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:1536(find_spec)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:159(_path_isfile)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:180(_path_isabs)
            4    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:380(cache_from_source)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:510(_get_cached)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:542(_check_name_wrapper)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:585(_classify_pyc)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:618(_validate_timestamp_pyc)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:670(_compile_bytecode)
           22    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:71(_relax_case)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:721(spec_from_file_location)
            6    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:84(_unpack_uint32)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:874(create_module)
          2/1    0.000    0.000    0.001    0.001 <frozen importlib._bootstrap_external="">:877(exec_module)
            2    0.000    0.000    0.000    0.000 <frozen importlib._bootstrap_external="">:950(get_code)
            6    0.000    0.000    0.000    0.000 __init__.py:77(find_spec)
            6    0.000    0.000    0.000    0.000 __init__.py:82(<lambda>)
            6    0.000    0.000    0.000    0.000 _virtualenv.py:54(find_spec)
            1    0.000    0.000    3.387    3.387 aaaa.py:1(<module>)
            2    0.139    0.070    3.385    1.692 aaaa.py:12(function2)
            1    0.000    0.000    1.693    1.693 aaaa.py:5(function1)
            1    0.000    0.000    0.000    0.000 bisect.py:1(<module>)
            1    0.000    0.000    0.001    0.001 random.py:1(<module>)
            1    0.000    0.000    0.000    0.000 random.py:103(Random)
            1    0.000    0.000    0.000    0.000 random.py:119(__init__)
            1    0.000    0.000    0.000    0.000 random.py:128(seed)
            1    0.000    0.000    0.000    0.000 random.py:219(__init_subclass__)
       200000    0.126    0.000    0.177    0.000 random.py:239(_randbelow_with_getrandbits)
       200000    0.204    0.000    0.425    0.000 random.py:292(randrange)
       200000    0.073    0.000    0.497    0.000 random.py:366(randint)
            1    0.000    0.000    0.000    0.000 random.py:813(SystemRandom)
            2    0.000    0.000    0.000    0.000 {built-in method _imp._fix_co_filename}
           42    0.000    0.000    0.000    0.000 {built-in method _imp.acquire_lock}
            4    0.000    0.000    0.000    0.000 {built-in method _imp.create_dynamic}
            4    0.000    0.000    0.000    0.000 {built-in method _imp.exec_dynamic}
            6    0.000    0.000    0.000    0.000 {built-in method _imp.is_builtin}
            6    0.000    0.000    0.000    0.000 {built-in method _imp.is_frozen}
           42    0.000    0.000    0.000    0.000 {built-in method _imp.release_lock}
       600000    0.043    0.000    0.043    0.000 {built-in method _operator.index}
           12    0.000    0.000    0.000    0.000 {built-in method _thread.allocate_lock}
           12    0.000    0.000    0.000    0.000 {built-in method _thread.get_ident}
            2    0.000    0.000    0.000    0.000 {built-in method builtins.__build_class__}
          3/1    0.000    0.000    3.387    3.387 {built-in method builtins.exec}
           42    0.000    0.000    0.000    0.000 {built-in method builtins.getattr}
           35    0.000    0.000    0.000    0.000 {built-in method builtins.hasattr}
           34    0.000    0.000    0.000    0.000 {built-in method builtins.isinstance}
            8    0.000    0.000    0.000    0.000 {built-in method builtins.len}
            6    0.000    0.000    0.000    0.000 {built-in method builtins.locals}
            4    0.000    0.000    0.000    0.000 {built-in method builtins.max}
           10    0.000    0.000    0.000    0.000 {built-in method builtins.print}
            6    0.000    0.000    0.000    0.000 {built-in method from_bytes}
            2    0.000    0.000    0.000    0.000 {built-in method io.open_code}
            2    0.000    0.000    0.000    0.000 {built-in method marshal.loads}
            1    0.000    0.000    0.000    0.000 {built-in method math.exp}
            2    0.000    0.000    0.000    0.000 {built-in method math.log}
            1    0.000    0.000    0.000    0.000 {built-in method math.sqrt}
           10    0.000    0.000    0.000    0.000 {built-in method posix.fspath}
            6    0.000    0.000    0.000    0.000 {built-in method posix.getcwd}
            1    0.000    0.000    0.000    0.000 {built-in method posix.register_at_fork}
           30    0.000    0.000    0.000    0.000 {built-in method posix.stat}
            1    0.000    0.000    0.000    0.000 {function Random.seed at 0x7f7cf91e2b90}
            2    0.000    0.000    0.000    0.000 {method '__exit__' of '_io._IOBase' objects}
           12    0.000    0.000    0.000    0.000 {method '__exit__' of '_thread.lock' objects}
       200000    0.020    0.000    0.020    0.000 {method 'bit_length' of 'int' objects}
            1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}
           10    0.000    0.000    0.000    0.000 {method 'endswith' of 'str' objects}
            6    0.000    0.000    0.000    0.000 {method 'format' of 'str' objects}
           12    0.000    0.000    0.000    0.000 {method 'get' of 'dict' objects}
       319983    0.031    0.000    0.031    0.000 {method 'getrandbits' of '_random.Random' objects}
       200000    2.748    0.000    2.748    0.000 {method 'insert' of 'list' objects}
          100    0.000    0.000    0.000    0.000 {method 'join' of 'str' objects}
            6    0.000    0.000    0.000    0.000 {method 'pop' of 'dict' objects}
            2    0.000    0.000    0.000    0.000 {method 'read' of '_io.BufferedReader' objects}
            4    0.000    0.000    0.000    0.000 {method 'rfind' of 'str' objects}
           38    0.000    0.000    0.000    0.000 {method 'rpartition' of 'str' objects}
          196    0.000    0.000    0.000    0.000 {method 'rstrip' of 'str' objects}
            6    0.000    0.000    0.000    0.000 {method 'startswith' of 'str' objects}

    gdzie również od razu widać problem z metoda insert.

    Wizualizacja cProfile’a

    Zamiast patrzeć w tekstową reprezentację wyniku działania cProfile’a możemy przedstawić ją graficznie. Pomoże nam w tym biblioteka snakeviz. Zainstalujmy ją:

    1
    pip install snakeviz

    Ten wizualizator, jak i większość innych, pracuje na pliku wynikowym cProfile’a, żeby go utworzyć, trzeba nieco zmodyfikować sposób uruchamiania profilowania, dodając do niego przełącznik -o którego parametrem jest nazwa pliku gdzie rezultat zostanie zapisany, czyli np:

    1
    python -m cProfile -o program.prof nazwa_pliku.py

    Teraz możemy już wywołać snakeviz’a:

    1
    snakeviz program.prof

    który uruchomi nam prostą stronkę z interaktywnymi wykresami:

    Podsumowując

    Yappi jak i cProfile pokazują, że profilowanie programów nie musi być udręką. Chociaż oczywiście nie można powiedzieć, żeby to było łatwe zdanie, to mam nadzieję, że ten artykuł pomoże Ci kiedyś usprawnić nie jeden proces.

    Dzięki za wizytę,
    Mateusz Mazurek

    A może wolisz nowości na mail?

    Podobne artykuły:

    Otagowano:
    Subskrybuj
    Powiadom o
    guest

    Witryna wykorzystuje Akismet, aby ograniczyć spam. Dowiedz się więcej jak przetwarzane są dane komentarzy.

    0 komentarzy
    Inline Feedbacks
    View all comments

    Cześć

    Muszę przyznać że niesamowicie fajnie Cię tu widzieć :)

    Informatyką pasjonuję się już od kilkunastu lat a ten blog jest odzwierciedleniem moich zainteresowań jak i chęcią podzielenia się nimi. Jeśli uważasz że znalazłeś tu coś interesującego – podziel się tym z innymi :)

    Dzięki ogromne!

    Serie artykułów

    serie
    Zerknij na pełne serie artykułów!

    Czytam aktualnie

    Przeczytane książki