Tweet
Tweet

Slide 1

Slide 1 text

@amjithr THREAD PROFILING DJANGOCON EU ■ Wednesday, May 15, 13

Slide 2

Slide 2 text

@amjithr Hi  Wednesday, May 15, 13

Slide 3

Slide 3 text

@amjithr ♥ Wednesday, May 15, 13

Slide 4

Slide 4 text

Wednesday, May 15, 13

Slide 5

Slide 5 text

@amjithr PERFORMANCE! Wednesday, May 15, 13

Slide 6

Slide 6 text

@amjithr WHAT’S PROFILING? Wednesday, May 15, 13

Slide 7

Slide 7 text

@amjithr WHAT’S PROFILING? Measuring Performance Wednesday, May 15, 13

Slide 8

Slide 8 text

@amjithr cPROFILE Wednesday, May 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} Wednesday, May 15, 13

Slide 10

Slide 10 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) .... .... ..... ..... .... ...... .... .... ..... ..... .... ...... Wednesday, May 15, 13

Slide 11

Slide 11 text

@amjithr  RunSnakeRun Wednesday, May 15, 13

Slide 12

Slide 12 text

@amjithr Wednesday, May 15, 13

Slide 13

Slide 13 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 Wednesday, May 15, 13

Slide 14

Slide 14 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 ~ % OVERHEAD Wednesday, May 15, 13

Slide 15

Slide 15 text

@amjithr You can’t run it in production Wednesday, May 15, 13

Slide 16

Slide 16 text

@amjithr PROFILER IN PRODUCTION Wednesday, May 15, 13

Slide 17

Slide 17 text

@amjithr SLOW PRODUCTION NOT REALISTIC cProfile Wednesday, May 15, 13

Slide 18

Slide 18 text

@amjithr CRITICAL FUNCTIONS HYBRID PROFILING TARGETED PROFILING Wednesday, May 15, 13

Slide 19

Slide 19 text

@amjithr WEB FRAMEWORKS VIEW HANDLERS SQL CALLS TARGET Wednesday, May 15, 13

Slide 20

Slide 20 text

@amjithr TRANSACTION TRACE Wednesday, May 15, 13

Slide 21

Slide 21 text

@amjithr NON-INSTRUMENTED CODE Wednesday, May 15, 13

Slide 22

Slide 22 text

@amjithr Cool Story, Bro! Can we talk about statistical profilers? Wednesday, May 15, 13

Slide 23

Slide 23 text

@amjithr STATISTICAL THREAD PROFILER Wednesday, May 15, 13

Slide 24

Slide 24 text

@amjithr Wednesday, May 15, 13

Slide 25

Slide 25 text

@amjithr WAT? Wednesday, May 15, 13

Slide 26

Slide 26 text

@amjithr OVERLY ATTACHED Wednesday, May 15, 13

Slide 27

Slide 27 text

@amjithr OVERLY ATTACHED Interrupt Inquire Collate Wednesday, May 15, 13

Slide 28

Slide 28 text

@amjithr OVERLY ATTACHED Interrupt Inquire Collate Wednesday, May 15, 13

Slide 29

Slide 29 text

@amjithr OVERLY ATTACHED  Interrupt Inquire Collate Wednesday, May 15, 13

Slide 30

Slide 30 text

@amjithr OVERLY ATTACHED  ◴ Interrupt Inquire Collate Wednesday, May 15, 13

Slide 31

Slide 31 text

@amjithr  ◴ Interrupt Inquire Collate STATISTICAL PROFILER Wednesday, May 15, 13

Slide 32

Slide 32 text

@amjithr Wednesday, May 15, 13

Slide 33

Slide 33 text

@amjithr SIGNALS THREADS INTERRUPT Wednesday, May 15, 13

Slide 34

Slide 34 text

@amjithr HTTP://FLIC.KR/P/bE NXH SIGNALS Wednesday, May 15, 13

Slide 35

Slide 35 text

@amjithr import signal # Use the virtual timer sig = signal.ITIMER_VIRTUAL # register a handler signal.signal(sig, handler) # 100ms repeating timer signal.setitimer(sig, 0.1, 0.1) SIGNAL Wednesday, May 15, 13

Slide 36

Slide 36 text

@amjithr PROs CONs Accurate timer Unix only - Ignored in mod_wsgi - Can’t interrupt C-extensions SIGNAL Wednesday, May 15, 13

Slide 37

Slide 37 text

@amjithr HTTP://FLIC.KR/P/db ZS THREADS Wednesday, May 15, 13

Slide 38

Slide 38 text

@amjithr import threading # Create a background thread t = threading.Thread(target=handler) t.setDaemon(True) # Start the thread t.start() # Sleep for 100ms in handler time.sleep(0.1) THREAD Wednesday, May 15, 13

Slide 39

Slide 39 text

@amjithr PROs CONs Cross Platform Inaccurate for CPU tasks mod_wsgi compatible Can’t interrupt C-extensions THREAD Wednesday, May 15, 13

Slide 40

Slide 40 text

@amjithr INQUIRE Stack frame of every thread Wednesday, May 15, 13

Slide 41

Slide 41 text

@amjithr >>> import sys # Get stack frames of every thread >>> frames = sys._current_frames() # Dictionary of { thread_id: frame_obj } >>> frames {4420: , 1407: } INQUIRE Wednesday, May 15, 13

Slide 42

Slide 42 text

@amjithr function3 function2 function1 FRAMES Wednesday, May 15, 13

Slide 43

Slide 43 text

@amjithr function3 function2 function1 Fn Name File Name Line No Arguments Globals Locals ... FRAMES Wednesday, May 15, 13

Slide 44

Slide 44 text

@amjithr function3 function2 function1 Fn Name File Name Line No Arguments Globals Locals ... FRAMES Wednesday, May 15, 13

Slide 45

Slide 45 text

@amjithr >>> import traceback # Extract useful info from frame >>> traceback.extract_stack(frame) [('code.py', 88, 'runsource', 'return'), ('code.py', 110, 'runcode', 'print')] EXTRACT Wednesday, May 15, 13

Slide 46

Slide 46 text

@amjithr COLLATE Wednesday, May 15, 13

Slide 47

Slide 47 text

@amjithr Default Dictionary ATTEMPT Wednesday, May 15, 13

Slide 48

Slide 48 text

@amjithr Default Dictionary Uniquely identify a function fdata = (f_name, file, line) Build a dictionary calls = defaultdict(int) Increment the value when found in frames calls[fn_a] += 1 ATTEMPT Wednesday, May 15, 13

Slide 49

Slide 49 text

@amjithr Default Dictionary Uniquely identify a function fdata = (f_name, file, line) Build a dictionary calls = defaultdict(int) Increment the value when found in frames calls[fn_a] += 1 ATTEMPT Wednesday, May 15, 13

Slide 50

Slide 50 text

@amjithr Default Dictionary Uniquely identify a function fdata = (f_name, file, line) Build a dictionary calls = defaultdict(int) Increment the value when found in frames calls[fn_a] += 1 ATTEMPT Wednesday, May 15, 13

Slide 51

Slide 51 text

@amjithr Results fn_a=3 fn_b=4 fn_c=5 fn_d=1 { } ATTEMPT Wednesday, May 15, 13

Slide 52

Slide 52 text

@amjithr Simple to implement Identifies hot functions No context ATTEMPT Wednesday, May 15, 13

Slide 53

Slide 53 text

@amjithr Call Tree ATTEMPT Wednesday, May 15, 13

Slide 54

Slide 54 text

@amjithr Example T1 Wednesday, May 15, 13

Slide 55

Slide 55 text

@amjithr Example fn_a fn_b fn_c T1 Wednesday, May 15, 13

Slide 56

Slide 56 text

@amjithr Example fn_a fn_b fn_c T1 Wednesday, May 15, 13

Slide 57

Slide 57 text

@amjithr Example fn_a fn_b fn_c T1 fn_a=1 Wednesday, May 15, 13

Slide 58

Slide 58 text

@amjithr Example fn_a fn_b fn_c T1 fn_a=1 Wednesday, May 15, 13

Slide 59

Slide 59 text

@amjithr Example fn_a fn_b fn_c T1 fn_a=1 fn_b=1 Wednesday, May 15, 13

Slide 60

Slide 60 text

@amjithr Example fn_a fn_b fn_c T1 fn_a=1 fn_b=1 Wednesday, May 15, 13

Slide 61

Slide 61 text

@amjithr Example fn_a fn_b fn_c T1 fn_a=1 fn_b=1 fn_c=1 Wednesday, May 15, 13

Slide 62

Slide 62 text

@amjithr T2 fn_a=1 fn_b=1 fn_c=1 Example Wednesday, May 15, 13

Slide 63

Slide 63 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 Example Wednesday, May 15, 13

Slide 64

Slide 64 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 Example Wednesday, May 15, 13

Slide 65

Slide 65 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 fn_a=2 Example Wednesday, May 15, 13

Slide 66

Slide 66 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 fn_a=2 Example Wednesday, May 15, 13

Slide 67

Slide 67 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 fn_a=2 fn_b=2 Example Wednesday, May 15, 13

Slide 68

Slide 68 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 fn_a=2 fn_b=2 Example Wednesday, May 15, 13

Slide 69

Slide 69 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_a=2 fn_b=2 fn_c=1 Example Wednesday, May 15, 13

Slide 70

Slide 70 text

@amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 Example Wednesday, May 15, 13

Slide 71

Slide 71 text

@amjithr fn_a=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 T3 Example Wednesday, May 15, 13

Slide 72

Slide 72 text

@amjithr fn_a fn_d fn_a=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 T3 Example Wednesday, May 15, 13

Slide 73

Slide 73 text

@amjithr fn_a fn_d fn_a=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 T3 Example Wednesday, May 15, 13

Slide 74

Slide 74 text

@amjithr fn_a fn_d fn_a=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 fn_a=3 T3 Example Wednesday, May 15, 13

Slide 75

Slide 75 text

@amjithr fn_a fn_d fn_a=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 fn_a=3 T3 Example Wednesday, May 15, 13

Slide 76

Slide 76 text

@amjithr fn_a fn_d fn_a=1 fn_a=2 fn_a=3 fn_b=2 fn_c=1 fn_d=1 T3 Example Wednesday, May 15, 13

Slide 77

Slide 77 text

@amjithr fn_a fn_d fn_a=1 fn_a=2 fn_a=3 fn_b=2 fn_c=1 fn_d=1 fn_d=1 T3 Example Wednesday, May 15, 13

Slide 78

Slide 78 text

@amjithr EXISTING TOOLS Wednesday, May 15, 13

Slide 79

Slide 79 text

@amjithr http://pypi.python.org/pypi/statprof StatProf Signals CLI Wednesday, May 15, 13

Slide 80

Slide 80 text

@amjithr https://github.com/bdarnell/plop PLOP Signals D Call Graph Wednesday, May 15, 13

Slide 81

Slide 81 text

@amjithr Wednesday, May 15, 13

Slide 82

Slide 82 text

@amjithr NewRelic Threads GUI Wednesday, May 15, 13

Slide 83

Slide 83 text

@amjithr Wednesday, May 15, 13

Slide 84

Slide 84 text

@amjithr SUMMARY Features Limitations Low Overhead No green threads CPython & PyPy No Jython support Wednesday, May 15, 13

Slide 85

Slide 85 text

@amjithr WRONG USE OF MEME. WHO LET THIS GUY ON THE STAGE? PROFILER in PRODUCTION Wednesday, May 15, 13

Slide 86

Slide 86 text

@amjithr FINALE DETERMINISTIC + STATISTICAL Wednesday, May 15, 13

Slide 87

Slide 87 text

@amjithr X-Ray Sessions Wednesday, May 15, 13

Slide 88

Slide 88 text

@amjithr DETERMINISTIC Wednesday, May 15, 13

Slide 89

Slide 89 text

@amjithr STATISTICAL Wednesday, May 15, 13

Slide 90

Slide 90 text

@amjithr HISTOGRAM Wednesday, May 15, 13

Slide 91

Slide 91 text

@amjithr RESPONSE & THROUGHPUT Wednesday, May 15, 13

Slide 92

Slide 92 text

@amjithr THANK YOU! @amjithr Wednesday, May 15, 13

Slide 93

Slide 93 text

Questions? • Promo: newrelic.com/djangocon • 30 days of Pro. • Free T-shirt. • In-depth data. Wednesday, May 15, 13