Pro Yearly is on sale from $80 to $50! »

Python Profiling by Amjith Ramanujam

Python Profiling by Amjith Ramanujam

A guided tour of profiling tools for python.

Afcfefa1f067d10bd021de0cc2e5e806?s=128

PyCon 2013

March 15, 2013
Tweet

Transcript

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

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

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

  4. @amjithr Hi  Friday, March 15, 13

  5. @amjithr ♥ Friday, March 15, 13

  6. @amjithr Friday, March 15, 13

  7. @amjithr PERFORMANCE! Friday, March 15, 13

  8. @amjithr cPROFILE Friday, March 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} Friday, March 15, 13
  10. @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(<module>) 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
  11. @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(<module>) 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
  12. @amjithr I KNOW PROFILING Friday, March 15, 13

  13. @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) .... .... ..... ..... .... ...... .... .... ..... ..... .... ...... Friday, March 15, 13
  14. @amjithr SAVE & ANALYZE PROFILE ANALYSIS Friday, March 15, 13

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

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

    >>> import pstats >>> p = pstats.Stats('shorten.prof') >>> p.sort_stats('calls') <pstats.Stats instance at 0x105ac8248> >>> 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
  17. @amjithr  RunSnakeRun Friday, March 15, 13

  18. @amjithr Friday, March 15, 13

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

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

    13
  21. @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
  22. @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
  23. @amjithr You can’t run it in production Friday, March 15,

    13
  24. @amjithr PROFILER IN PRODUCTION Friday, March 15, 13

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

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

  27. @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
  28. @amjithr TARGETED PROFILING PROs CONs Less overhead Still slow Finer

    Resolution Manual Friday, March 15, 13
  29. @amjithr TARGETED HYBRID PROFILING WEB APPS ONLY NEWRELIC Friday, March

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

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

    Friday, March 15, 13
  32. @amjithr TRANSACTION TRACE Friday, March 15, 13

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

  34. @amjithr HYBRID PROFILING PROs CONs FAST SEMI-MANUAL FUNCTION ARGS LIMITED

    INSTRUMENTATION Friday, March 15, 13
  35. @amjithr STATISTICAL PROFILER Friday, March 15, 13

  36. @amjithr Friday, March 15, 13

  37. @amjithr WAT? Friday, March 15, 13

  38. @amjithr OVERLY ATTACHED Friday, March 15, 13

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

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

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

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

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

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

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

    13
  46. @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
  47. @amjithr EXISTING TOOLS Friday, March 15, 13

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

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

    15, 13
  50. @amjithr Friday, March 15, 13

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

  52. @amjithr Friday, March 15, 13

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

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

  55. @amjithr DETERMINISTIC Friday, March 15, 13

  56. @amjithr STATISTICAL Friday, March 15, 13

  57. @amjithr HISTOGRAM Friday, March 15, 13

  58. @amjithr RESPONSE & THROUGHPUT Friday, March 15, 13

  59. @amjithr PROFILING IN PRODUCTION Friday, March 15, 13

  60. @amjithr QUESTIONS Friday, March 15, 13

  61. Questions? • Promo Code: pycon13 • 30 days of Pro.

    • Free T-shirt. • In-depth data. Friday, March 15, 13