Emin Martinian - Statistical Profiling (and other fun with the sys module)

Profiling involves computing a set of data about how often and how long various parts of your program are executed. Profiling is useful to understand what makes your program slow and how you can improve it. After a quick review of deterministic profiling tools and techniques, I will describe how you can do statistical profiling with existing packages or write your own from scratch.

Statistical profiling involves occasionally sampling what your program is doing instead of watching each line or function. A key feature of statistical profiling is that by using a moderate sampling frequency, you can profile your production code with almost no overhead. This lets you find the actual bottlenecks in real use cases.

The core technical focus of the talk is python's sys module and how it lets you easily examine a running program. I also describe some tricks to be aware of related to threading, context switches, locks, and so on. At the conclusion of the talk, you will hopefully understand how to use an existing statistical profiler or write a customized version yourself.

https://us.pycon.org/2019/schedule/presentation/197/

Transcript

1. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 1/58 Statistical Pro ling (and other neat features of the sys module) Statistical Profiling https://github.com/emin63/ox_profile 1 / 58
2. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 2/58 Outline 1. Why statistical profiling? 2. Various python tools available. 3. Details of ox_profile statistical profiler. Statistical Profiling https://github.com/emin63/ox_profile 2 / 58
3. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 3/58 Outline 1. Why statistical profiling? 2. Various python tools available. 3. Details of ox_profile statistical profiler. Goal: learn how to use ox_profile, other profilers Statistical Profiling https://github.com/emin63/ox_profile 3 / 58
4. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 4/58 Outline 1. Why statistical profiling? 2. Various python tools available. 3. Details of ox_profile statistical profiler. Goal: learn how to use ox_profile, other profilers or write your own! Statistical Profiling https://github.com/emin63/ox_profile 4 / 58
5. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 5/58 What is pro ling? From python.org: "A profile is a set of statistics that describes how often and for how long various parts of the program executed." Profiling is useful to find out which parts of program are slow. Statistical Profiling https://github.com/emin63/ox_profile 5 / 58
6. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 6/58 Deterministic Pro ling >>> import cProfile, re # could also use pure python `profile` >>> cProfile.run('re.compile("foo|bar")') gives: 197 function calls (192 primitive calls) in 0.002 seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 0.001 0.001 <string>:1(<module>) 1 0.000 0.000 0.001 0.001 re.py:212(compile) 1 0.000 0.000 0.001 0.001 re.py:268(_compile) 1 0.000 0.000 0.000 0.000 sre_compile.py:172(_compile_charset) 1 0.000 0.000 0.000 0.000 sre_compile.py:201(_optimize_charset) 4 0.000 0.000 0.000 0.000 sre_compile.py:25(_identityfunction) 3/1 0.000 0.000 0.000 0.000 sre_compile.py:33(_compile) Statistical Profiling https://github.com/emin63/ox_profile 6 / 58
7. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 7/58 Deterministic pro ling hooks The sys module provides: setprofile: execute function on each call. settrace: like setprofile + each line Used as a hook to inspect stack frame. Statistical Profiling https://github.com/emin63/ox_profile 7 / 58
8. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 8/58 Python Stack Frame Statistical Profiling https://github.com/emin63/ox_profile 8 / 58
9. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 9/58 Program Diagram Statistical Profiling https://github.com/emin63/ox_profile 9 / 58
10. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 10/58 Program Diagram w/Pro ler Statistical Profiling https://github.com/emin63/ox_profile 10 / 58
11. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 11/58 Drawbacks to deterministic pro ling 1. SLOW: hooks run on each line or each call! Statistical Profiling https://github.com/emin63/ox_profile 11 / 58
12. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 12/58 Drawbacks to deterministic pro ling 1. SLOW: hooks run on each line or each call! 2. See #1: usually can't profile in production. Statistical Profiling https://github.com/emin63/ox_profile 12 / 58
13. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 13/58 Drawbacks to deterministic pro ling 1. SLOW: hooks run on each line or each call! 2. See #1: usually can't profile in production. 3. Not thread-aware: "it must be registered using settrace() for each thread being debugged" (similar for setprofile()). Statistical Profiling https://github.com/emin63/ox_profile 13 / 58
14. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 14/58 Statistical Pro ler (Main Thread) Statistical Profiling https://github.com/emin63/ox_profile 14 / 58
15. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 15/58 Statistical Pro ler (Sampling) Statistical Profiling https://github.com/emin63/ox_profile 15 / 58
16. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 16/58 POSIX timer as Sampler Low level timer interrupts your process Periodically check call stack + record it. stat_prof, plop (not available on Windows). Statistical Profiling https://github.com/emin63/ox_profile 16 / 58
17. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 17/58 POSIX ptrace as Sampler Threads via ptrace. Lets one program control/inspect other. Main/Sampler are different programs! pyflame (not available on Windows). Statistical Profiling https://github.com/emin63/ox_profile 17 / 58
18. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 18/58 Why do we care about non-POSIX? Statistical Profiling https://github.com/emin63/ox_profile 18 / 58
19. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 19/58 Why do we care about non-POSIX? 1. Nice to have "portable" implementation. Statistical Profiling https://github.com/emin63/ox_profile 19 / 58
20. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 20/58 Why do we care about non-POSIX? 1. Nice to have "portable" implementation. 2. Using only python features may be easier to understand/modify. Understandable implementation essential if run in production. Statistical Profiling https://github.com/emin63/ox_profile 20 / 58
21. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 21/58 Why do we care about non-POSIX? 1. Nice to have "portable" implementation. 2. Using only python features may be easier to understand/modify. Understandable implementation essential if run in production. 3. Consumer software (e.g., games) often run in Windows. Statistical Profiling https://github.com/emin63/ox_profile 21 / 58
22. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 22/58 Python sys._current_frames lists each thread's current frame. ox_profile, pprofile, (works on windows!) Statistical Profiling https://github.com/emin63/ox_profile 22 / 58
23. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 23/58 _current_frames (Function 2) lists each thread's current frame. ox_profile, pprofile, (works on windows!) Statistical Profiling https://github.com/emin63/ox_profile 23 / 58
24. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 24/58 _current_frames (Function 3) lists each thread's current frame. ox_profile, pprofile, (works on windows!) Statistical Profiling https://github.com/emin63/ox_profile 24 / 58
25. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 25/58 Logistics: How do we pro le? Install via the usual $ pip install ox_profile Then start your python interpreter and: >>> from ox_profile.core.launchers import SimpleLauncher >>> profiler = SimpleLauncher.launch() # Create + start >>> # call some functions >>> print(profiler.show()) # Show results >>> profiler.cancel() # Turn off Statistical Profiling https://github.com/emin63/ox_profile 25 / 58
26. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 26/58 Sampling loop Oversimplified illustration of sampler loop: while 1: time.sleep(self.interval) for id, frame in sys._current_frames().items(): self.my_db[frame.f_code.co_name] += 1 Sampling loop runs in separate thread. Statistical Profiling https://github.com/emin63/ox_profile 26 / 58
27. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 27/58 Sampling Interval Control overhead based on sampling interval: >>> profiler.set_interval(5) # changes profiler.interval 5 second sampling = negligible overhead. Trade-off between various goals: accuracy, collection time, overhead May want to also add random jitter Statistical Profiling https://github.com/emin63/ox_profile 27 / 58
28. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 28/58 Pro ler output >>> profiler.show() Output shows: Function name (and module). How many times function was seen. Function Hits % --------------------------------------------------------- send(requests.sessions) 10082 2.8 request(requests.api) 7710 2.1 get(requests.api) 7710 2.1 <listcomp>(__main__) 7710 2.1 __call__(ox_profile.core.sampling) 7710 2.1 request(requests.sessions) 7698 2.1 send(requests.adapters) 6897 1.9 _make_request(urllib3.connectionpool) 6893 1.9 urlopen(urllib3.connectionpool) 6893 1.9 connect(urllib3.connection) 5602 1.5 Statistical Profiling https://github.com/emin63/ox_profile 28 / 58
29. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 29/58 Basic theory of sys._current_frames 1. Start thread doing mostly time.sleep. 2. Periodically wake + sys._current_frames() 3. Record current stack frame(s) info. In theory, you can write simple statistical profiler with just these. Statistical Profiling https://github.com/emin63/ox_profile 29 / 58
30. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 30/58 Basic theory of sys._current_frames 1. Start thread doing mostly time.sleep. 2. Periodically wake + sys._current_frames() 3. Record current stack frame(s) info. In theory, you can write simple statistical profiler with just these. In theory, there is no difference between theory and practice. Statistical Profiling https://github.com/emin63/ox_profile 30 / 58
31. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 31/58 Basic theory of sys._current_frames 1. Start thread doing mostly time.sleep. 2. Periodically wake + sys._current_frames() 3. Record current stack frame(s) info. In theory, you can write simple statistical profiler with just these. In theory, there is no difference between theory and practice. But, in practice, there is. Statistical Profiling https://github.com/emin63/ox_profile 31 / 58
32. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 32/58 Using sys._current_frames In theory, iter sys._current_frames() + record. for dummy_frame_id, frame in (sys._current_frames().items()): self.my_db.record(measure_tool(frame)) Statistical Profiling https://github.com/emin63/ox_profile 32 / 58
33. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 33/58 Using sys._current_frames In theory, iter sys._current_frames() + record. for dummy_frame_id, frame in (sys._current_frames().items()): self.my_db.record(measure_tool(frame)) What could go wrong? Statistical Profiling https://github.com/emin63/ox_profile 33 / 58
34. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 34/58 Using sys._current_frames In theory, iter sys._current_frames() + record. for dummy_frame_id, frame in (sys._current_frames().items()): self.my_db.record(measure_tool(frame)) What could go wrong? thread context could switch Statistical Profiling https://github.com/emin63/ox_profile 34 / 58
35. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 35/58 Using sys._current_frames In theory, iter sys._current_frames() + record. for dummy_frame_id, frame in (sys._current_frames().items()): self.my_db.record(measure_tool(frame)) What could go wrong? thread context could switch attempt to read stale frame = CRASH! Statistical Profiling https://github.com/emin63/ox_profile 35 / 58
36. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 36/58 Using sys._current_frames In theory, iter sys._current_frames() + record. switch_interval = sys.getswitchinterval() sys.setswitchinterval(10000) for dummy_frame_id, frame in (sys._current_frames().items()): self.my_db.record(measure_tool(frame)) sys.setswitchinterval(switch_interval) sys.setswitchinterval prevents context switch. Now, what could go wrong? Statistical Profiling https://github.com/emin63/ox_profile 36 / 58
37. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 37/58 Using sys._current_frames In theory, iter sys._current_frames() + record. switch_interval = sys.getswitchinterval() sys.setswitchinterval(10000) for dummy_frame_id, frame in (sys._current_frames().items()): self.my_db.record(measure_tool(frame)) sys.setswitchinterval(switch_interval) sys.setswitchinterval prevents context switch. Now, what could go wrong? Exception prevents switch interval being reset! Statistical Profiling https://github.com/emin63/ox_profile 37 / 58
38. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 38/58 Using sys._current_frames In theory, iter sys._current_frames() + record. switch_interval = sys.getswitchinterval() try: sys.setswitchinterval(10000) for dummy_frame_id, frame in ( sys._current_frames().items()): self.my_db.record(measure_tool(frame)) finally: sys.setswitchinterval(switch_interval) sys.setswitchinterval prevents context switch. Need try/finally to protect thread logic. Now, what could go wrong? Statistical Profiling https://github.com/emin63/ox_profile 38 / 58
39. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 39/58 Using sys._current_frames In theory, iter sys._current_frames() + record. switch_interval = sys.getswitchinterval() try: sys.setswitchinterval(10000) for dummy_frame_id, frame in ( sys._current_frames().items()): self.my_db.record(measure_tool(frame)) finally: sys.setswitchinterval(switch_interval) sys.setswitchinterval prevents context switch. Need try/finally to protect thread logic. Now, what could go wrong? We are just getting started. Statistical Profiling https://github.com/emin63/ox_profile 39 / 58
40. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 40/58 Recording a sample Simple function to record a sample in dict: def record(self, measurement): record = self.my_db.get(measurement.name, 0) self.my_db[measurement.name] = record + 1 keep dict of measurements find + increment hit for given function What could go wrong? Statistical Profiling https://github.com/emin63/ox_profile 40 / 58
41. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 41/58 Recording sample changing dict Imagine getting profile results def record(self, measurement): record = self.my_db.get(measurement.name, 0) self.my_db[measurement.name] = record + 1 If record being called change dict during iteration = CRASH! Statistical Profiling https://github.com/emin63/ox_profile 41 / 58
42. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 42/58 Recording a sample def __init__(self): self.db_lock = threading.Lock() def record(self, measurement): with self.db_lock: record = self.my_db.get(measurement.name, 0) self.my_db[measurement.name] = record + 1 Need to use threading.Lock Must check lock in viewing self.my_db Prevents simultaneous access to my_db What could go wrong? Statistical Profiling https://github.com/emin63/ox_profile 42 / 58
43. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 43/58 Recording a sample def __init__(self): self.db_lock = threading.Lock() def record(self, measurement): with self.db_lock: record = self.my_db.get(measurement.name, 0) self.my_db[measurement.name] = record + 1 Need to use threading.Lock Must check lock in viewing self.my_db Prevents simultaneous access to my_db What could go wrong? Unknown unknowns: use faulthandler.enable() at startup Statistical Profiling https://github.com/emin63/ox_profile 43 / 58
44. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 44/58 Additional Issues Sampler thread still alive on exit program Set self.daemon = True for sampler Minimum sleep time ~ 1--10 milliseconds For time.sleep or wait on a thread event. Granularity about 10 milliseconds. Statistical Profiling https://github.com/emin63/ox_profile 44 / 58
45. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 45/58 Using Flask If you are running a flask web server, do: from ox_profile.ui.flask.views import OX_PROF_BP app.register_blueprint(OX_PROF_BP) app.config['OX_PROF_USERS'] = {<admin_user_1>, <admin_user_2>, ...} for easy way to profile production code: ox_profile/unpause: Start (or unpause) ox_profile/pause: Pause profiler ox_profile/status: Shows current results ox_profile/set_interval: sample frequency Statistical Profiling https://github.com/emin63/ox_profile 45 / 58
46. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 46/58 Additional Uses What else can you do with sys._current_frames()? Statistical Profiling https://github.com/emin63/ox_profile 46 / 58
47. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 47/58 Additional Uses What else can you do with sys._current_frames()? Major damage that is very hard to track down! Statistical Profiling https://github.com/emin63/ox_profile 47 / 58
48. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 48/58 Additional Uses What else can you do with sys._current_frames()? Major damage that is very hard to track down! Be careful! Statistical Profiling https://github.com/emin63/ox_profile 48 / 58
49. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 49/58 Idea: Data Snapshot Periodically snapshot specific function data Instead of frame.f_code.co_name, Just look at frame.f_locals Statistical Profiling https://github.com/emin63/ox_profile 49 / 58
50. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 50/58 Idea: Data Snapshot Periodically snapshot specific function data Instead of frame.f_code.co_name, Just look at frame.f_locals Can even modify f_locals! Statistical Profiling https://github.com/emin63/ox_profile 50 / 58
51. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 51/58 Idea: Statistical Debugger Periodically snapshot debug info full stack backtrace + locals Either dump these to logs or store locally and report on "failure". Statistical Profiling https://github.com/emin63/ox_profile 51 / 58
52. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 52/58 Idea: Statistical code coverage Like coverage.py, but in production Periodically turn on tracing After brief sample, turn back off Statistical Profiling https://github.com/emin63/ox_profile 52 / 58
53. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 53/58 Summary 1. Profiling find bottlenecks + improve your code. Statistical Profiling https://github.com/emin63/ox_profile 53 / 58
54. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 54/58 Summary 1. Profiling find bottlenecks + improve your code. 2. Statistical profiler samples code periodically use to analyze production with low overhead. Statistical Profiling https://github.com/emin63/ox_profile 54 / 58
55. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 55/58 Summary 1. Profiling find bottlenecks + improve your code. 2. Statistical profiler samples code periodically use to analyze production with low overhead. 3. Use ox_profile or write your own profiler. Statistical Profiling https://github.com/emin63/ox_profile 55 / 58
56. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 56/58 Summary 1. Profiling find bottlenecks + improve your code. 2. Statistical profiler samples code periodically use to analyze production with low overhead. 3. Use ox_profile or write your own profiler. 4. sys.setprofile, sys.settrace, sys._current_frames Statistical Profiling https://github.com/emin63/ox_profile 56 / 58
57. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 57/58 Summary 1. Profiling find bottlenecks + improve your code. 2. Statistical profiler samples code periodically use to analyze production with low overhead. 3. Use ox_profile or write your own profiler. 4. sys.setprofile, sys.settrace, sys._current_frames 5. Simple in theory; but be careful with threads: try/finally, locks, switch interval, faulthandler Statistical Profiling https://github.com/emin63/ox_profile 57 / 58
58. 5/2/2019 Title file:///U:/code/ox_profile/docs/overview_slides.html#58 58/58 Further investigations Slides, ox_profile, etc. at https://github.com/emin63/ox_profile Clone, fork, or file issues for questions. About presenter: Name: Emin Martinian Role: software, technology, finance consulting at www.aocks.com Contact: emin.martinian@gmail.com Statistical Profiling https://github.com/emin63/ox_profile 58 / 58