Tweet
Tweet

Slide 1

Slide 1 text

@amjithr http://speakerdeck.com/amjith/ PYTHON PROFILING PYCON ■ Friday, March 15, 13

Slide 2

Slide 2 text

@amjithr WHAT’S PROFILING? Friday, March 15, 13

Slide 3

Slide 3 text

@amjithr WHAT’S PROFILING? Measuring Performance Friday, March 15, 13

Slide 4

Slide 4 text

@amjithr Hi  Friday, March 15, 13

Slide 5

Slide 5 text

@amjithr ♥ Friday, March 15, 13

Slide 6

Slide 6 text

@amjithr Friday, March 15, 13

Slide 7

Slide 7 text

@amjithr PERFORMANCE! Friday, March 15, 13

Slide 8

Slide 8 text

@amjithr cPROFILE Friday, March 15, 13

Slide 9

Slide 9 text

@amjithr $ python -m cProfile lcm.py 7780242 function calls in 3.822 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 3.822 3.822 lcm.py:12() 1 2.383 2.383 3.822 3.822 lcm.py:12(lcm) 3890120 0.724 0.000 0.724 0.000 {max} 1 0.000 0.000 0.000 0.000 {method 'disable' of 3890119 0.716 0.000 0.716 0.000 {min} Friday, March 15, 13

Slide 10

Slide 10 text

@amjithr $ python -m cProfile lcm.py 5 function calls in 0.811 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.811 0.811 lcm.py:2() 1 0.811 0.811 0.811 0.811 lcm.py:2(lcm) 1 0.000 0.000 0.000 0.000 {max} 1 0.000 0.000 0.000 0.000 {method 'disable' of 1 0.000 0.000 0.000 0.000 {min} Friday, March 15, 13

Slide 11

Slide 11 text

@amjithr $ python -m cProfile lcm.py 5 function calls in 0.811 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.811 0.811 lcm.py:2() 1 0.811 0.811 0.811 0.811 lcm.py:2(lcm) 1 0.000 0.000 0.000 0.000 {max} 1 0.000 0.000 0.000 0.000 {method 'disable' of 1 0.000 0.000 0.000 0.000 {min} TADA! Friday, March 15, 13

Slide 12

Slide 12 text

@amjithr I KNOW PROFILING Friday, March 15, 13

Slide 13

Slide 13 text

@amjithr $ python -m cProfile shorten.py 88466 function calls (86374 primitive calls) in 0.220 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.000 0.000 :1() 1 0.000 0.000 0.000 0.000 :1() 1 0.000 0.000 0.000 0.000 :1(AnnotatedCTE) 1 0.000 0.000 0.000 0.000 :1(AnnotatedCase) 1 0.000 0.000 0.000 0.000 :1(AnnotatedCast) 1 0.000 0.000 0.000 0.000 :1(AnnotatedClauseElement) 1 0.000 0.000 0.000 0.000 :1(AnnotatedClauseList) 1 0.000 0.000 0.000 0.000 :1(AnnotatedColumn) 1 0.000 0.000 0.000 0.000 :1(AnnotatedColumnClause) 1 0.000 0.000 0.000 0.000 :1(AnnotatedColumnElement) 1 0.000 0.000 0.000 0.000 :1(AnnotatedCompoundSelect) 1 0.000 0.000 0.000 0.000 :1(AnnotatedDelete) .... .... ..... ..... .... ...... .... .... ..... ..... .... ...... Friday, March 15, 13

Slide 14

Slide 14 text

@amjithr SAVE & ANALYZE PROFILE ANALYSIS Friday, March 15, 13

Slide 15

Slide 15 text

@amjithr $ python -m cProfile -o file.prof script.py SAVE Friday, March 15, 13

Slide 16

Slide 16 text

@amjithr $ python -m cProfile -o file.prof script.py SAVE ANALYZE >>> import pstats >>> p = pstats.Stats('shorten.prof') >>> p.sort_stats('calls') >>> p.print_stats(5) List reduced from 1979 to 5 due to restriction <5> ncalls tottime percall cumtime percallfilename:lineno(function) 8053 0.007 0.000 0.007 0.000 {isinstance} 2794 0.004 0.000 0.004 0.000 {built-in method match} Friday, March 15, 13

Slide 17

Slide 17 text

@amjithr  RunSnakeRun Friday, March 15, 13

Slide 18

Slide 18 text

@amjithr Friday, March 15, 13

Slide 19

Slide 19 text

@amjithr THAT IS PERFECTION! Friday, March 15, 13

Slide 20

Slide 20 text

@amjithr THAT IS PERFECTION! JUST ONE CATCH. Friday, March 15, 13

Slide 21

Slide 21 text

@amjithr $ time python fib.py python fib.py 5.43s user 0.01s system 99% cpu 5.451 total $ time python -m cProfile fib.py python -m cProfile fib.py 9.63s user 0.04s system 99% cpu 9.670 total Friday, March 15, 13

Slide 22

Slide 22 text

@amjithr $ time python fib.py python fib.py 5.43s user 0.01s system 99% cpu 5.451 total $ time python -m cProfile fib.py python -m cProfile fib.py 9.63s user 0.04s system 99% cpu 9.670 total ~ x OVERHEAD Friday, March 15, 13

Slide 23

Slide 23 text

@amjithr You can’t run it in production Friday, March 15, 13

Slide 24

Slide 24 text

@amjithr PROFILER IN PRODUCTION Friday, March 15, 13

Slide 25

Slide 25 text

@amjithr SLOW PRODUCTION NOT REALISTIC cProfile Friday, March 15, 13

Slide 26

Slide 26 text

@amjithr CRITICAL FUNCTIONS TARGETED PROFILING Friday, March 15, 13

Slide 27

Slide 27 text

@amjithr HTTP://GIT.IO/ JUoiw from profile_func import profile_func @profile_func def lcm(arg1, arg2): mx = i = max(arg1, arg2) mn = min(arg1, arg2) while i < (arg1 * arg2): if i % mn == 0: return i i += mx return(arg1 * arg2) Friday, March 15, 13

Slide 28

Slide 28 text

@amjithr TARGETED PROFILING PROs CONs Less overhead Still slow Finer Resolution Manual Friday, March 15, 13

Slide 29

Slide 29 text

@amjithr TARGETED HYBRID PROFILING WEB APPS ONLY NEWRELIC Friday, March 15, 13

Slide 30

Slide 30 text

@amjithr https://newrelic.com/docs/python/instrumented-python-packages WEB FRAMEWORKS VIEW HANDLERS SQL CALLS TARGET Friday, March 15, 13

Slide 31

Slide 31 text

@amjithr TOP-LEVEL FUNCTION ONLY TIMING DATA CAPTURE ARGUMENTS HYBRID PROFILING Friday, March 15, 13

Slide 32

Slide 32 text

@amjithr TRANSACTION TRACE Friday, March 15, 13

Slide 33

Slide 33 text

@amjithr NON-INSTRUMENTED CODE Friday, March 15, 13

Slide 34

Slide 34 text

@amjithr HYBRID PROFILING PROs CONs FAST SEMI-MANUAL FUNCTION ARGS LIMITED INSTRUMENTATION Friday, March 15, 13

Slide 35

Slide 35 text

@amjithr STATISTICAL PROFILER Friday, March 15, 13

Slide 36

Slide 36 text

@amjithr Friday, March 15, 13

Slide 37

Slide 37 text

@amjithr WAT? Friday, March 15, 13

Slide 38

Slide 38 text

@amjithr OVERLY ATTACHED Friday, March 15, 13

Slide 39

Slide 39 text

@amjithr OVERLY ATTACHED Interrupt Inquire Collate Friday, March 15, 13

Slide 40

Slide 40 text

@amjithr OVERLY ATTACHED Interrupt Inquire Collate Friday, March 15, 13

Slide 41

Slide 41 text

@amjithr OVERLY ATTACHED  Interrupt Inquire Collate Friday, March 15, 13

Slide 42

Slide 42 text

@amjithr OVERLY ATTACHED  ◴ Interrupt Inquire Collate Friday, March 15, 13

Slide 43

Slide 43 text

@amjithr Interrupt Inquire Collate STATISTICAL PROFILER ⏳ Friday, March 15, 13

Slide 44

Slide 44 text

@amjithr UNIX SIGNALS THREADS INTERRUPT Friday, March 15, 13

Slide 45

Slide 45 text

@amjithr INQUIRE Stack frame of every thread Friday, March 15, 13

Slide 46

Slide 46 text

@amjithr >>> import sys, traceback # Get stack frames of every thread >>> frames = sys._current_frames() # Extract useful info from frame # (file, line_no, function, line) >>> traceback.extract_stack(frame) [('code.py', 88, 'runsource', 'return'), ('code.py', 110, 'runcode', 'print')] INQUIRE Friday, March 15, 13

Slide 47

Slide 47 text

@amjithr EXISTING TOOLS Friday, March 15, 13

Slide 48

Slide 48 text

@amjithr http://pypi.python.org/pypi/statprof StatProf UNIX SIGNALS CLI Friday, March 15, 13

Slide 49

Slide 49 text

@amjithr HTTP://GIT.IO/UdfHGQ PLOP UNIX SIGNALS D Call Graph Friday, March 15, 13

Slide 50

Slide 50 text

@amjithr Friday, March 15, 13

Slide 51

Slide 51 text

@amjithr http://newrelic.com/docs/features/thread-profiler NewRelic Threads GUI Friday, March 15, 13

Slide 52

Slide 52 text

@amjithr Friday, March 15, 13

Slide 53

Slide 53 text

@amjithr FINALE DETERMINISTIC + STATISTICAL Friday, March 15, 13

Slide 54

Slide 54 text

@amjithr X-Ray Sessions (SECRET BETA) Friday, March 15, 13

Slide 55

Slide 55 text

@amjithr DETERMINISTIC Friday, March 15, 13

Slide 56

Slide 56 text

@amjithr STATISTICAL Friday, March 15, 13

Slide 57

Slide 57 text

@amjithr HISTOGRAM Friday, March 15, 13

Slide 58

Slide 58 text

@amjithr RESPONSE & THROUGHPUT Friday, March 15, 13

Slide 59

Slide 59 text

@amjithr PROFILING IN PRODUCTION Friday, March 15, 13

Slide 60

Slide 60 text

@amjithr QUESTIONS Friday, March 15, 13

Slide 61

Slide 61 text

Questions? • Promo Code: pycon13 • 30 days of Pro. • Free T-shirt. • In-depth data. Friday, March 15, 13