Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Thread Profiling in Python

Thread Profiling in Python

How to create your own statistical thread profiler in Python language.

2bc9d9ab2650be544088e93da1820e26?s=128

Amjith

May 15, 2013
Tweet

Transcript

  1. @amjithr THREAD PROFILING DJANGOCON EU ▪ Wednesday, May 15, 13

  2. @amjithr Hi  Wednesday, May 15, 13

  3. @amjithr ♥ Wednesday, May 15, 13

  4. Wednesday, May 15, 13

  5. @amjithr PERFORMANCE! Wednesday, May 15, 13

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

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

  8. @amjithr cPROFILE Wednesday, May 15, 13

  9. @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(<module>) 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
  10. @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 <string>:1(<lambda>) 1 0.000 0.000 0.000 0.000 <string>:1(<module>) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedCTE) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedCase) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedCast) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedClauseElement) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedClauseList) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedColumn) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedColumnClause) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedColumnElement) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedCompoundSelect) 1 0.000 0.000 0.000 0.000 <string>:1(AnnotatedDelete) .... .... ..... ..... .... ...... .... .... ..... ..... .... ...... Wednesday, May 15, 13
  11. @amjithr  RunSnakeRun Wednesday, May 15, 13

  12. @amjithr Wednesday, May 15, 13

  13. @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
  14. @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
  15. @amjithr You can’t run it in production Wednesday, May 15,

    13
  16. @amjithr PROFILER IN PRODUCTION Wednesday, May 15, 13

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

  18. @amjithr CRITICAL FUNCTIONS HYBRID PROFILING TARGETED PROFILING Wednesday, May 15,

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

    15, 13
  20. @amjithr TRANSACTION TRACE Wednesday, May 15, 13

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

  22. @amjithr Cool Story, Bro! Can we talk about statistical profilers?

    Wednesday, May 15, 13
  23. @amjithr STATISTICAL THREAD PROFILER Wednesday, May 15, 13

  24. @amjithr Wednesday, May 15, 13

  25. @amjithr WAT? Wednesday, May 15, 13

  26. @amjithr OVERLY ATTACHED Wednesday, May 15, 13

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

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

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

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

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

    15, 13
  32. @amjithr Wednesday, May 15, 13

  33. @amjithr SIGNALS THREADS INTERRUPT Wednesday, May 15, 13

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

  35. @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
  36. @amjithr PROs CONs Accurate timer Unix only - Ignored in

    mod_wsgi - Can’t interrupt C-extensions SIGNAL Wednesday, May 15, 13
  37. @amjithr HTTP://FLIC.KR/P/db ZS THREADS Wednesday, May 15, 13

  38. @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
  39. @amjithr PROs CONs Cross Platform Inaccurate for CPU tasks mod_wsgi

    compatible Can’t interrupt C-extensions THREAD Wednesday, May 15, 13
  40. @amjithr INQUIRE Stack frame of every thread Wednesday, May 15,

    13
  41. @amjithr >>> import sys # Get stack frames of every

    thread >>> frames = sys._current_frames() # Dictionary of { thread_id: frame_obj } >>> frames {4420: <frame object at 0x7fd96c04a650>, 1407: <frame object at 0x7fd96c301730>} INQUIRE Wednesday, May 15, 13
  42. @amjithr function3 function2 function1 FRAMES Wednesday, May 15, 13

  43. @amjithr function3 function2 function1 Fn Name File Name Line No

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

    Arguments Globals Locals ... FRAMES Wednesday, May 15, 13
  45. @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
  46. @amjithr COLLATE Wednesday, May 15, 13

  47. @amjithr Default Dictionary ATTEMPT Wednesday, May 15, 13

  48. @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
  49. @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
  50. @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
  51. @amjithr Results fn_a=3 fn_b=4 fn_c=5 fn_d=1 { } ATTEMPT Wednesday,

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

    Wednesday, May 15, 13
  53. @amjithr Call Tree ATTEMPT Wednesday, May 15, 13

  54. @amjithr Example T1 Wednesday, May 15, 13

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

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

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

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

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

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

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

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

  63. @amjithr fn_a fn_b fn_d T2 fn_a=1 fn_b=1 fn_c=1 Example Wednesday,

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

    May 15, 13
  65. @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
  66. @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
  67. @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
  68. @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
  69. @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
  70. @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
  71. @amjithr fn_a=1 fn_a=2 fn_b=2 fn_c=1 fn_d=1 T3 Example Wednesday, May

    15, 13
  72. @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
  73. @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
  74. @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
  75. @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
  76. @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
  77. @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
  78. @amjithr EXISTING TOOLS Wednesday, May 15, 13

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

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

    13
  81. @amjithr Wednesday, May 15, 13

  82. @amjithr NewRelic Threads GUI Wednesday, May 15, 13

  83. @amjithr Wednesday, May 15, 13

  84. @amjithr SUMMARY Features Limitations Low Overhead No green threads CPython

    & PyPy No Jython support Wednesday, May 15, 13
  85. @amjithr WRONG USE OF MEME. WHO LET THIS GUY ON

    THE STAGE? PROFILER in PRODUCTION Wednesday, May 15, 13
  86. @amjithr FINALE DETERMINISTIC + STATISTICAL Wednesday, May 15, 13

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

  88. @amjithr DETERMINISTIC Wednesday, May 15, 13

  89. @amjithr STATISTICAL Wednesday, May 15, 13

  90. @amjithr HISTOGRAM Wednesday, May 15, 13

  91. @amjithr RESPONSE & THROUGHPUT Wednesday, May 15, 13

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

  93. Questions? • Promo: newrelic.com/djangocon • 30 days of Pro. •

    Free T-shirt. • In-depth data. Wednesday, May 15, 13