-
-
Notifications
You must be signed in to change notification settings - Fork 36.6k
Expand file tree
/
Copy pathprofiling.sampling.rst
More file actions
1735 lines (1194 loc) · 63.1 KB
/
Copy pathprofiling.sampling.rst
File metadata and controls
1735 lines (1194 loc) · 63.1 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
458
459
460
461
462
463
464
465
466
467
468
469
470
471
472
473
474
475
476
477
478
479
480
481
482
483
484
485
486
487
488
489
490
491
492
493
494
495
496
497
498
499
500
501
502
503
504
505
506
507
508
509
510
511
512
513
514
515
516
517
518
519
520
521
522
523
524
525
526
527
528
529
530
531
532
533
534
535
536
537
538
539
540
541
542
543
544
545
546
547
548
549
550
551
552
553
554
555
556
557
558
559
560
561
562
563
564
565
566
567
568
569
570
571
572
573
574
575
576
577
578
579
580
581
582
583
584
585
586
587
588
589
590
591
592
593
594
595
596
597
598
599
600
601
602
603
604
605
606
607
608
609
610
611
612
613
614
615
616
617
618
619
620
621
622
623
624
625
626
627
628
629
630
631
632
633
634
635
636
637
638
639
640
641
642
643
644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
666
667
668
669
670
671
672
673
674
675
676
677
678
679
680
681
682
683
684
685
686
687
688
689
690
691
692
693
694
695
696
697
698
699
700
701
702
703
704
705
706
707
708
709
710
711
712
713
714
715
716
717
718
719
720
721
722
723
724
725
726
727
728
729
730
731
732
733
734
735
736
737
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
766
767
768
769
770
771
772
773
774
775
776
777
778
779
780
781
782
783
784
785
786
787
788
789
790
791
792
793
794
795
796
797
798
799
800
801
802
803
804
805
806
807
808
809
810
811
812
813
814
815
816
817
818
819
820
821
822
823
824
825
826
827
828
829
830
831
832
833
834
835
836
837
838
839
840
841
842
843
844
845
846
847
848
849
850
851
852
853
854
855
856
857
858
859
860
861
862
863
864
865
866
867
868
869
870
871
872
873
874
875
876
877
878
879
880
881
882
883
884
885
886
887
888
889
890
891
892
893
894
895
896
897
898
899
900
901
902
903
904
905
906
907
908
909
910
911
912
913
914
915
916
917
918
919
920
921
922
923
924
925
926
927
928
929
930
931
932
933
934
935
936
937
938
939
940
941
942
943
944
945
946
947
948
949
950
951
952
953
954
955
956
957
958
959
960
961
962
963
964
965
966
967
968
969
970
971
972
973
974
975
976
977
978
979
980
981
982
983
984
985
986
987
988
989
990
991
992
993
994
995
996
997
998
999
1000
.. highlight:: sh
.. _profiling-sampling:
***************************************************
:mod:`!profiling.sampling` --- Statistical profiler
***************************************************
.. module:: profiling.sampling
:synopsis: Statistical sampling profiler for Python processes.
.. versionadded:: 3.15
**Source code:** :source:`Lib/profiling/sampling/`
.. program:: profiling.sampling
--------------
.. image:: ../../Lib/profiling/sampling/_assets/tachyon-logo.png
:alt: Tachyon logo
:align: center
:width: 300px
The :mod:`!profiling.sampling` module, named **Tachyon**, provides statistical
profiling of Python programs through periodic stack sampling. Tachyon can
run scripts directly or attach to any running Python process without requiring
code changes or restarts. Because sampling occurs externally to the target
process, overhead is virtually zero, making Tachyon suitable for both
development and production environments.
What is statistical profiling?
==============================
Statistical profiling builds a picture of program behavior by periodically
capturing snapshots of the call stack. Rather than instrumenting every function
call and return as deterministic profilers do, Tachyon reads the call stack at
regular intervals to record what code is currently running.
This approach rests on a simple principle: functions that consume significant
CPU time will appear frequently in the collected samples. By gathering thousands
of samples over a profiling session, Tachyon constructs an accurate statistical
estimate of where time is spent. The more samples collected, the
more precise this estimate becomes.
.. only:: html
The following interactive visualization demonstrates how sampling profiling
works. Press **Play** to watch a Python program execute, and observe how the
profiler periodically captures snapshots of the call stack. Adjust the
**sample interval** to see how sampling frequency affects the results.
.. raw:: html
:file: profiling-sampling-visualization.html
.. only:: not html
.. note::
An interactive visualization of sampling profiling is available in the
HTML version of this documentation.
How time is estimated
---------------------
The time values shown in Tachyon's output are **estimates derived from sample
counts**, not direct measurements. Tachyon counts how many times each function
appears in the collected samples, then multiplies by the sampling interval to
estimate time.
For example, with a 10 kHz sampling rate over a 10-second profile,
Tachyon collects approximately 100,000 samples. If a function appears in 5,000
samples (5% of total), Tachyon estimates it consumed 5% of the 10-second
duration, or about 500 milliseconds. This is a statistical estimate, not a
precise measurement.
The accuracy of these estimates depends on sample count. With 100,000 samples,
a function showing 5% has a margin of error of roughly ±0.5%. With only 1,000
samples, the same 5% measurement could actually represent anywhere from 3% to
7% of real time.
This is why longer profiling durations and shorter sampling intervals produce
more reliable results---they collect more samples. For most performance
analysis, the default settings provide sufficient accuracy to identify
bottlenecks and guide optimization efforts.
Because sampling is statistical, results will vary slightly between runs. A
function showing 12% in one run might show 11% or 13% in the next. This is
normal and expected. Focus on the overall pattern rather than exact percentages,
and don't worry about small variations between runs.
When to use a different approach
--------------------------------
Statistical sampling is not ideal for every situation.
For very short scripts that complete in under one second, the profiler may not
collect enough samples for reliable results. Use :mod:`profiling.tracing`
instead, or run the script in a loop to extend profiling time.
When you need exact call counts, sampling cannot provide them. Sampling
estimates frequency from snapshots, so if you need to know precisely how many
times a function was called, use :mod:`profiling.tracing`.
When comparing two implementations where the difference might be only 1-2%,
sampling noise can obscure real differences. Use :mod:`timeit` for
micro-benchmarks or :mod:`profiling.tracing` for precise measurements.
The key difference from :mod:`profiling.tracing` is how measurement happens.
A tracing profiler instruments your code, recording every function call and
return. This provides exact call counts and precise timing but adds overhead
to every function call. A sampling profiler, by contrast, observes the program
from outside at fixed intervals without modifying its execution. Think of the
difference like this: tracing is like having someone follow you and write down
every step you take, while sampling is like taking photographs every second
and inferring your path from those snapshots.
This external observation model is what makes sampling profiling practical for
production use. The profiled program runs at full speed because there is no
instrumentation code running inside it, and the target process is never stopped
or paused during sampling---Tachyon reads the call stack directly from the
process's memory while it continues to run. You can attach to a live server,
collect data, and detach without the application ever knowing it was observed.
The trade-off is that very short-lived functions may be missed if they happen
to complete between samples.
Statistical profiling excels at answering the question, "Where is my program
spending time?" It reveals hotspots and bottlenecks in production code where
deterministic profiling overhead would be unacceptable. For exact call counts
and complete call graphs, use :mod:`profiling.tracing` instead.
Quick examples
==============
Profile a script and see the results immediately::
python -m profiling.sampling run script.py
Profile a module with arguments::
python -m profiling.sampling run -m mypackage.module arg1 arg2
Generate an interactive flame graph::
python -m profiling.sampling run --flamegraph -o profile.html script.py
Attach to a running process by PID::
python -m profiling.sampling attach 12345
Print a single snapshot of a running process's stack::
python -m profiling.sampling dump 12345
Use live mode for real-time monitoring (press ``q`` to quit)::
python -m profiling.sampling run --live script.py
Profile for 60 seconds with a faster sampling rate::
python -m profiling.sampling run -d 60 -r 20khz script.py
Generate a line-by-line heatmap::
python -m profiling.sampling run --heatmap script.py
Enable opcode-level profiling to see which bytecode instructions are executing::
python -m profiling.sampling run --opcodes --flamegraph script.py
Commands
========
Tachyon operates through several subcommands. ``run`` and ``attach`` collect
samples over time; ``dump`` captures a single snapshot; ``replay`` converts
binary profiles to other formats.
The ``run`` command
-------------------
The ``run`` command launches a Python script or module and profiles it from
startup::
python -m profiling.sampling run script.py
python -m profiling.sampling run -m mypackage.module
When profiling a script, the profiler starts the target in a subprocess, waits
for it to initialize, then begins collecting samples. The ``-m`` flag
indicates that the target should be run as a module (equivalent to
``python -m``). Arguments after the target are passed through to the
profiled program::
python -m profiling.sampling run script.py --config settings.yaml
The ``attach`` command
----------------------
The ``attach`` command connects to an already-running Python process by its
process ID::
python -m profiling.sampling attach 12345
This command is particularly valuable for investigating performance issues in
production systems. The target process requires no modification and need not
be restarted. The profiler attaches, collects samples for the specified
duration, then detaches and produces output.
::
python -m profiling.sampling attach --live 12345
python -m profiling.sampling attach --flamegraph -d 30 -o profile.html 12345
On most systems, attaching to another process requires appropriate permissions.
See :ref:`profiling-permissions` for platform-specific requirements.
.. _dump-command:
The ``dump`` command
--------------------
The ``dump`` command prints a single snapshot of a running process's Python
stack and exits, similar to a traceback::
python -m profiling.sampling dump 12345
Unlike ``attach``, ``dump`` does not run a sampling loop: it reads the
stack once. This is useful for investigating hung or unresponsive
processes, or for answering "what is this process doing right now?".
The output mirrors a traceback (most recent call last) and annotates each
thread with its current state (main thread, has GIL, on CPU, waiting for
GIL, has exception, or idle):
.. code-block:: text
Stack dump for PID 12345, thread 140735 (main thread, has GIL, on CPU; most recent call last):
File "server.py", line 28, in serve
await handle_request(req)
File "handler.py", line 91, in handle_request
result = expensive_call(req)
When the target's source files are readable, ``dump`` prints the source
line for each frame and highlights the executing expression.
Like ``attach``, ``dump`` requires permission to read the target process's
memory. See :ref:`profiling-permissions`.
The ``dump`` command supports the following options:
``-a``, ``--all-threads``
Dump every thread in the target process. Without this flag only the main
thread is shown.
``--native``
Include synthetic ``<native>`` frames marking transitions into C
extensions or other non-Python code.
``--no-gc``
Hide the synthetic ``<GC>`` frames that mark active garbage collection.
``--opcodes``
Annotate each frame with the bytecode opcode the thread is currently
executing (for example, ``opcode=CALL_KW``). Useful for
instruction-level investigation, including identifying specializations
chosen by the adaptive interpreter.
``--async-aware``
Reconstruct stacks across ``await`` boundaries. ``dump`` walks the task
graph and emits one section per task, with ``<task>`` markers separating
coroutines awaiting each other.
``--async-mode {running,all}``
Controls which tasks are included when ``--async-aware`` is enabled.
``running`` shows only the task currently executing on each thread;
``all`` (the default for ``dump``) also includes tasks suspended on a
wait. ``attach``'s default for this flag is ``running``; ``dump``
defaults to ``all`` because a single snapshot is most useful when it
shows the full task graph.
``--blocking``
Pause every thread in the target while reading its stack and resume
them after. Guarantees a fully consistent snapshot at the cost of
briefly stopping the target. Without it, ``dump`` reads memory while
the target keeps running, which is faster but can occasionally produce
a torn stack.
.. _replay-command:
The ``replay`` command
----------------------
The ``replay`` command converts binary profile files to other output formats::
python -m profiling.sampling replay profile.bin
python -m profiling.sampling replay --flamegraph -o profile.html profile.bin
This command is useful when you have captured profiling data in binary format
and want to analyze it later or convert it to a visualization format. Binary
profiles can be replayed multiple times to different formats without
re-profiling.
::
# Convert binary to pstats (default, prints to stdout)
python -m profiling.sampling replay profile.bin
# Convert binary to flame graph
python -m profiling.sampling replay --flamegraph -o output.html profile.bin
# Convert binary to gecko format for Firefox Profiler
python -m profiling.sampling replay --gecko -o profile.json profile.bin
# Convert binary to heatmap
python -m profiling.sampling replay --heatmap -o my_heatmap profile.bin
Profiling in production
-----------------------
The sampling profiler is designed for production use. It imposes no measurable
overhead on the target process because it reads memory externally rather than
instrumenting code. The target application continues running at full speed and
is unaware it is being profiled.
When profiling production systems, keep these guidelines in mind:
Start with shorter durations (10-30 seconds) to get quick results, then extend
if you need more statistical accuracy. By default, profiling runs until the
target process completes, which is usually sufficient to identify major hotspots.
If possible, profile during representative load rather than peak traffic.
Profiles collected during normal operation are easier to interpret than those
collected during unusual spikes.
The profiler itself consumes some CPU on the machine where it runs (not on the
target process). On the same machine, this is typically negligible. When
profiling remote processes, network latency does not affect the target.
Results from production may differ from development due to different data
sizes, concurrent load, or caching effects. This is expected and is often
exactly what you want to capture.
.. _profiling-permissions:
Platform requirements
---------------------
The profiler reads the target process's memory to capture stack traces. This
requires elevated permissions on most operating systems.
**Linux**
On Linux, the profiler uses ``ptrace`` or ``process_vm_readv`` to read the
target process's memory. This typically requires one of:
- Running as root
- Having the ``CAP_SYS_PTRACE`` capability
- Adjusting the Yama ptrace scope: ``/proc/sys/kernel/yama/ptrace_scope``
The default ptrace_scope of 1 restricts ptrace to parent processes only. To
allow attaching to any process owned by the same user, set it to 0::
echo 0 | sudo tee /proc/sys/kernel/yama/ptrace_scope
**macOS**
On macOS, the profiler uses ``task_for_pid()`` to access the target process.
This requires one of:
- Running as root
- The profiler binary having the ``com.apple.security.cs.debugger`` entitlement
- System Integrity Protection (SIP) being disabled (not recommended)
**Windows**
On Windows, the profiler requires administrative privileges or the
``SeDebugPrivilege`` privilege to read another process's memory.
Version compatibility
---------------------
The profiler and target process must run the same Python minor version (for
example, both Python 3.15). Attaching from Python 3.14 to a Python 3.15 process
is not supported.
Additional restrictions apply to pre-release Python versions: if either the
profiler or target is running a pre-release (alpha, beta, or release candidate),
both must run the exact same version.
On free-threaded Python builds, the profiler cannot attach from a free-threaded
build to a standard build, or vice versa.
Sampling configuration
======================
Before exploring the various output formats and visualization options, it is
important to understand how to configure the sampling process itself. The
profiler offers several options that control how frequently samples are
collected, how long profiling runs, which threads are observed, and what
additional context is captured in each sample.
The default configuration works well for most use cases:
.. list-table::
:header-rows: 1
:widths: 25 75
* - Option
- Default
* - Default for ``--sampling-rate`` / ``-r``
- 1 kHz
* - Default for ``--duration`` / ``-d``
- Run to completion
* - Default for ``--all-threads`` / ``-a``
- Main thread only
* - Default for ``--native``
- No ``<native>`` frames (C code time attributed to caller)
* - Default for ``--no-gc``
- ``<GC>`` frames included when garbage collection is active
* - Default for ``--mode``
- Wall-clock mode (all samples recorded)
* - Default for ``--realtime-stats``
- Disabled
* - Default for ``--subprocesses``
- Disabled
* - Default for ``--blocking``
- Disabled (non-blocking sampling)
Sampling rate and duration
--------------------------
The two most fundamental parameters are the sampling rate and duration.
Together, these determine how many samples will be collected during a profiling
session.
The :option:`--sampling-rate` option (:option:`-r`) sets how frequently samples
are collected. The default is 1 kHz (1,000 samples per second)::
python -m profiling.sampling run -r 20khz script.py
Higher rates capture more samples and provide finer-grained data at the
cost of slightly higher profiler CPU usage. Lower rates reduce profiler
overhead but may miss short-lived functions. For most applications, the
default rate provides a good balance between accuracy and overhead.
The :option:`--duration` option (:option:`-d`) sets how long to profile in seconds. By
default, profiling continues until the target process exits or is interrupted::
python -m profiling.sampling run -d 60 script.py
Specifying a duration is useful when attaching to long-running processes or when
you want to limit profiling to a specific time window. When profiling a script,
the default behavior of running to completion is usually what you want.
Thread selection
----------------
Python programs often use multiple threads, whether explicitly through the
:mod:`threading` module or implicitly through libraries that manage thread
pools.
By default, the profiler samples only the main thread. The :option:`--all-threads`
option (:option:`-a`) enables sampling of all threads in the process::
python -m profiling.sampling run -a script.py
Multi-thread profiling reveals how work is distributed across threads and can
identify threads that are blocked or starved. Each thread's samples are
combined in the output, with the ability to filter by thread in some formats.
This option is particularly useful when investigating concurrency issues or
when work is distributed across a thread pool.
.. _blocking-mode:
Blocking mode
-------------
By default, Tachyon reads the target process's memory without stopping it.
This non-blocking approach is ideal for most profiling scenarios because it
imposes virtually zero overhead on the target application: the profiled
program runs at full speed and is unaware it is being observed.
However, non-blocking sampling can occasionally produce incomplete or
inconsistent stack traces in applications with many generators or coroutines
that rapidly switch between yield points, or in programs with very fast-changing
call stacks where functions enter and exit between the start and end of a single
stack read, resulting in reconstructed stacks that mix frames from different
execution states or that never actually existed.
For these cases, the :option:`--blocking` option stops the target process during
each sample::
python -m profiling.sampling run --blocking script.py
python -m profiling.sampling attach --blocking 12345
When blocking mode is enabled, the profiler suspends the target process,
reads its stack, then resumes it. This guarantees that each captured stack
represents a real, consistent snapshot of what the process was doing at that
instant. The trade-off is that the target process runs slower because it is
repeatedly paused.
.. warning::
Do not use very high sample rates (low ``--interval`` values) with blocking
mode. Suspending and resuming a process takes time, and if the sampling
interval is too short, the target will spend more time stopped than running.
For blocking mode, intervals of 1000 microseconds (1 millisecond) or higher
are recommended. The default 100 microsecond interval may cause noticeable
slowdown in the target application.
Use blocking mode only when you observe inconsistent stacks in your profiles,
particularly with generator-heavy or coroutine-heavy code. For most
applications, the default non-blocking mode provides accurate results with
zero impact on the target process.
Special frames
--------------
The profiler can inject artificial frames into the captured stacks to provide
additional context about what the interpreter is doing at the moment each
sample is taken. These synthetic frames help distinguish different types of
execution that would otherwise be invisible.
The :option:`--native` option adds ``<native>`` frames to indicate when Python has
called into C code (extension modules, built-in functions, or the interpreter
itself)::
python -m profiling.sampling run --native script.py
These frames help distinguish time spent in Python code versus time spent in
native libraries. Without this option, native code execution appears as time
in the Python function that made the call. This is useful when optimizing
code that makes heavy use of C extensions like NumPy or database drivers.
By default, the profiler includes ``<GC>`` frames when garbage collection is
active. The :option:`--no-gc` option suppresses these frames::
python -m profiling.sampling run --no-gc script.py
GC frames help identify programs where garbage collection consumes significant
time, which may indicate memory allocation patterns worth optimizing. If you
see substantial time in ``<GC>`` frames, consider investigating object
allocation rates or using object pooling.
Opcode-aware profiling
----------------------
The :option:`--opcodes` option enables instruction-level profiling that captures
which Python bytecode instructions are executing at each sample::
python -m profiling.sampling run --opcodes --flamegraph script.py
This feature provides visibility into Python's bytecode execution, including
adaptive specialization optimizations. When a generic instruction like
``LOAD_ATTR`` is specialized at runtime into a more efficient variant like
``LOAD_ATTR_INSTANCE_VALUE``, the profiler shows both the specialized name
and the base instruction.
Opcode information appears in several output formats:
- **Flame graphs**: Hovering over a frame displays a tooltip with a bytecode
instruction breakdown, showing which opcodes consumed time in that function
- **Heatmap**: Expandable bytecode panels per source line show instruction
breakdown with specialization percentages
- **Live mode**: An opcode panel shows instruction-level statistics for the
selected function, accessible via keyboard navigation
- **Gecko format**: Opcode transitions are emitted as interval markers in the
Firefox Profiler timeline
This level of detail is particularly useful for:
- Understanding the performance impact of Python's adaptive specialization
- Identifying hot bytecode instructions that might benefit from optimization
- Analyzing the effectiveness of different code patterns at the instruction level
- Debugging performance issues that occur at the bytecode level
The :option:`--opcodes` option is compatible with :option:`--live`, :option:`--flamegraph`,
:option:`--heatmap`, and :option:`--gecko` formats. It requires additional memory to store
opcode information and may slightly reduce sampling performance, but provides
unprecedented visibility into Python's execution model.
Real-time statistics
--------------------
The :option:`--realtime-stats` option displays sampling rate statistics during
profiling::
python -m profiling.sampling run --realtime-stats script.py
This shows the actual achieved sampling rate, which may be lower than requested
if the profiler cannot keep up. The statistics help verify that profiling is
working correctly and that sufficient samples are being collected. See
:ref:`sampling-efficiency` for details on interpreting these metrics.
Subprocess profiling
--------------------
The :option:`--subprocesses` option enables automatic profiling of subprocesses
spawned by the target::
python -m profiling.sampling run --subprocesses script.py
python -m profiling.sampling attach --subprocesses 12345
When enabled, the profiler monitors the target process for child process
creation. When a new Python child process is detected, a separate profiler
instance is automatically spawned to profile it. This is useful for
applications that use :mod:`multiprocessing`, :mod:`subprocess`,
:mod:`concurrent.futures` with :class:`~concurrent.futures.ProcessPoolExecutor`,
or other process spawning mechanisms.
.. code-block:: python
:caption: worker_pool.py
from concurrent.futures import ProcessPoolExecutor
import math
def compute_factorial(n):
total = 0
for i in range(50):
total += math.factorial(n)
return total
if __name__ == "__main__":
numbers = [5000 + i * 100 for i in range(50)]
with ProcessPoolExecutor(max_workers=4) as executor:
results = list(executor.map(compute_factorial, numbers))
print(f"Computed {len(results)} factorials")
::
python -m profiling.sampling run --subprocesses --flamegraph worker_pool.py
This produces separate flame graphs for the main process and each worker
process: ``flamegraph_<main_pid>.html``, ``flamegraph_<worker1_pid>.html``,
and so on.
Each subprocess receives its own output file. The filename is derived from
the specified output path (or the default) with the subprocess's process ID
appended:
- If you specify ``-o profile.html``, subprocesses produce ``profile_12345.html``,
``profile_12346.html``, and so on
- With default output, subprocesses produce files like ``flamegraph_12345.html``
or directories like ``heatmap_12345``
- For pstats format (which defaults to stdout), subprocesses produce files like
``profile_12345.pstats``
The subprocess profilers inherit most sampling options from the parent (sampling
rate, duration, thread selection, native frames, GC frames, async-aware mode,
and output format). All Python descendant processes are profiled recursively,
including grandchildren and further descendants.
Subprocess detection works by periodically scanning for new descendants of
the target process and checking whether each new process is a Python process
by probing the process memory for Python runtime structures. Non-Python
subprocesses (such as shell commands or external tools) are ignored.
There is a limit of 100 concurrent subprocess profilers to prevent resource
exhaustion in programs that spawn many processes. If this limit is reached,
additional subprocesses are not profiled and a warning is printed.
The :option:`--subprocesses` option is incompatible with :option:`--live` mode
because live mode uses an interactive terminal interface that cannot
accommodate multiple concurrent profiler displays.
.. _sampling-efficiency:
Sampling efficiency
-------------------
Sampling efficiency metrics help assess the quality of the collected data.
These metrics appear in the profiler's terminal output and in the flame graph
sidebar.
**Sampling efficiency** is the percentage of sample attempts that succeeded.
Each sample attempt reads the target process's call stack from memory. An
attempt can fail if the process is in an inconsistent state at the moment of
reading, such as during a context switch or while the interpreter is updating
its internal structures. A low efficiency may indicate that the profiler could
not keep up with the requested sampling rate, often due to system load or an
overly aggressive interval setting.
**Missed samples** is the percentage of expected samples that were not
collected. Based on the configured interval and duration, the profiler expects
to collect a certain number of samples. Some samples may be missed if the
profiler falls behind schedule, for example when the system is under heavy
load. A small percentage of missed samples is normal and does not significantly
affect the statistical accuracy of the profile.
Both metrics are informational. Even with some failed attempts or missed
samples, the profile remains statistically valid as long as enough samples
were collected. The profiler reports the actual number of samples captured,
which you can use to judge whether the data is sufficient for your analysis.
Profiling modes
===============
The sampling profiler supports four modes that control which samples are
recorded. The mode determines what the profile measures: total elapsed time,
CPU execution time, time spent holding the global interpreter lock, or
exception handling.
Wall-clock mode
---------------
Wall-clock mode (:option:`--mode`\ ``=wall``) captures all samples regardless of what the
thread is doing. This is the default mode and provides a complete picture of
where time passes during program execution::
python -m profiling.sampling run --mode=wall script.py
In wall-clock mode, samples are recorded whether the thread is actively
executing Python code, waiting for I/O, blocked on a lock, or sleeping.
This makes wall-clock profiling ideal for understanding the overall time
distribution in your program, including time spent waiting.
If your program spends significant time in I/O operations, network calls, or
sleep, wall-clock mode will show these waits as time attributed to the calling
function. This is often exactly what you want when optimizing end-to-end
latency.
CPU mode
--------
CPU mode (:option:`--mode`\ ``=cpu``) records samples only when the thread is actually
executing on a CPU core::
python -m profiling.sampling run --mode=cpu script.py
Samples taken while the thread is sleeping, blocked on I/O, or waiting for
a lock are discarded. The resulting profile shows where CPU cycles are consumed,
filtering out idle time.
CPU mode is useful when you want to focus on computational hotspots without
being distracted by I/O waits. If your program alternates between computation
and network calls, CPU mode reveals which computational sections are most
expensive.
Comparing wall-clock and CPU profiles
-------------------------------------
Running both wall-clock and CPU mode profiles can reveal whether a function's
time is spent computing or waiting.
If a function appears prominently in both profiles, it is a true computational
hotspot---actively using the CPU. Optimization should focus on algorithmic
improvements or more efficient code.
If a function is high in wall-clock mode but low or absent in CPU mode, it is
I/O-bound or waiting. The function spends most of its time waiting for network,
disk, locks, or sleep. CPU optimization won't help here; consider async I/O,
connection pooling, or reducing wait time instead.
.. code-block:: python
import time
def do_sleep():
time.sleep(2)
def do_compute():
sum(i**2 for i in range(1000000))
if __name__ == "__main__":
do_sleep()
do_compute()
::
python -m profiling.sampling run --mode=wall script.py # do_sleep ~98%, do_compute ~1%
python -m profiling.sampling run --mode=cpu script.py # do_sleep absent, do_compute dominates
GIL mode
--------
GIL mode (:option:`--mode`\ ``=gil``) records samples only when the thread holds Python's
global interpreter lock::
python -m profiling.sampling run --mode=gil script.py
The GIL is held only while executing Python bytecode. When Python calls into
C extensions, performs I/O operations, or executes native code, the GIL is
typically released. This means GIL mode effectively measures time spent
running Python code specifically, filtering out time in native libraries.
In multi-threaded programs, GIL mode reveals which code is preventing other
threads from running Python bytecode. Since only one thread can hold the GIL
at a time, functions that appear frequently in GIL mode profiles are
monopolizing the interpreter.
GIL mode helps answer questions like "which functions are monopolizing the
GIL?" and "why are my other threads starving?" It can also be useful in
single-threaded programs to distinguish Python execution time from time spent
in C extensions or I/O.
.. code-block:: python
import hashlib
def hash_work():
# C extension - releases GIL during computation
for _ in range(200):
hashlib.sha256(b"data" * 250000).hexdigest()
def python_work():
# Pure Python - holds GIL during computation
for _ in range(3):
sum(i**2 for i in range(1000000))
if __name__ == "__main__":
hash_work()
python_work()
::
python -m profiling.sampling run --mode=cpu script.py # hash_work ~42%, python_work ~38%
python -m profiling.sampling run --mode=gil script.py # hash_work ~5%, python_work ~60%
Exception mode
--------------
Exception mode (``--mode=exception``) records samples only when a thread has
an active exception::
python -m profiling.sampling run --mode=exception script.py
Samples are recorded in two situations: when an exception is being propagated
up the call stack (after ``raise`` but before being caught), or when code is
executing inside an ``except`` block where exception information is still
present in the thread state.
The following example illustrates which code regions are captured:
.. code-block:: python
def example():
try:
raise ValueError("error") # Captured: exception being raised
except ValueError:
process_error() # Captured: inside except block
finally:
cleanup() # NOT captured: exception already handled
def example_propagating():
try:
try:
raise ValueError("error")
finally:
cleanup() # Captured: exception propagating through
except ValueError:
pass
def example_no_exception():
try:
do_work()
finally:
cleanup() # NOT captured: no exception involved
Note that ``finally`` blocks are only captured when an exception is actively
propagating through them. Once an ``except`` block finishes executing, Python
clears the exception information before running any subsequent ``finally``
block. Similarly, ``finally`` blocks that run during normal execution (when no
exception was raised) are not captured because no exception state is present.
This mode is useful for understanding where your program spends time handling
errors. Exception handling can be a significant source of overhead in code
that uses exceptions for flow control (such as ``StopIteration`` in iterators)
or in applications that process many error conditions (such as network servers
handling connection failures).
Exception mode helps answer questions like "how much time is spent handling
exceptions?" and "which exception handlers are the most expensive?" It can
reveal hidden performance costs in code that catches and processes many
exceptions, even when those exceptions are handled gracefully. For example,
if a parsing library uses exceptions internally to signal format errors, this
mode will capture time spent in those handlers even if the calling code never
sees the exceptions.
Output formats
==============
The profiler produces output in several formats, each suited to different
analysis workflows. The format is selected with a command-line flag, and
output goes to stdout, a file, or a directory depending on the format.
pstats format
-------------
The pstats format (:option:`--pstats`) produces a text table similar to what
deterministic profilers generate. This is the default output format::
python -m profiling.sampling run script.py
python -m profiling.sampling run --pstats script.py
.. figure:: tachyon-pstats.png
:alt: Tachyon pstats terminal output
:align: center
:width: 100%
The pstats format displays profiling results in a color-coded table showing
function hotspots, sample counts, and timing estimates.
Output appears on stdout by default::
Profile Stats (Mode: wall):
nsamples sample% tottime (ms) cumul% cumtime (ms) filename:lineno(function)
234/892 11.7% 234.00 44.6% 892.00 server.py:145(handle_request)
156/156 7.8% 156.00 7.8% 156.00 <built-in>:0(socket.recv)
98/421 4.9% 98.00 21.1% 421.00 parser.py:67(parse_message)
The columns show sampling counts and estimated times:
- **nsamples**: Displayed as ``direct/cumulative`` (for example, ``10/50``).
Direct samples are when the function was at the top of the stack, actively
executing. Cumulative samples are when the function appeared anywhere on the
stack, including when it was waiting for functions it called. If a function
shows ``10/50``, it was directly executing in 10 samples and was on the call
stack in 50 samples total.
- **sample%** and **cumul%**: Percentages of total samples for direct and
cumulative counts respectively.
- **tottime** and **cumtime**: Estimated wall-clock time based on sample counts
and the profiling duration. Time units are selected automatically based on
the magnitude: seconds for large values, milliseconds for moderate values,
or microseconds for small values.
The output includes a legend explaining each column and a summary of
interesting functions that highlights:
- **Hot spots**: Functions with high direct/cumulative sample ratio (ratio
close to 1.0). These functions spend most of their time executing their own
code rather than waiting for callees. High ratios indicate where CPU time
is actually consumed.
- **Indirect calls**: Functions with large differences between cumulative and
direct samples. These are orchestration functions that delegate work to
other functions. They appear frequently on the stack but rarely at the top.
- **Call magnification**: Functions where cumulative samples far exceed direct
samples (high cumulative/direct multiplier). These are frequently-nested
functions that appear deep in many call chains.
Use :option:`--no-summary` to suppress both the legend and summary sections.
To save pstats output to a binary file instead of stdout::
python -m profiling.sampling run -o profile.pstats script.py
The pstats format supports several options for controlling the display.
The :option:`--sort` option determines the column used for ordering results::
python -m profiling.sampling run --sort=tottime script.py
python -m profiling.sampling run --sort=cumtime script.py
python -m profiling.sampling run --sort=nsamples script.py
The :option:`--limit` option restricts output to the top N entries::
python -m profiling.sampling run --limit=30 script.py
The :option:`--no-summary` option suppresses the header summary that precedes the
statistics table.
Collapsed stacks format
-----------------------
Collapsed stacks format (:option:`--collapsed`) produces one line per unique call
stack, with a count of how many times that stack was sampled::
python -m profiling.sampling run --collapsed script.py