Python Profiling by Amjith Ramanujam

A guided tour of profiling tools for python.

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