Programowanie

Profilowanie Pythona z yappi

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:

Aby potwierdzić swoją subskrypcję, odbierz pocztę i kliknij w link potwierdzający:) jeśli maila nie ma to poczekaj chwile i/lub sprawdź folder spam/inne/oferty itp :)

Aby potwierdzić swoją subskrypcję, odbierz pocztę i kliknij w link potwierdzający:) jeśli maila nie ma to poczekaj chwile i/lub sprawdź folder spam/inne/oferty itp :)
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 :)

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
Tagi: profilowaniepythonwydajnośćyappi
2 lata ago
Mateusz M.

Zostaw komentarz

Podobne wpisy

Ostatnie wpisy

Podsumowanie: maj, czerwiec, lipiec i sierpień 2024

Oj daaawnoo mnie tu nie było. Ale wakacje to był czas dużej liczby intensywnych wyjazdów i tak naprawdę, dopiero jakoś… Read More

2 miesiące ago

Podsumowanie: kwiecień 2024

Cześć! Zapraszam na krótkie podsumowanie kwietnia. Wyjazd do Niemiec A dokładniej pod granicę z Francją. Chrześnica miała pierwszą komunię. Po… Read More

6 miesięcy ago

Podsumowanie: luty i marzec 2024

Ostatnio tygodnie były tak bardzo wypełnione, że nie udało mi się napisać nawet krótkiego podsumowanie. Więc dziś zbiorczo podsumuję luty… Read More

7 miesięcy ago

Podsumowanie: styczeń 2024

Zapraszam na krótkie podsumowanie miesiąca. Książki W styczniu przeczytałem "Homo Deus: Historia jutra". Książka łudząco podoba do wcześniejszej książki tego… Read More

9 miesięcy ago

Podsumowanie roku 2023

Cześć! Zapraszam na podsumowanie roku 2023. Książki Zacznijmy od książek. W tym roku cel 35 książek nie został osiągnięty. Niemniej… Read More

10 miesięcy ago

Podsumowanie: grudzień 2023

Zapraszam na krótkie podsumowanie miesiąca. Książki W grudniu skończyłem czytać Mein Kampf. Nudna książka. Ciekawsze fragmenty można by było streścić… Read More

10 miesięcy ago