|
| 1 | +.. _profiling-tracing: |
| 2 | + |
| 3 | +**************************************************** |
| 4 | +:mod:`profiling.tracing` --- Deterministic Profiler |
| 5 | +**************************************************** |
| 6 | + |
| 7 | +.. module:: profiling.tracing |
| 8 | + :synopsis: Deterministic tracing profiler for Python programs. |
| 9 | + |
| 10 | +**Source code:** :source:`Lib/profiling/tracing/` |
| 11 | + |
| 12 | +-------------- |
| 13 | + |
| 14 | +.. versionadded:: 3.15 |
| 15 | + |
| 16 | +The :mod:`profiling.tracing` module provides deterministic profiling of Python |
| 17 | +programs. It monitors every function call, function return, and exception event, |
| 18 | +recording precise timing for each. This approach provides exact call counts and |
| 19 | +complete visibility into program execution, making it ideal for development and |
| 20 | +testing scenarios. |
| 21 | + |
| 22 | +.. note:: |
| 23 | + |
| 24 | + This module is also available as :mod:`cProfile` for backward compatibility. |
| 25 | + The :mod:`cProfile` name will continue to work in all future Python versions. |
| 26 | + Use whichever import style suits your codebase:: |
| 27 | + |
| 28 | + # Preferred (new style) |
| 29 | + import profiling.tracing |
| 30 | + profiling.tracing.run('my_function()') |
| 31 | + |
| 32 | + # Also works (backward compatible) |
| 33 | + import cProfile |
| 34 | + cProfile.run('my_function()') |
| 35 | + |
| 36 | + |
| 37 | +What Is Deterministic Profiling? |
| 38 | +================================ |
| 39 | + |
| 40 | +:dfn:`Deterministic profiling` captures every function call, function return, |
| 41 | +and exception event during program execution. The profiler measures the precise |
| 42 | +time intervals between these events, providing exact statistics about how the |
| 43 | +program behaves. |
| 44 | + |
| 45 | +In contrast to :ref:`statistical profiling <profiling-sampling>`, which samples |
| 46 | +the call stack periodically to estimate where time is spent, deterministic |
| 47 | +profiling records every event. This means you get exact call counts rather than |
| 48 | +statistical approximations. The trade-off is that instrumenting every event |
| 49 | +introduces overhead that can slow down program execution. |
| 50 | + |
| 51 | +Python's interpreted nature makes deterministic profiling practical. The |
| 52 | +interpreter already dispatches events for function calls and returns, so the |
| 53 | +profiler can hook into this mechanism without requiring code modification. The |
| 54 | +overhead tends to be moderate relative to the inherent cost of interpretation, |
| 55 | +making deterministic profiling suitable for most development workflows. |
| 56 | + |
| 57 | +Deterministic profiling helps answer questions like: |
| 58 | + |
| 59 | +- How many times was this function called? |
| 60 | +- What is the complete call graph of my program? |
| 61 | +- Which functions are called by a particular function? |
| 62 | +- Are there unexpected function calls happening? |
| 63 | + |
| 64 | +Call count statistics can identify bugs (surprising counts) and inline |
| 65 | +expansion opportunities (high call counts). Internal time statistics reveal |
| 66 | +"hot loops" that warrant optimization. Cumulative time statistics help identify |
| 67 | +algorithmic inefficiencies. The handling of cumulative times in this profiler |
| 68 | +allows direct comparison of recursive and iterative implementations. |
| 69 | + |
| 70 | + |
| 71 | +.. _profiling-tracing-cli: |
| 72 | + |
| 73 | +Command Line Interface |
| 74 | +====================== |
| 75 | + |
| 76 | +.. program:: profiling.tracing |
| 77 | + |
| 78 | +The :mod:`profiling.tracing` module can be invoked as a script to profile |
| 79 | +another script or module:: |
| 80 | + |
| 81 | + python -m profiling.tracing [-o output_file] [-s sort_order] (-m module | myscript.py) |
| 82 | + |
| 83 | +This runs the specified script or module under the profiler and prints the |
| 84 | +results to standard output (or saves them to a file). |
| 85 | + |
| 86 | +.. option:: -o <output_file> |
| 87 | + |
| 88 | + Write the profile results to a file instead of standard output. The output |
| 89 | + file can be read by the :mod:`pstats` module for later analysis. |
| 90 | + |
| 91 | +.. option:: -s <sort_order> |
| 92 | + |
| 93 | + Sort the output by the specified key. This accepts any of the sort keys |
| 94 | + recognized by :meth:`pstats.Stats.sort_stats`, such as ``cumulative``, |
| 95 | + ``time``, ``calls``, or ``name``. This option only applies when |
| 96 | + :option:`-o <profiling.tracing -o>` is not specified. |
| 97 | + |
| 98 | +.. option:: -m <module> |
| 99 | + |
| 100 | + Profile a module instead of a script. The module is located using the |
| 101 | + standard import mechanism. |
| 102 | + |
| 103 | + .. versionadded:: 3.7 |
| 104 | + The ``-m`` option for :mod:`cProfile`. |
| 105 | + |
| 106 | + .. versionadded:: 3.8 |
| 107 | + The ``-m`` option for :mod:`profile`. |
| 108 | + |
| 109 | + |
| 110 | +Programmatic Usage Examples |
| 111 | +=========================== |
| 112 | + |
| 113 | +For more control over profiling, use the module's functions and classes |
| 114 | +directly. |
| 115 | + |
| 116 | + |
| 117 | +Basic Profiling |
| 118 | +--------------- |
| 119 | + |
| 120 | +The simplest approach uses the :func:`run` function:: |
| 121 | + |
| 122 | + import profiling.tracing |
| 123 | + profiling.tracing.run('my_function()') |
| 124 | + |
| 125 | +This profiles the given code string and prints a summary to standard output. |
| 126 | +To save results for later analysis:: |
| 127 | + |
| 128 | + profiling.tracing.run('my_function()', 'output.prof') |
| 129 | + |
| 130 | + |
| 131 | +Using the Profile Class |
| 132 | +----------------------- |
| 133 | + |
| 134 | +The :class:`Profile` class provides fine-grained control:: |
| 135 | + |
| 136 | + import profiling.tracing |
| 137 | + import pstats |
| 138 | + from io import StringIO |
| 139 | + |
| 140 | + pr = profiling.tracing.Profile() |
| 141 | + pr.enable() |
| 142 | + # ... code to profile ... |
| 143 | + pr.disable() |
| 144 | + |
| 145 | + # Print results |
| 146 | + s = StringIO() |
| 147 | + ps = pstats.Stats(pr, stream=s).sort_stats(pstats.SortKey.CUMULATIVE) |
| 148 | + ps.print_stats() |
| 149 | + print(s.getvalue()) |
| 150 | + |
| 151 | +The :class:`Profile` class also works as a context manager:: |
| 152 | + |
| 153 | + import profiling.tracing |
| 154 | + |
| 155 | + with profiling.tracing.Profile() as pr: |
| 156 | + # ... code to profile ... |
| 157 | + |
| 158 | + pr.print_stats() |
| 159 | + |
| 160 | + |
| 161 | +Module Reference |
| 162 | +================ |
| 163 | + |
| 164 | +.. currentmodule:: profiling.tracing |
| 165 | + |
| 166 | +.. function:: run(command, filename=None, sort=-1) |
| 167 | + |
| 168 | + Profile execution of a command and print or save the results. |
| 169 | + |
| 170 | + This function executes the *command* string using :func:`exec` in the |
| 171 | + ``__main__`` module's namespace:: |
| 172 | + |
| 173 | + exec(command, __main__.__dict__, __main__.__dict__) |
| 174 | + |
| 175 | + If *filename* is not provided, the function creates a :class:`pstats.Stats` |
| 176 | + instance and prints a summary to standard output. If *filename* is |
| 177 | + provided, the raw profile data is saved to that file for later analysis |
| 178 | + with :mod:`pstats`. |
| 179 | + |
| 180 | + The *sort* argument specifies the sort order for printed output, accepting |
| 181 | + any value recognized by :meth:`pstats.Stats.sort_stats`. |
| 182 | + |
| 183 | + |
| 184 | +.. function:: runctx(command, globals, locals, filename=None, sort=-1) |
| 185 | + |
| 186 | + Profile execution of a command with explicit namespaces. |
| 187 | + |
| 188 | + Like :func:`run`, but executes the command with the specified *globals* |
| 189 | + and *locals* mappings instead of using the ``__main__`` module's namespace:: |
| 190 | + |
| 191 | + exec(command, globals, locals) |
| 192 | + |
| 193 | + |
| 194 | +.. class:: Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True) |
| 195 | + |
| 196 | + A profiler object that collects execution statistics. |
| 197 | + |
| 198 | + The optional *timer* argument specifies a custom timing function. If not |
| 199 | + provided, the profiler uses a platform-appropriate default timer. When |
| 200 | + supplying a custom timer, it must return a single number representing the |
| 201 | + current time. If the timer returns integers, use *timeunit* to specify the |
| 202 | + duration of one time unit (for example, ``0.001`` for milliseconds). |
| 203 | + |
| 204 | + The *subcalls* argument controls whether the profiler tracks call |
| 205 | + relationships between functions. The *builtins* argument controls whether |
| 206 | + built-in functions are profiled. |
| 207 | + |
| 208 | + .. versionchanged:: 3.8 |
| 209 | + Added context manager support. |
| 210 | + |
| 211 | + .. method:: enable() |
| 212 | + |
| 213 | + Start collecting profiling data. |
| 214 | + |
| 215 | + .. method:: disable() |
| 216 | + |
| 217 | + Stop collecting profiling data. |
| 218 | + |
| 219 | + .. method:: create_stats() |
| 220 | + |
| 221 | + Stop collecting data and record the results internally as the current |
| 222 | + profile. |
| 223 | + |
| 224 | + .. method:: print_stats(sort=-1) |
| 225 | + |
| 226 | + Create a :class:`pstats.Stats` object from the current profile and print |
| 227 | + the results to standard output. |
| 228 | + |
| 229 | + The *sort* argument specifies the sorting order. It accepts a single |
| 230 | + key or a tuple of keys for multi-level sorting, using the same values |
| 231 | + as :meth:`pstats.Stats.sort_stats`. |
| 232 | + |
| 233 | + .. versionadded:: 3.13 |
| 234 | + Support for a tuple of sort keys. |
| 235 | + |
| 236 | + .. method:: dump_stats(filename) |
| 237 | + |
| 238 | + Write the current profile data to *filename*. The file can be read by |
| 239 | + :class:`pstats.Stats` for later analysis. |
| 240 | + |
| 241 | + .. method:: run(cmd) |
| 242 | + |
| 243 | + Profile the command string via :func:`exec`. |
| 244 | + |
| 245 | + .. method:: runctx(cmd, globals, locals) |
| 246 | + |
| 247 | + Profile the command string via :func:`exec` with the specified |
| 248 | + namespaces. |
| 249 | + |
| 250 | + .. method:: runcall(func, /, *args, **kwargs) |
| 251 | + |
| 252 | + Profile a function call. Returns whatever *func* returns:: |
| 253 | + |
| 254 | + result = pr.runcall(my_function, arg1, arg2, keyword=value) |
| 255 | + |
| 256 | +.. note:: |
| 257 | + |
| 258 | + Profiling requires that the profiled code returns normally. If the |
| 259 | + interpreter terminates (for example, via :func:`sys.exit`) during |
| 260 | + profiling, no results will be available. |
| 261 | + |
| 262 | + |
| 263 | +Using a Custom Timer |
| 264 | +==================== |
| 265 | + |
| 266 | +The :class:`Profile` class accepts a custom timing function, allowing you to |
| 267 | +measure different aspects of execution such as wall-clock time or CPU time. |
| 268 | +Pass the timing function to the constructor:: |
| 269 | + |
| 270 | + pr = profiling.tracing.Profile(my_timer_function) |
| 271 | + |
| 272 | +The timer function must return a single number representing the current time. |
| 273 | +If it returns integers, also specify *timeunit* to indicate the duration of |
| 274 | +one unit:: |
| 275 | + |
| 276 | + # Timer returns time in milliseconds |
| 277 | + pr = profiling.tracing.Profile(my_ms_timer, 0.001) |
| 278 | + |
| 279 | +For best performance, the timer function should be as fast as possible. The |
| 280 | +profiler calls it frequently, so timer overhead directly affects profiling |
| 281 | +overhead. |
| 282 | + |
| 283 | +The :mod:`time` module provides several functions suitable for use as custom |
| 284 | +timers: |
| 285 | + |
| 286 | +- :func:`time.perf_counter` for high-resolution wall-clock time |
| 287 | +- :func:`time.process_time` for CPU time (excluding sleep) |
| 288 | +- :func:`time.monotonic` for monotonic clock time |
| 289 | + |
| 290 | + |
| 291 | +Limitations |
| 292 | +=========== |
| 293 | + |
| 294 | +Deterministic profiling has inherent limitations related to timing accuracy. |
| 295 | + |
| 296 | +The underlying timer typically has a resolution of about 1 millisecond. |
| 297 | +Measurements cannot be more accurate than this resolution. With enough |
| 298 | +measurements, timing errors tend to average out, but individual measurements |
| 299 | +may be imprecise. |
| 300 | + |
| 301 | +There is also latency between when an event occurs and when the profiler |
| 302 | +captures the timestamp. Similarly, there is latency after reading the |
| 303 | +timestamp before user code resumes. Functions called frequently accumulate |
| 304 | +this latency, which can make them appear slower than they actually are. This |
| 305 | +error is typically less than one clock tick per call but can become |
| 306 | +significant for functions called many times. |
| 307 | + |
| 308 | +The :mod:`profiling.tracing` module (and its :mod:`cProfile` alias) is |
| 309 | +implemented as a C extension with low overhead, so these timing issues are |
| 310 | +less pronounced than with the deprecated pure Python :mod:`profile` module. |
| 311 | + |
| 312 | + |
| 313 | +.. seealso:: |
| 314 | + |
| 315 | + :mod:`profiling` |
| 316 | + Overview of Python profiling tools and guidance on choosing a profiler. |
| 317 | + |
| 318 | + :mod:`profiling.sampling` |
| 319 | + Statistical sampling profiler for production use. |
| 320 | + |
| 321 | + :mod:`pstats` |
| 322 | + Statistics analysis and formatting for profile data. |
| 323 | + |
| 324 | + :mod:`profile` |
| 325 | + Deprecated pure Python profiler (includes calibration documentation). |
0 commit comments