FEAT: extend profiling to child processes

[TTsangSC]

This PR adds support for kernprof to profile code execution in child Python processes, building on ongoing work (see Credits).

Usage

The EXPERIMENTAL new flags --no-prof-child-procs and --prof-child-procs[=...] are added to kernprof. By setting --prof-child-procs to true, child Python processes created by the profiled process are also profiled:¹

$ kernprof -lv --prof-child-procs -c "if True:
    import itertools
    import multiprocessing
    from collections.abc import Collection

    def sum_worker(nums: Collection[int]) -> int:
        result = 0
        for x in nums:
            result += x
        return result

    def sum_parallel(nums: Collection[int], nprocs: int) -> int:
        size_ = len(nums) / nprocs
        size = int(size_)
        if size_ > size:
            size += 1
        with multiprocessing.Pool(nprocs) as pool:
            sub_sums = pool.map(sum_worker, itertools.batched(nums, size))  # 3.12+
            pool.close()
            pool.join()
        return sum_worker(sub_sums)

    if __name__ == '__main__':
        print(sum_parallel(range(1, 1001), 3))"
500500
Wrote profile results to 'kernprof-command-<...>.lprof'
Timer unit: 1e-06 s

Total time: 0.000312 s
File: <...>/kernprof-command.py
Function: sum_worker at line 6

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     6                                               def sum_worker(nums: Collection[int]) -> int:
     7         4          3.0      0.8      1.0          result = 0
     8      1007        155.0      0.2     49.7          for x in nums:
     9      1003        153.0      0.2     49.0              result += x
    10         4          1.0      0.2      0.3          return result

Total time: 0.100223 s
File: <...>/kernprof-command.py
Function: sum_parallel at line 12

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
    12                                               def sum_parallel(nums: Collection[int], nprocs: int) -> int:
    13         1          1.0      1.0      0.0          size_ = len(nums) / nprocs
    14         1          1.0      1.0      0.0          size = int(size_)
    15         1          0.0      0.0      0.0          if size_ > size:
    16         1          0.0      0.0      0.0              size += 1
    17         2      21685.0  10842.5     21.6          with multiprocessing.Pool(nprocs) as pool:
    18         1      68692.0  68692.0     68.5              sub_sums = pool.map(sum_worker, itertools.batched(nums, size))  # 3.12+
    19         1         27.0     27.0      0.0              pool.close()
    20         1       9800.0   9800.0      9.8              pool.join()
    21         1         17.0     17.0      0.0          return sum_worker(sub_sums)

Note how the sum_worker() calls are profiled:

• The main process contributes 1 call and 3 loops summing the sub-sums.
• The 3 child processes each contributes 1 call, and they loop over all 1000 of the items combined.

Highlights

• Children created by (including but not limited to) these methods can be profiled:
  • os.system() and subprocess.run()
  • multiprocessing²
  • concurrent.futures
• All three multiprocessing "start methods" ('fork', 'forkserver', and 'spawn') tested to be compatible, where available on the platform
• Profiling unaffected by whether the profiled function run in child processes:
  • Is locally defined in the profiled code or imported
  • Executes cleanly or errors out
• Mode of profiling (with eager --preimports or via test-code rewriting) replicated in child processes

Explanation

• A serializable cache object (line_profiler._child_process_profiling.cache.LineProfilingCache) is created by the main process, containing session config information (e.g. values for --prod-mod and --preimports) so that profiling can be replicated in child processes.
• In the main process, environment variables are injected, so that it and its children would have access to its PID and the cache-directory location.
• A temporary .pth file is created; Python processes inheriting the right environment will thus go through profiling setup, while those without the env var (and just happens to share the Python executable) will be minimally affected.
• os.fork() (where available) is patched with a wrapper which ensures consistent global states.
• As with coverage.multiproc, various multiprocessing components are patched (line_profiler._child_process_profiling.multiprocessing_patches.apply()) so that child processes can retrieve the cache and report profiling data appropriately. Patches are inherited by forked child processes and reapplied by spawned ones. Extra care is taken in ensuring that profiling is not affected even when the parallel workload errors out.³
• When properly set up, child processes write profiling output on exit to the session cache directory, which kernprof then gather and merge with the profiling result in main process.

Code changes

New code (click to expand)

_line_profiler_hook.py

New module installed along with line_profiler for managing the temporary .pth files used for setting up profiling in child processes; this module is kept as lightweight as possible to minimize the amount of startup code run as the mere result of having said .pth file(s) (presumably) in the virtual environment's site-packages.

• load_pth_hook():
  For processes inheriting a matching "parent PID" from the environment (see LineProfilingCache below), load the cache and set up the LineProfiler instance used, like how the main kernprof process does.

line_profiler/_threading_patches.py

New submodule patching threading for the consistent gathering of profiling data between tracing modes.

• apply():
  When legacy tracing is used (Python < 3.12 or LINE_PROFILER_CORE=ctrace), patch threading.Thread.__init__() so that the profiler's .enable_count is synced to the new thread; this is necessary for correctness, ensuring that profiling continues on the new thread.

line_profiler/cleanup.py

New submodule defining the Cleanup class, which handles various setup/cleanup tasks like:

• Registering/Calling callbacks
• Creation/Deletion of tempfiles
• Insertion/Reversion of environment variables
• Patching/Restoration of object attributes

line_profiler/curated_profiling.py

New submodule containing mostly relocated code from kernprof, so that child processes can more easily reestablish profiling:

• ClassifiedPreimportTargets:
  Object resolving and classifying the --prof-mods, and writing a corresponding preimport module
• CuratedProfilerContext:
  Context manager managing the state of the LineProfiler, e.g.:
  • Slipping it into line_profiler.profile on startup
  • Patching threading (see _threading_patches above) so that the profiler stays enabled on newly spawned threads
  • Purging its .enable_counts on teardown

line_profiler/_child_process_profiling/

New private subpackage for maintaining the states, setting up the hooks, and performing the patches which makes it possible to profile child processes:

• /cache.py::LineProfilingCache:
  "Session state" object. It:

  • Can be auto-(de-)serialized in the main and child processes based on env-var values, managing setup (module patches, .pth tempfile creation, profiler curation, eager pre-imports) and cleanup (tempfile management, dumping and gathering of profiling results) in each process.

  • Injects the following environment variables, which are inherited by child processes:

    • ${LINE_PROFILER_PROFILE_CHILD_PROCESSES_CACHE_PID}: main-process PID
    • ${LINE_PROFILER_PROFILE_CHILD_PROCESSES_CACHE_DIR_<PID>}: location of the cache directory

    From the combination of both, child processes can retrieve the cache by calling .load().

• /multiprocessing_patches/:
  Sub-sub-package for the patching of multiprocessing facilities so that child processes managed thereby are properly profiled. The main entities are:
  • /__init__.py::apply():
    Select and apply the appropriate patches below to multiprocessing module components.
  • /_mandatory_patches.py::PROCESS_SETUP_PATCH:
    Patch: perform setups specific to multiprocessing-managed child processes.
  • /_mandatory_patches.py::POOL_WORKER_PID_PATCH:
    Patch: keep track of which multiprocessing.pool tasks are sent to which Pool-worker child processes, so that we don't expect profiling output from idle workers.
  • /_mandatory_patches.py::RESOURCE_TRACKER_PATCH:
    Patch: make sure that profiling isn't set up on the resource-tracker server process, and if it is, tear it down. This ensures that when the profiling session ends and cleans up in the parent process, it wouldn't cause problems in the server process.
  • /_mandatory_patches.py::RebootForkserverPatch:
    Patch: manage the fork-server process (from which child processes are, well, forked; see multiprocessing.forkserver), ensuring that (1) when profiling, it is rebooted with the proper profiling tooling which its forked children can inherit, and (2) when profiling ends, it is rebooted so that said tooling doesn't leak into future child processes.
  • /_mandatory_patches.py::RunpyPatch:
    Patch the copy of runpy that multiprocessing.spawn uses; necessary for profiling to function in non-eager-preimports mode (--no-preimports).
  • /_profiling_patches.py::POOL_PATCH:
    Patch multiprocessing.pool so that Pool-worker child processes dump profiling data after every task received,³ regardless of whether the parallel workload succeeded or errored out.
  • /_profiling_patches.py::PROCESS_PATCH:
    Patch multiprocessing.process.BaseProcess so that child processes dump profiling data after the parallel workload (Process(target=...)) is executed.
  • /_optional_patches.py::LOGGING_PATCH:
    Patch the various logging functions in multiprocessing.util (e.g. multiprocessing.util.info()) so that their log entries are also visible in the LineProfilingCache debug logs.
• /runpy_patches.py::create_runpy_wrapper():
  Make a clone of the runpy module which checks if the code executed is the code to be profiled; if so, it goes through the same code-rewriting facilities that line_profiler.autoprofile.autoprofile.run() uses to set up profiling. (See RunpyPatch above.)

tests/test_child_procs/

Refactored and greatly extended into a package from the previous tests/test_child_procs.py; the tests proper are now found at tests/test_child_procs/test_child_procs.py, while the example scripts/modules to be profiled have been moved to their own respective files in tests/test_child_procs/multiproc_examples/.

• /_test_child_procs_utils.py:
  Define various utilities, e.g.:
  • ModuleFixture:
    Helper object to be created as pytest fixtures which encapsulates the /multiproc_examples/ scripts, making them temporarily available as modules in the current and/or child processes.
  • Params:
    Helper object extending @pytest.mark.parametrize() which handles concatenation and Cartesian products of parametrizations.
  • CheckWarnings:
    Helper object analogous to @pytest.warns() allowing for easy checks for/against certain warnings issued.
  • @add_timeout:
    Decorator for isolating a function in a new thread so that it can be timed out.
  • run_subproc():
    Wrapper around subprocess.run() which provide extra debugging output (standard streams, timing info, etc.)
• /multiproc_examples/:
  The example scripts to be profiled.
  • /pool_test_module.py, /external_module.py:
    The existing example script (and the module it imports), where multiprocessing.pool.Pool is used for parallelism.
  • /process_test_module.py:
    New example script mirroring /pool_test_module.py which instead directly manages instances of multiprocessing.process.BaseProcess and communication of parallel workloads and results therewith.
  • /concurrent_test_module.py:
    New example script mirroring /pool_test_module.py which uses a concurrent.futures.Executor instead of a multiprocessing pool, and deals with futures instead of tasks.
• /conftest.py:
  Set up _test_child_procs_utils.py::ModuleFixture fixtures for the /multiproc_examples/ scripts so that they can be imported as modules in tests.
• /test_pool_protocol.py:
  (Contributed by @Erotemic.) New tests making sure the profiling session is resilient to failures in setting up profiling in child processes; profiling stats therefrom may be lost, but it doesn't cause the executed code to fail or other stats to be lost.
• /test_fork_stats_attribute.py:
  (Contributed by @Erotemic.) New tests making sure when child processes are created with os.fork(), preexisting profiling stats already accumulated on the session LineProfiler object aren't double-counted.
• /test_child_procs.py:
  • Added "unit tests" for the line_profiler._child_processing_profiling components, or as close as is possible thereto:
    • test_runpy_patches():
      Test the functionality of ~.runpy_patches.create_runpy_wrapper().
    • test_cache_dump_load():
      Test the functionalities of ~.cache.LineProfilingCache.dump() and .load().
    • test_cache_setup_main_process():
      Test the functionality of ~.cache.LineProfilingCache._setup_in_main_process().
    • test_cache_setup_child():
      Test the functionality of ~.cache.LineProfilingCache._setup_in_child_process().
    • test_load_pth_hook():
      Test the functionality of ~.pth_hook.load_pth_hook().
    • test_apply_mp_patches_{success,failure}():
      Test the functionality of ~.multiprocessing_patches.apply().
  • Other new tests:
    • test_profiling_multiproc_script_{success,failure}():
      "Main" new tests for running the test scripts with kernprof --prof-child-procs; heavily parametrized to check for profiling-result correctness in different contexts:
      • success|failure: whether the parallel workload errors out
      • run_func: execution modes (kernprof <script>, kernprof -m <module>, and kernprof -c <code>)
      • test_module: whether to run pool_test_module.py (testing multiprocessing.pool) or process_test_module.py (testing multiprocessing.process)
      • prof_child_procs: whether to use child-process profiling (--[no-]prof-child-procs)
      • preimports: eager vs. on-import profiling (--[no-]preimports)
      • use_local_func: whether the parallel workload is locally defined in the executed code or imported from external modules
      • start_method: multiprocessing "start methods" ('fork', 'forkserver', and 'spawn')
    • test_profiling_bare_python():
      New test for profiling child processes where the code run by kernprof --prof-child-procs spins up another Python process via non-multiprocessing means (e.g. os.system() or subprocess.run()).
• /test_abnormal_execution.py:
  New tests for various edge cases where profiling is hindered on child processes for various reasons, testing that overall code execution and stats-gathering from other processes (incl. the main one) are not affected.
  • test_prematurely_terminated_process(): when the multiprocessing.process.Process is .terminated() and thus cannot properly clean up
  • test_corrupted_child_stats_file(): when the LineStats file written is corrupted and thus cannot be read
  • test_unwritable_purelib_path(): when a .pth file cannot be written, and thus profiling cannot be set up on non-forked child processes

Modified code (fixes; click to expand)

pyproject.toml::[tool.ty.terminal]

Now explicitly setting error-on-warning to false because the default behavior changed in ty v0.0.52. (Note that this conflicts with identical change made in #434.)

line_profiler/line_profiler.py::LineStats

Fixed doctest in multiple methods (.__eq__(), .__add__(), .__iadd__(), .from_stats_objects()) which may give the wrong impression of the layout of the .timings; the dict keys are supposed to be of the layout (filename: str, lineno: int, func_name: str), not (func_name, lineno, filename).

line_profiler/toml_config.py::ConfigSource.get_subconfig()

Fixed bug where the subtable is not deep-copied even with copy=True.

kernprof.py::_prepare_profiler()

Fixed bug in the pre-refactor _pre_profile() where sys.argv is replaced with another list, preventing the @_restore.sequence(sys.argv) decorator from correctly restoring the sys.argv entries; also see the section below.

Modified code (others; click to expand)

.github/workflows/tests.yml

Added timeouts to job stages where pytest is invoked, so that if multiprocessing causes any of the new tests to deadlock the whole pipeline doesn't get stuck in limbo for hours.

• Build sdist -> Test full loose dist: 10 minutes
• <OS>, arch=<ARCH> -> Build binary wheels: 60 minutes
• <PYTHON_VERS> on <OS>, arch=<ARCH> with <EXTRA> -> Test wheel <EXTRA>: 10 minutes

setup.py

Added _line_profiler_hooks to the installed among the setuptools.setup(py_modules=[...]).

line_profiler/line_profiler.py::LineStats

• .get_empty_instance():
  New convenience class method for creating an instance with no profiling data and the platform-appropriate .unit.
• .from_files():
  Added new parameters on_defective | on_empty: Literal['ignore', 'warn', 'error'], allowing for passing over bad (empty/malformed) files with optional warnings. The old behavior (on_defective=on_empty='error') remains the default.

line_profiler/line_profiler_utils.py

Added new utilties:

• CallbackRepr:
  reprlib.Repr subclass helpful for formatting calls (via its .format_call() method) and adjacent objects (e.g. functools.partial).
• block_indent():
  Block-indent a multi-line string to sit flush with a prefix.
• make_tempfile():
  Convenience wrapper around tempfile.mkstemp() which returns a pathlib.Path.

line_profiler/rc/line_profiler.toml

• [tool.line_profiler.kernprof]:
  New key-value pair prof-child-procs = <bool> for the default of the kernprof --[no-]prof-child-procs flag.

• [tool.line_profiler.child_processes]:
  New key-value pairs for controlling the setup of profiling in child processes:

  • pth_files = { prefix = <str>, suffix = <str>}:
    Instructions on how the temporary .pth files responsible for setting up shop in child processes are created.
  • multiprocessing = { patches = { pool = <bool>, process = <bool>, logging = <bool>} }:
    Toggles for which of the multiprocessing patches to apply.

  The child_processes table and its contents are as of yet considered private implementation details.

kernprof.py

• _add_core_parser_arguments():
  Now adding these flags to the parser:
  • --prof-child-procs[=...], --no-prof-child-procs:
    Whether to use the feature implemented in this PR; the default is read from [tool.line_profiler.kernprof]::prof-child-procs.
  • --debug-log=...:
    Undocumented (private) flag for writing out the LineProfilingCache debug logs.
• _write_preimports():
  Refactored to use the new/relocated facilities at line_profiler.curated_profiling.
• _dump_filtered_stats():
  • New argument extra_line_stats: LineStats | None allows for handling and combining the profiling stats gathered elsewhere (e.g. child processes).
  • Partially split off into the new _dump_filtered_line_stats() which it now calls.
• _manage_profiler:
  Context manager refactored from the old _pre_profile() for more Pythonic handling of setups and teardowns.
  • Added setup for the session cache via calling _prepare_child_profiling_cache().
  • The old function body is split off into smaller components (_prepare_profiler(), _prepare_exec_script()).
  • Now calling _post_profile() on context exit so that we no longer have to explicitly try: ... finally: ... in _main_profile().
• _post_profile():
  • New argument extra_line_stats: LineStats | None allows for handling and combining the profiling stats gathered elsewhere (e.g. child processes).
  • Simplified because some of the cleanup is relocated to line_profiler.curated_profiling.

tests/test_child_procs/test_child_procs.py

Mass-relocated code which isn't directly the test functions into other locations in the package (see New Code above). Plus the following changes (among others):

• /pool_test_module.py:
  Added the following command-line flags:
  • --start-method selects a specific multiprocessing "start method", including dummy which uses multiprocessing.dummy.
  • --local toggles between using a sum function defined locally in /pool_test_module.py or the one defined externally in /external_module.py.
  • --force-failure toggles whether the sum function should return normally or raise an error.
• /conftest.py::pool_test_module:
  Supersede the previous test_module.
  • Now a /_test_child_procs_utils.py::ModuleFixture, allowing for easy setup as a temporarily import-able module in the current and/or child processes (see above).
  • Now joined by pool_test_module_clone (same source code but separate module) and process_test_module (same CLI but different model of parallelism)
• /_test_child_procs_utils.py::_run_as_{script,module}():
  • Now joined by a _run_as_literal_code() to also test kernprof -c ....
  • Now taking test_module as a ModuleFixture instead of a path, and handling its installation.
• /_test_child_procs_utils.py::_run_test_module():
  • New convenience wrappers run_module = partial(_run_test_module, _run_as_module), etc. now available for more convenient testing of kernprof execution modes as test parametrization.
  • New parameters:
    • profiled_code_is_tempfile: bool helps with constructing the kernprof command line in cases where the code is anonymous (kernprof -c ...).
    • use_local_func: bool, fail: bool, and start_method: Literal['fork', 'forkserver', 'spawn'] | None allows for fuzzing code execution with the aforementioned test_module CLI flags (resp. --local, --force-failure, and --start-method).
    • nhits: dict[str, int] | None, when provided, checks that the line-hit stats are as expected (all calls traced with --prof-child-procs, only those in the main process without).
    • subproc: bool for toggling whether to run the test module in-process or in a subprocess.
  • Added checks:
    • If fail is true, the kernprof subprocess should fail.
    • Temporary .pth files created by kernprof --prof-child-procs should be cleaned up.
    • Profiling output is consistent with the provided nhits (where available).
    • If subproc is false, that certain warnings aren't issued (e.g. LineStats warning that we're trying to read profiling stats from an empty file), paralleling the checks in /test_child_procs.py::test_apply_mp_patches_{success,failure}().
  • Now retrieving the LineProfilingCache debug logs and printing them for debug purposes.
• /test_child_procs.py::test_multiproc_script_sanity_check():
  • Now also testing the new /process_test_module.py.
  • Now fuzzing the parametrizations use_local_func, fail, and start_method, to ensure that the test scripts are fully functional in vanilla Python.
  • Superseded the argument as_module: bool with run_func: Callable[..., CompletedProcess], allowing for more flexible testing of execution modes (python ..., python -m ..., and the new python -c added via the aforementioned _run_as_literal_code()).
• /test_child_procs.py::test_running_multiproc_script():
  New parametrization run_func allows for absorbing the old test_running_multiproc_module() into the same test as additional parametrization, as well as testing kernprof -c.

Caveats

• The temporary .pth file created is course benign and as mentioned tries to be as out of the way as possible, but I just figured that the use of .pth files should be called out, given their recent spotlight in a CVE vulnerability.
• Since the .pth file is written to a predetermined list of candidate locations (e.g. sys.get_path('purelib')), it depends on one of those directories being writable. If we aren't in a venv or a similarly isolated environment (which is increasingly unlikely nowadays), all processes using the same Python will have to import and run _line_profiler_hooks.load_pth_hook(). While the function itself should quit rather quickly when we're not in a child process, and without causing any of line_profiler to be loaded into sys.modules, it does still incur a certain overhead for interpreter boot-up.
• Prematurely terminating child processes (e.g. via multiprocessing.process.BaseProcess.terminate() and subprocess.Popen.kill()) circumvents the Python interpreter, and thus disrupts cleanup and can result in profiling-data loss/corruption.
• It is currently UB if the initializer argument to multiprocessing.pool.Pool and concurrent.futures.Executor causes a failure.

What didn't work

• Currently multiprocessing-managed child processes have the usual atexit hook which dumps profiling data disabled. On top of that the multiprocessing patch "pool" (~._child_process_profiling.multiprocessing_patches._profilling_patches.py::POOL_PATCH) also disables the dumping of profiling data at the end of multiprocessing.process.BaseProcess._bootstrap() patched in by the patch "process" ([...]::PROCESS_PATCH). This was the conclusion after much head-scratching, where processes terminated (presumably) in the middle of a LineStats.write() call results in corrupted/incomplete data.
• In theory one could've caught the SIGTERM that BaseProcess.terminate() sends to the child and only dumped the stats then and there (along with normal end-of-callback stats-dumping), which sounds much more efficient than dumping stats for every task submitted to a Pool. However:
  • Handling SIGTERM on Windows is generally noted to be inconsistent. See e.g. this coverage.control.Coverage._init_for_start() comment and this SO discussion that it refers to.
  • Even on POSIX platforms, signal handling in multiprocessing-managed children is known to be messy and causes occasional deadlocks; a lesson I found out way too late and after much wailing and gnashing of teeth. See e.g. Deadlock in multiprocessing.pool.Pool on terminate python/cpython#73945, Setting a signal handler gets multiprocessing.Pool stuck python/cpython#82408, and Process hang with Coverage 6.3 coveragepy/coveragepy#1310. Guess that's why coverage made their SIGTERM handler opt-in after originally having that on by default.
• All attempts at cross-process synchronization (e.g. setting up lock files so that child processes can signal to the parent that they are ready for whatever) turned out... badly. There seems to be a million way for things to go sideways in child processes, and I guess now I understand why multiprocessing.pool is so gung-ho in killing off worker processes and replacing them, without much regard of what actually went down down there.³

TODO

• Add documentation on this new feature, but I guess we should wait until we're happy with the feature and the code.
• Maybe we should indicate this feature to be experimental...
• Would it make more sense for any of the content in line_profiler._child_process_profiling to become public API?

Credits

• Loosely based on similar work I did for pytest-autoprofile, which in turn was based on the solution implemented in coverage.multiproc. And the longer I've worked on this, the more the similarities seem to have diminished ...
• Related PRs:
  • Prevent duplicate output in 3.14 #415 (from @Erotemic)
  • ENH: LineStats aggregation #380
  • FIX: kernprof to always run code in sys.modules['__main__']'s namespace #423

Notes

Welp. This took way longer than I expected. (EDIT: I think I wrote this sentence like two months ago.) The main friction points were that:

• There isn't a pre-existing "global-ish" state object that I can leverage, and which can be easily replicated in subprocesses. The new line_profiler._child_process_profiling.cache.LineProfilingCache class tackles this issue.
• I had a very hard time trying to make profiling results consistent even when the parallelly-executed function errors out. Would have thought that I already took care of that in the other project (see pytest-autoprofile::tests/test_subprocess.py::_test_inner()), but apparently I only made the tests fail there, not the parallel functions themselves. Figuring out how to do so consistently took the better part of these months.

Footnotes

1. Note however that the equivalent vanilla Python command (python -c ...) would error out, because functions sent to multiprocessing must be pickle-able and thus must reside in a physical file. This is sidestepped by kernprof's always writing code received by kernprof -c ... and ... | kernprof - to a tempfile (ENH: auto-profile stdin or literal snippets #338). ↩

2. In the test suite, process creation is tested both with the most common multiprocessing[.get_context(...)].Pool and with self-managed Process objects. Different patches to multiprocessing are responsible for profiling-data collection between the two situations, and they have been tested to work both (1) individually on their respective use-cases and (2) together without stepping on one another. See tests/test_child_procs/test_child_procs.py::test_profiling_multiproc_script_{success,failure}(). ↩

3. Since multiprocessing.pool.Pool-managed child processes ("workers") are regularly and wantonly terminated, which bypasses Python control flow and prevents e.g. atexit hooks from executing, we've taken to report profiling data from Pool workers on a per-task basis. ↩ ↩² ↩³

[TTsangSC]

Did some more tests on local post-#428-merge, maybe it is just legacy Python and dependency versions causing the issues. Will just rebase, force-push, and see what happens.

[TTsangSC]

Unfortunately there's too little context to determine why the tests are failing on other platforms. Heck I can't even replicate the macOS failures on my machine with matching dep versions. Just wrote in more code for extracting the debug outputs, force-pushed, and hopefully I will have more clues for what to work on.

[TTsangSC]

Added a ton of logging/debug messages, a few debug-only config options and a kernprof flag,¹ some unit tests of the individual components, but apparently two problems remain:

• tests/test_child_procs.py::test_apply_mp_patches(start_method='dummy') is failing out of the gate (on 3.10), because I assumed that the profiler would just catch the data from within the same process. Which it did on my machine, but I was on 3.14. Further tests revealed that it passes on 3.12+ but only when LINE_PROFILER_CORE="ctrace" is not set, indicating that there are some inconsistencies between how threading is handled between the legacy trace system and sys.monitoring.

  • Even weirder is that we kinda already have preexisting tests covering multithreaded cases (which use concurrent.futures.ThreadPoolExecutor, i.e. threading in the backend):

    • tests/test_complex_case.py::test_varied_complex_invocations() tests that kernprof runs the code and writes a profiling-stats file, but doesn't really test the content of said file. (We should probably update this test once the PR matures.)
    • tests/test_sys_trace.py::test_wrapping_thread_local_callbacks() mainly tests the use of trace callbacks, but also inadvertently the collection of profiling data across threads, because the target function calls one profiled function on the main thread and another on the worker thread, and we expect and test for profiling outputs from both.

  This begs the question, we already know from the 2nd that we can collect data from a worker thread in the same process, even before this PR – and consistently so between all our supposed EDIT: supported Python versions. So why is it different when multiprocessing.dummy (i.e. a wrapper around threading) is used?

• Particularly on Linux, the tests/test_child_procs.py::test_profiling_multiproc_script(preimports=False, start_method='forkserver') tests have been consistently failing for a few pushes. From the debug output, the issue is apparently that multiprocessing.spawn.prepare() in the child process isn't calling runpy.run_path(), which would've set profiling up. My guess is that we're somehow failing the check inside _fixup_main_from_path()... but that would imply that (1) the child processes are somehow inheriting sys.modules['__main__'] from the fork-server process from which they are forked, and (2) said fork-server process doesn't already have profiling set up. Neither of those seems to be true on MacOS when using forkserver so IDK what's happening. Maybe something to do with how the default start methods are different between the platforms...

Footnotes

1. Maybe I added a bit too much stuff and should tear some of that out when we're done debugging... ↩

[Erotemic]

WRT to the existing multithreaded case, IIRC the main point of that is just to ensure we don't hang. I could be misremembering.

For the forkserver issue, from what I understand that's a long lived process, so maybe some forkerserve state debugging (not sure if your code does this or not, I haven't looked at it yet)

def debug_forkserver_state(label):
    import os
    from multiprocessing import forkserver

    fs = forkserver._forkserver  # private CPython state
    pid = getattr(fs, "_forkserver_pid", None)

    # "Did *this process* already know about / launch a forkserver?"
    known_forkserver_pid = pid
    known_forkserver_started = pid is not None

    # "Was *this current process* itself started by a forkserver?"
    started_by_forkserver = forkserver.get_inherited_fds() is not None

    # Best-effort liveness check for the known forkserver PID, if any.
    # This is optional, and mostly useful in the parent/originating process.
    forkserver_pid_alive = None
    if pid is not None:
        try:
            os.kill(pid, 0)
        except OSError:
            forkserver_pid_alive = False
        else:
            forkserver_pid_alive = True

    print(
        f"[{label}] "
        f"pid={os.getpid()} ppid={os.getppid()} "
        f"known_forkserver_pid={known_forkserver_pid!r} "
        f"known_forkserver_started={known_forkserver_started} "
        f"forkserver_pid_alive={forkserver_pid_alive} "
        f"started_by_forkserver={started_by_forkserver}"
    )

And maybe also check if the main module attributes differ in any meaningful way?

getattr(sys.modules['__main__'].__spec__, 'name', None)
getattr(sys.modules['__main__'], '__file__', None)
multiprocessing.get_start_method()

But IDK, your guess is probably better than mine at this point.

[TTsangSC]

Thanks for the input! May have to take a closer look at the ForkServer object as you've suggested.

I have a piece of good news and a half:

• Apparently the first discrepancy is due to how LineProfiler.enable_count is managed – somehow (seriously IDK why) with legacy trace but not with sys.monitoring, the profiler starts out not being .enable()-d in the new thread.¹ I have yet to push the fix yet, but patching threading.Thread.__init__() iff we're using legacy trace so that the .enable_count in the new thread is synced seems to fix the bug.
• The discrepancy between my local tests and the CI for is apparently not platform issue but a Python version one – I'm on 3.13.3 while CI is on 3.13.13, and I managed to replicate the failing pattern in test_profiling_multiproc_script after brew upgrade python@3.13. Still scouring through the diffs to figure out what exactly changed between the versions... but at least I can test out the fix before pushing. That said, differing behavior between patch versions is a big red flag and a PITA to catch and fix...

Footnotes

1. Meanwhile the aforementioned test_wrapping_thread_local_callbacks consistently worked, because the profiled function is (1) explicitly wrapped by the profiler inside the concurrent workload, and (2) called through the wrapper the profiler. These factors ensured that the profiler was enabled from within the new threads. ↩

[TTsangSC]

Figured it out, the issue is that:

• Prior to gh-126631: fix pre-loading of __main__ python/cpython#135295 (merged since 3.13.8 and 3.14.1), the 'init_main_from_path' key from multiprocessing.spawn.get_preparation_data() was erroneously ignored by multiprocessing.forkserver.ForkServer.ensure_running() and not passed to multiprocessing.forkserver.main().
• The side effect was that:
  • The fork-server process was started without calling multiprocessing.spawn.import_main_path(), and thus child worker processes forked therefrom started out without a sys.modules['__main__'].
  • This in turn means that when the child processes run multiprocessing.spawn.prepare(), they had to set __main__ up via runpy.run_path() themselves, thus running the code which sets up the rewrite-based profiling (like line_profiler.autoprofile.autoprofile.run()).
• Meanwhile, post-135925 said __main__ setup has been done in the fork-server process itself. However, since the fork-server process is neither our main process or a child worker process, the setup code path is different and doesn't involve patching multiprocessing.runpy.run_path(), and hence no rewriting is done.

I think the bug is fixed (will push shortly), but I've noticed significant performance regression (about 100% slowdown of test_profiling_multiproc_script()) between up-to-date patch versions of Python 3.13 and 14 and older ones. Gotta try to iron that out...

[TTsangSC]

Tests seem flaky... there is no good reason that 6e60a6a failed on building for 3.12 ARM manylinux while d2203a0 succeeded.

[codecov]

Codecov Report

❌ Patch coverage is 84.31138% with 262 lines in your changes missing coverage. Please review.
✅ Project coverage is 85.66%. Comparing base (b5ca752) to head (068e8a8).
⚠️ Report is 1 commits behind head on main.

Files with missing lines	Patch %	Lines
line_profiler/_child_process_profiling/cache.py	79.73%	65 Missing and 26 partials ⚠️
...ling/multiprocessing_patches/_mandatory_patches.py	66.15%	41 Missing and 3 partials ⚠️
line_profiler/curated_profiling.py	71.28%	20 Missing and 9 partials ⚠️
...cess_profiling/multiprocessing_patches/__init__.py	71.18%	12 Missing and 5 partials ⚠️
...hild_process_profiling/_patching_infrastructure.py	90.51%	7 Missing and 4 partials ⚠️
line_profiler/line_profiler.py	83.58%	9 Missing and 2 partials ⚠️
...ling/multiprocessing_patches/_profiling_patches.py	83.87%	10 Missing ⚠️
...rofiler/_child_process_profiling/_cache_logging.py	95.12%	5 Missing and 3 partials ⚠️
line_profiler/_threading_patches.py	80.00%	7 Missing and 1 partial ⚠️
...ess_profiling/multiprocessing_patches/mp_config.py	78.12%	7 Missing ⚠️
... and 6 more

Additional details and impacted files

@@            Coverage Diff             @@
##             main     #431      +/-   ##
==========================================
+ Coverage   84.95%   85.66%   +0.71%     
==========================================
  Files          21       36      +15     
  Lines        2412     4075    +1663     
  Branches      376      554     +178     
==========================================
+ Hits         2049     3491    +1442     
- Misses        263      424     +161     
- Partials      100      160      +60     

Files with missing lines	Coverage Δ
...rofiler/_child_process_profiling/_retrieve_pids.py	100.00% <100.00%> (ø)
...iling/multiprocessing_patches/_optional_patches.py	100.00% <100.00%> (ø)
line_profiler/toml_config.py	91.17% <50.00%> (-1.31%)	⬇️
line_profiler/line_profiler_utils.py	96.12% <96.34%> (+0.07%)	⬆️
...ing/multiprocessing_patches/_pool_patch_helpers.py	91.52% <91.52%> (ø)
...rocess_profiling/multiprocessing_patches/_queue.py	91.22% <91.22%> (ø)
...profiler/_child_process_profiling/runpy_patches.py	91.52% <91.52%> (ø)
line_profiler/cleanup.py	95.58% <95.58%> (ø)
...ess_profiling/multiprocessing_patches/mp_config.py	78.12% <78.12%> (ø)
...rofiler/_child_process_profiling/_cache_logging.py	95.12% <95.12%> (ø)
... and 8 more

... and 7 files with indirect coverage changes

---

Continue to review full report in Codecov by Harness.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 2ef5262...068e8a8. Read the comment docs.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[TTsangSC]

Hi @Erotemic, I think this is ready for review if you have the time... sorry for the metric ton of code.

[Erotemic]

It will take me a while to fully go through this, but here is a start.

[Erotemic]

Note, because we use xdoctest, you should be able to put # doctest: +NORMALIZE_WHITESPACE as a standalone comment above the code for it to apply to every line after. Although I don't often use NORMALIZE_WHITESPACE, so I can't say I'm 100% confident in that.

[Erotemic]

This has the potential to cause some import overhead. IIUC, we are going to effectively import the entire line_profiler.init. I'm not sure if that's going to be noticeable or not. One idea is to make a separate _line_profiler_hooks package that's just a minimal top level module for very fast import, but that may be overengineering. I'd need to think about it and probably test it.

[TTsangSC]

One data point on my machine, though I think other platforms are most likely gonna behave the same: importing line_profiler._child_process_profiling.pth_hook causes the following to be imported:

• All top-level line_profiler submodules except the following:
  • ~.cleanup
  • ~.curated_profiling
  • ~._threading_patches
  • ~.ipython_extension
• None of the line_profiler.autoprofile components, and
• None of the line_profiler._child_process_profiling components except ~~.pth_hook itself.

So, as one would intuit, most of the "core" stuff directly used by line_profiler.LineProfiler and @line_profiler.profile. Could be worthwhile to set it up as a separate namespace... and it should be trivial to configure, given that we already create two separate namespaces (line_profiler and kernprof).

The remaining question is more of a design one: should write_pth_hook() stay in said namespace for symmetry with load_pth_hook(), or should it become an instance method of LineProfilingCache's?

[Erotemic]

Maybe on_defective='warn' makes more sense here?

[TTsangSC]

Could be. The original motivation is that:

• Since the ._setup_in_child_process() code is run in all child processes at startup incl. unused worker processes and the fork-server process, each such process occupies and secures a tempfile name (*.lprof) by touching it. Said tempfile is supposed to be written to when the corresponding Python process terminates.
• But then some of these files could result in errors upon reading: processes killed via signals before cleanup is run result in empty tempfiles, and those killed mid-cleanup make for corrupted ones.
• I opted to suppress the error/warning messages given that they originate directly from pickle and are thus not the most intuitive/helpful.

But maybe that's just indication that we should've vet the input files better before passing them onto pickle. And given that the rest of the PR has seen a lot of iteration after these lines were first written, we should probably get a lot fewer false alarms from the warnings, and where we do have something to warn it will be of actual problematic cases (e.g. unclean exits resulting in incomplete data).

[Erotemic]

Do these need to be nested functions? Would a helper class make more sense than relying on closures / be more testable?

Do we have a test for a worker that does some non trivial processing and then intentionally terminates so we can have an explicit comparison between the unpatched and patched terminate and make sure they both behave similar enough?

[TTsangSC]

Yeah I should probably refactor wrap_terminate() for readability. We've barely used closure variables in the nested funcs anyway (just cache in process_has_returned()); still, that can be easily remedied, given that I can just pass cache to the function in the _Poller.poll_until() constructor.

We do test Process.terminate() as shown in the coverage report, albeit indirectly:

• In normal ("happy-path") code execution Process.terminate() isn't even called – AFAIK it only happens when the parallel workload errored out, which for whatever reason may leave the child process stuck "in limbo", where e.g. atexit cleanup callbacks may or may not be executed, or be in various stages thereof.
• Such children are .terminate()-d as a part of finalization of the parent Pool (see Pool.__init__() and .terminate()), which in particular does not wait for child-process cleanup, thus necessitating the patch.
• In order to test this we have tests¹ where the parallel workload can be "set up for failure". Those are where the coverage on wrap_terminate() comes from. A quick check is how running the test suite with -k "test_child and success" only gives 52% coverage on multiprocessing_patches.py while -k "test_child and failure" gives 72%.

Given that the existing code do call vanilla_impl() in a finally clause, it is probably the closest we can get to the unpatched behavior in that we (1) do eventually send the SIGTERM, and (2) before that, give child processes (as far as possible – which isn't 100% of the time, hence the necessity of the timeout) the required grace to run cleanup and write profiling data. Anyhow, maybe we can look into tests where we explicitly create a Process object and later .terminate() it, if that would be more assuring.

Footnotes

1. Granted, we just sum over consecutive integers in those tests. They have the benefit that the workload size corresponds directly to the num-hits on the loop line, and hence we can keep track of whether the gathered profiling data are complete. If that's too trivial maybe we can do Fibonacci or something instead. ↩

[Erotemic]

unused argument.

[TTsangSC]

Thanks, good catch!

[Erotemic]

Why is a retry necessary here? Is there something non deterministic going on? Any chance we are hiding a race condition? Similar question with other pytest.mark.retry marked tests.

[TTsangSC]

The short answer

Yes, workers with failing workload ends up in limbo sometimes, as mentioned in the other comment. It should theoretically be possible to drop the retry on POSIX (and even the whole wrap_terminate() deal) because of the use of SIGTERM handlers, but the consensus seems to be that signal handling is busted on Windows, so we still need the timeout which is by nature flaky.

The long answer

• Again, processes receiving parallel workloads which don't error out seem to always exit cleanly and never need to be .terminate()-d. Those which don't... don't. Which sets up the potential race condition: the failing child could be cleaning up, stuck in limbo (possibly waiting for communication from the parent?), or whatever; meanwhile the parent don't really care either way, because it already received all the results (i.e. pickled return-value objects or exceptions) from the children, and is ready to .terminate() whichever child process that remain alive.
• In earlier iterations of the PR I just set each child process up to manage a lock file, and had the parent process wait without a timeout for said file before sending the SIGTERM (which is essentially the only thing that the vanilla Process.terminate() does). Which then caused the tests to sometimes hang indefinitely, meaning that in some failing child processes we never naturally got to the point where the finally: cache.cleanup() clause is executed. Unfortunately such failure also seems to be nondeterministic, at least at a cursory glance.
• Hence the timeout. Which did alleviate the issue in that we do get all of the profiling data most of the time – because the parent process no longer willy-nilly kills the children, at least until the timeout expires. This handles cases where the child process is healthy enough to actually attempt cleanup, but would have been prevented from doing so by the parent's .terminate()-ing it.
• But then of course there are still corner cases for when the children is FUBAR – and I think it can be argued that those cases are what the Process.terminate() method is for in the first place. Like, in a perfect would the child process would've just executed its atexit hooks and exited non-zero, right after raising the error and pushing it to the communication queue with the parent. But obviously that doesn't always happen. In those cases anything goes... hence the retries.

Notably, coverage also seems to be having trouble with consistently handling data collection when child processes are .terminate()-d, and just gives up while on Windows:

@pytest.mark.skipif(env.WINDOWS, reason="SIGTERM doesn't work the same on Windows")
@pytest.mark.flaky(max_runs=3)  # Sometimes a test fails due to inherent randomness. Try more times.
class SigtermTest(CoverageTest):

What do we do?

I didn't like having to retry either – but here we are. But maybe we can at least refactor and separate the tests, so that we make sure that the mark is only applied to cases where it might be needed/justified (i.e. tests with failing parallel workloads and on Windows).

That or we just skip (as coverage does) or XFAIL on Windows.

[TTsangSC]

I have a new idea for improving determinism in profiling multiprocessing stuff.

• The main culprit for failure in profiling child processes is that:
  • While by wrapping Process._bootstrap() we are "guaranteed" on Python level that cleanup will occur after the parallel workload exits, it is important to note that the processes created by Pool doesn't directly have the callables we sent to the pool (via e.g. .map(), .starmap(), or .apply()) as their workloads. Instead their workload is the multiprocessing.pool.worker() function, which fetches tasks (i.e. our callables and their arguments) from an inqueue and pushes the results (either the return values of the parallel workloads or the errors they raised) back into an outqueue.
  • The Pool object in the main process communicates with the children via said queues, and sees it fit to (OS-level) terminate them as long as all the results have been collected – even if the workload (i.e. worker()) hasn't exited per-se.
• To maintain Python-level control, we must write profiling results on the task level, before the result is handed back to the pool. This can be achieved via patching the methods where tasks are pushed onto the queues, slipping in calls to LineProfilingCache.load().profiler.dump_stats() – namely Pool._get_tasks() and Pool._guarded_task_generation().
• Unfortunately everything that needs to be communicated between processes has to be pickle-able, meaning that we can't simply create wrapper functions around the original callable. Still, if we wrote a helper class which does the wrapping on its .__call__() method it should be workable.

However, this strat does have complications:

• Generally we have one profiler instance (LineProfilingCache.load().profiler) per child process. Since each process can handle multiple tasks, we must be careful against double-counting profiling data. Maintaining a single per-process filename handle to which profiling data is written and overwritten may be a solution. That or we reset the profiler after every task, but we haven't merged feat: Add reset_stats method to LineProfiler for resetting accumulated profiling data #322 yet.
• This works fine and all with Pool-based parallelism, but fails if one sidestepped the Pool and otherwise managed their own Processes. Maybe we can have a switch somewhere for choosing whether to patch Pool or Process (or both, but we'll have to make sure the patches don't clash and cause double-counting), like how coverage allows for configuring which patch(es) to apply.

[TTsangSC]

As it is now, the code (at least on non-Windows platforms) already reliably and deterministically captures all profiling data related to tasks set to the child processes. If the child process gets to execute any task at all, it must have gone through setup which allows for the capturing of profiling data.

What however is more difficult to handle consistently, and is causing most of the recent pipeline failures (other than 25785347402, which was entirely on me), is what happens with child processes which terminates without ever having received a task.¹ While currently the SIGTERM handler (which ensures that the profiling stats are written before the child process kicks the bucket) is set up rather early (at the start of multiprocessing.pool.worker() or multiprocessing.process.BaseProcess._bootstrap()), it is apparently not always early enough, as shown by the tests failing on the account of the empty-prof-stats-file warnings.²

Such failure calls into question:

• Can any child-process setup be guaranteed to happen early enough that we can ensure the writing of profiling data before the parent process can terminate it? (Probably not.)
• Is more bookkeeping the only option (e.g. having each child report the number of parallel tasks executed, and special-casing those that didn't report any)?
• Is that even a worthwhile pursuit, given that more bookkeeping = more overhead? Should we just accept the occasional empty-file warnings as long as any actual workload executed can be profiled?

Footnotes

1. This seems to only happens when a task fails (e.g. in the test_*_failure() tests), but that may also be an artifact of our setup (which creates exactly as many tasks as there are child processes). ↩

2. I must note that the code has been extensively tested on local without failing like this, albeit without pytest-cov. It seems that the overhead of setting up coverage however delayed the setting up of the SIGTERM handler in child processes, hence preventing the profiling data (or the lack thereof) from being written. So it is indeed a race condition... between the parent and child processes that is. ↩

[TTsangSC]

Added the PID bookkeeping, but there seems to be an unrelated Heisenbug which I'm struggling to pin down. Every ≈ 1000–2000 runs of test_apply_mp_patches_failure() with start_method=fork or forkserver on my local would lock up and fail... and the bug vanishes when I also apply the logging patch to tee the multiprocessing internal logs. So much for determinism... 🤦‍♂️

The newest pipeline failures are semi-related:

• Job 76436927210 failed on test_child_procs.py::test_profiling_multiproc_script_failure[2000-3-run_func0-script-True-with-child-prof-fork-False-no-preimports-False-external] – makes sense, since this is just the integration-test and isolated-in-its-own-subprocess version of test_apply_mp_patches_failure().
• Job 76436927202 failed on test_child_procs.py::test_apply_mp_patches_failure[100-2-False-True-process-only-spawn], but that was because the poller we use for Pool.terminate() on Windows timed out, and I forgot that pytest.raises() would catch the timeout but fail it with an AssertionError because of mismatching error messages. Guess that I'll just use an explicit try-except to fish for the specific RuntimeError I want.

[TTsangSC]

@Erotemic yikes, unfortunately job 76507649976 seems to have gotten stuck despite multiple precautions (timeouts for dubious sections, hundreds/thousands of rounds of local tests)... worse, its the Mac job that's stuck (which I suppose is the most expensive on CI), despite that being the most thoroughly tested env, since it's also my local.

I don't have the perms to cancel the job; please do so ASAP before it continues to rack up compute.

Terribly sorry for this.

[Erotemic]

Yikes! Just saw the message. I don't see an immediate way to cancel it. Maybe it timed out and it just looks like it is churning? It does say: "The job has exceeded the maximum execution time of 6h0m0s", and in this PR I see: Cancelled after 365m. So I think it is not running.

[TTsangSC]

Yep, I think Actions have a default 6 h limit (not sure if it's the entire pipeline or individual jobs) on GitHub. This happened on Monday so said default timeout expired a while before intervention... it may not be ideal, but we can probably put in loose-ish timeouts for build_and_test_sdist, build_binpy_wheels, and test_binpy_wheels, like maybe 1 h for build_binpy_wheels and 10 m for the others.

For the (probably¹) offending test test_apply_mp_patches_failure(), unfortunately I'm still struggling to replicate the failure – not even the hanging part, and much less how it hanged despite the critical part's being supposedly isolated in a thread on a timer. (Doesn't exactly inspire confidence for the PR I know...) Before I apparently "fixed" similar failures on local (and thus felt confident enough to push after much testing), the logs seemed to be stuck after the call to Process.terminate() before resuming after the timeout expired. My guess is that Process.join() hung, but that must have meant that Process.terminate() somehow failed to nail the processes. But beyond that IDK.

We can probably mitigate this by folding the cases tested by test_apply_mp_patches_*() back into test_multiproc_script_sanity_check() so that we're "protected" by the kernprof subprocess, but of course (1) we're not supposed to have to do that, (2) we lose granularity and coverage by not running the patched code in-process, and (3) more subprocess-based tests means more overhead... but any such overhead is probably minimal compared to spending 6 h stuck in limbo. (Again, very sorry.)

Footnotes

1. Because the stuck job wasn't on pytest --verbose and pytest output is kinda line-buffered, the test where we were stuck could've been any of the latter ones in tests/test_child_procs.py. But that one is the most suspicious because the kernprof ones use subprocess.run(timeout=...) instead of my jury-rigged thread-based timeout solution, which is probably more robust. ↩

[TTsangSC]

When trying to sniff around and trigger and fix the bug I ran into an even weirder issue.

• In principle, the @_timeout decorator does nothing other than to run the function on a new (daemon) thread, pickle and return/raise the result if it finished execution without the time limit, and just raise a timeout error otherwise.
• Moving said decorator out from the function using multiprocessing to the entire test function, the first subtest passes while the following mostly fails, on account of the profiling stats being inconsistent.
• Interestingly, the failure patterns seem to be that the stats are:
  • Correctly collected in child threads and/or processes when using multiprocessing.dummy (i.e. threads) or the start methods forkserver or spawn, but
  • Not collected when using the start method fork, and
  • Not collected in the "current" thread on which the test function is run.

This seems to indicate something being wrong when profiling starts on a non-main thread; in view of that, how start_method='fork' completely falls apart kinda makes sense, given Python's warnings on mixing process forking and multithreading. But then this still doesn't explain why we're losing stats on the current thread from the second subtest onwards. There's possibly some pollution in thread-local states which I'll have to diagnose...

[TTsangSC]

Sorry for the lack of update. Was a bit shellshocked after the last blunder and held off on making pushes until I can diagnose what happened and better reproduce the sporadic hanging bug...

... in which however I am not quite successful. It still only shows up every ≈1000 tests or so, and apparently according to the logs, that is due to the signal handler's somehow not firing on one of the child processes; still trying to figure out how that is at all possible. Still I've made some further changes:

• Added workflow-level timeouts to all the test jobs to avert the worse-case scenario of something being stuck for six hours.
• Fixed a bug in LineProfilingCache which causes global-state pollution after kernprof.main() has been called.
• Updated tests/test_child_procs.py::test_profiling_multiproc_{success,failure}() so that most of the subtests are run with kernprof.main() in-process.

If it isn't as safe and deterministic to temper with signal handling as I've initially hoped, we may just have to report profiling stats more granularly like on Windows, where each multiproc pool task prompts the child process to write the profiling stats to its assigned file. Since one of the patches already patches task/result queues to send the child-process identity back to the parent alongside the task result, it should be easy (though with overhead) to also slip the collected stats in. Will see if that helps.

Oh and looks like I broke something else completely related... not a good sign. The lint-job failure seems unrelated though, it was on line_profiler/autoprofile/profmod_extractor.py and I didn't touch that file. Seems an artifact of our not pinning the ty version – on 0.0.31 it still type-checked and now on 0.0.46 it doesn't. Will fix both either way.

[TTsangSC]

Still working on this on-and-off, but I'm unfortunately still stuck with flaky tests... seems that there's something which makes SIGTERM handling inherently unreliable in multiprocessing child processes, causing them to randomly hang (see python/cpython#73945, python/cpython#82408, and coveragepy/coveragepy#1310).

Unfortunately this means that there's no guarantee for profiling output when a child process is BaseProcess.terminate()-ed, since an unhandled SIGTERM breaks the Python runtime (try-finally clauses, atexit hooks, etc.). Seems that the only workaround is to avoid having children terminated at all, will look more into that.

[Erotemic]

I started looking at this again, with the help of GPT 5.6 and the complexity of this feature and the number of subtle ways things can go wrong make me nervous.

The full GPT review is here:

Details

Deep review: PR #431 — child-process profiling

Reviewed snapshot: 0156dab4024ad54d2076f2fe1af898d144582618
Comparison base: d0878e74d3990c68c96a75fbf7ded1b0230b91eb

Verdict

Request changes.

The overall architecture is plausible, and the test matrix is much better than it was during the original review. I do not think the PR needs to be abandoned or redesigned from scratch.

However, I found three issues I consider merge blockers:

1. Pool profiling has a real synchronization race that can silently discard valid child profiling data.
2. Eager preimports run arbitrary user modules inside multiprocessing infrastructure processes, including the resource tracker and forkserver.
3. The legacy-threading compatibility patch changes ordinary kernprof behavior outside --prof-child-procs, and its semantics are incorrect for delayed thread starts and Thread subclasses.

I also found a broader failure-containment problem: several profiler-internal failures can change the behavior of the program being profiled instead of degrading to missing profiling data.

---

Blockers

1. Pool-worker stats can be silently lost due to a result-handler/finalizer race

Relevant code

line_profiler/_child_process_profiling/multiprocessing_patches/_profiling_patches.py:

• _report_stats_and_dest() at roughly lines 85–132 sends the worker's cumulative LineStats back with each task result.
• _record_stats() at roughly lines 135–149 records the most recently received snapshot in the parent.
• _write_recorded_stats() at roughly lines 152–177 writes that recorded snapshot when the worker is finalized.

_pool_patch_helpers.py runs worker finalization from patches around:

• Pool._terminate_pool
• Pool._join_exited_workers

Those operate independently of the result-handler thread which calls _record_stats().

The race

A worker can:

1. finish a task,
2. enqueue (profiling_stats, task_result),
3. exit,
4. be observed and finalized by the worker-handler thread,
5. have _write_recorded_stats() run,
6. before the result-handler thread consumes the queued final result and calls _record_stats().

The finalizer consequently writes either an older cumulative snapshot or nothing.

Later, the result-handler receives the final profiling snapshot and stores it in _get_worker_stats(cache), but that worker has already disappeared from the pool. Nothing necessarily comes back and writes the newly received snapshot to disk.

There is an additional interaction with the PID-accounting patch: if worker finalization also beats receipt of the PID-tagged result, the worker can be classified as having run zero tasks. Its empty output file is then treated as an expected empty file. The loss can therefore occur without even emitting a warning.

Reproduction

I forced the result-handler to pause for one second and used:

Pool(1, maxtasksperchild=1)

with one profiled task.

Without the delay:

Line 14    Hits 1    y = x + 1
Line 15    Hits 1    return y

With the delayed result handler:

Line 14    Hits 0    y = x + 1
Line 15    Hits 0    return y

The actual multiprocessing result was still returned correctly:

[2]

There was no profiling warning.

So this is not theoretical and does not depend on worker crashes.

Why existing tests miss it

The exact-hit-count tests are good, but they rely on normal scheduler ordering. They do not force worker reaping to happen before result consumption, and I found no maxtasksperchild coverage in tests/test_child_procs.

Recommended correction

The durable source of truth cannot be a callback that runs only when the worker object is finalized.

One straightforward design is:

• Keep the newest snapshot keyed by its output path.
• Do not permanently discard it when a worker is finalized.
• At session/cache cleanup, flush every outstanding latest snapshot regardless of whether the corresponding BaseProcess object is still present.

Alternatively, write/replace the output file when each _record_stats() message is received. That is simpler semantically, though it restores per-task filesystem I/O.

Whichever solution is chosen, add a deterministic test which delays result handling and uses maxtasksperchild=1.

Severity: blocker.

---

2. User profiling targets are imported inside resource_tracker and forkserver infrastructure processes

Relevant code

LineProfilingCache._setup_in_child_process() in cache.py, roughly lines 764–809, does:

1. install a CuratedProfilerContext,
2. execute self.preimports_module,
3. allocate the stats file,
4. apply the multiprocessing patches.

In particular:

if self.preimports_module:
    ...
    exec(code, {})

occurs around lines 776–782.

But resource-tracker recognition happens later, in _mandatory_patches.py::wrap_main() around lines 222–262.

That wrapper explicitly says:

reason = 'resource-tracker server process not to be profiled'

and tears profiling back down.

The problem is that by then the arbitrary user preimports have already executed.

The forkserver similarly executes the preimports while establishing its inherited profiling machinery.

Reproduction

I profiled a module whose import simply logged:

• PID
• PPID
• sys.argv

then launched one process using the forkserver start method.

The module was imported three times:

1. the normal profiling/main process,
2. the multiprocessing resource tracker,
3. the multiprocessing forkserver.

The debug log explicitly showed the resource-tracker PID:

Setting up (pth)...
Loading preimports...
...
Starting cleanup
(resource-tracker server process not to be profiled ...)

The forkserver also logged:

Setting up (pth)...
Loading preimports...

before it forked the actual worker.

Why this matters

--preimports defaults to true.

These are arbitrary user modules. Importing one can:

• initialize CUDA/OpenMP/native runtimes,
• start threads,
• establish connections,
• mutate global/environmental state,
• install signal handlers,
• allocate shared resources,
• perform registrations or filesystem operations.

Doing that inside the forkserver is particularly problematic. A major reason to use a forkserver is to fork workers from a controlled server process. Importing user profiling targets there can give that server threads or native runtime state that should not be inherited through fork().

The resource tracker has even less reason to execute user profiling targets; the code already recognizes that it is not supposed to contribute profiling data.

Recommended correction

Child-process setup should be split into two phases:

Infrastructure setup

• load the session metadata,
• install only the monkeypatches necessary to propagate profiling,
• identify the process role.

Actual profiling-target setup

• instantiate/configure the profiler,
• perform eager preimports,
• allocate a stats file.

Resource tracker: infrastructure only, no user imports.

Forkserver: ideally infrastructure only. Complete target/profiler setup in the actual worker after it has been forked, e.g. from the BaseProcess._bootstrap boundary that is already patched.

This is cleaner than trying to allow a full profiler setup and then undoing it once resource_tracker.main() happens.

Add a regression module with an import side effect and assert that neither the resource tracker nor forkserver appears in its import log.

Severity: blocker.

---

3. Legacy thread propagation captures state at Thread.__init__, not when the thread starts

Relevant code

line_profiler/_threading_patches.py.

make_thread_init_wrapper() captures:

enable_count = prof.enable_count

during Thread(...) construction and, only if it is nonzero, replaces the supplied target with a wrapper carrying that fixed count.

This patch is installed by CuratedProfilerContext.install() for every LineProfiler using the legacy backend.

Critically, this is not gated by --prof-child-procs.

On Python <3.12, legacy tracing is the default. It can also be selected explicitly on newer versions with:

LINE_PROFILER_CORE=ctrace

Concrete incorrect behavior

Case A:

prof.enable_by_count()
t = threading.Thread(target=target)
prof.disable_by_count()
t.start()

The parent profiler is inactive when the thread actually starts.

The child nevertheless sees:

enable_count == 1

because the state was captured when Thread was constructed.

Conversely:

t = threading.Thread(target=target)
prof.enable_by_count()
t.start()

The thread sees:

enable_count == 0

even though profiling is active in the spawning thread at start() time.

I reproduced both.

Thread subclasses are also missed

This common form:

class Worker(threading.Thread):
    def run(self):
        ...

constructs a Thread with target=None.

The current patch therefore installs no wrapper at all.

I reproduced that as well: with the parent profiler enabled, the subclass's run() starts with child-thread enable_count == 0.

Scope of regression

CuratedProfilerContext.install() calls apply_threading_patches() unconditionally for a LineProfiler.

So this PR changes ordinary legacy kernprof threading behavior even when the user never asks for child-process profiling.

Recommended correction

The state transfer should occur at the start/execution boundary, not construction.

For example:

• At Thread.start(), record the spawning thread's current enable_count on the Thread object.
• Arrange for that value to be installed in the new thread immediately before its run() executes, and restored afterward.
• Ensure subclassed run() implementations participate as well.

The implementation mechanism may require wrapping start() plus an execution boundary rather than only wrapping the constructor's target.

Tests should include:

1. construct inactive → enable → start,
2. construct enabled → disable → start,
3. Thread subclass overriding run(),
4. a Thread constructed in one thread and started from another.

Severity: blocker, especially because it affects non-child-process profiling on supported Python 3.10/3.11.

---

Major failure-containment issue

4. Profiling setup/reporting failures can alter or hang the user program

There is a good fail-open principle in parts of this PR. _line_profiler_hooks.load_pth_hook(), for example, catches child setup errors and says:

this process runs unprofiled

But several lower-level paths do not actually provide that guarantee.

4a. Child setup is not transactional

_setup_in_child_process():

1. stores self.profiler,
2. installs CuratedProfilerContext,
3. mutates builtins, the global profiler, and possibly threading,
4. then executes preimports,
5. then allocates files and applies multiprocessing patches.

If step 4 or later raises, _line_profiler_hooks catches the exception, but it does not roll back the partial setup.

I reproduced this by removing the generated preimports file immediately before starting a Python child.

The startup hook reported:

line_profiler child-process profiling setup failed ...
this process runs unprofiled

Yet inside that supposedly unprofiled process:

CHILD_BUILTIN_PROFILE True
CHILD_THREAD_PATCHED True

So the process was left with line_profiler's global mutations installed.

The cache is also left with self.profiler is not None, meaning another _setup_in_child_process() call will decide that setup has already occurred.

This should be transaction-like: failed setup needs to unwind every mutation performed before the failure.

4b. The direct os.fork() wrapper does not fail open

cache.py::_wrap_os_fork() around lines 846–881 calls:

forked._setup_in_child_process(...)

without containment.

I reproduced a missing-preimports failure across a raw os.fork().

Instead of os.fork() returning normally in the child, the child got:

FORK_ERROR ... FileNotFoundError ...

The parent saw the child exit normally only because the test script explicitly caught that exception.

Profiling machinery should not turn a valid fork() into an exception in the user's child path.

4c. Pool statistics collection can suppress the user's task result

PutWrapper.put() currently does:

data = self._callback()
...
self._queue.put(obj)

So successful delivery of the user's multiprocessing result depends on successful execution of the profiler callback.

I injected a failure into _StatsHelper.get().

The user's task itself succeeded, but instead of obtaining its result:

RESULT_ERROR TimeoutError

The pool worker traceback showed:

RuntimeError: synthetic stats failure

while trying to execute _report_stats_and_dest() before writing the user's result.

The worker then attempted multiprocessing's normal error-reporting path, but that second result also went through the same PutWrapper, called the failing profiler callback again, and failed again.

The result was lost and the caller timed out.

Required invariant

A profiler failure should preferably produce:

• a warning,
• loss of some profiling data,

but not:

• a changed return value,
• a new user-code exception,
• a dead pool,
• a hung AsyncResult,
• a failed fork().

The PR already follows this rule in some places; it should be made systematic at every injected hook.

Severity: major; I would fix this before merge rather than leave it as experimental risk.

---

Other correctness issues

5. LineStats.from_files(..., on_defective=...) does not implement its stated contract

line_profiler/line_profiler.py, roughly lines 490–574.

The docstring says on_defective='warn' or 'ignore' applies when a file otherwise fails to load.

However:

with open(file, 'rb') as f:
    try:
        ...

places open() outside the exception handler.

Reproduction:

LineStats.from_files('/missing', on_defective='ignore')

raises FileNotFoundError.

So does:

on_defective='warn'

There is a second case: a valid pickle containing the wrong object type gets through pickle.load(), is appended to stats_objs, and later fails during aggregation:

AttributeError: 'dict' object has no attribute 'timings'

again despite on_defective='ignore' or 'warn'.

This matters to the child-profile aggregator because files are generated and consumed concurrently with process teardown. The API should treat all unusable inputs consistently.

Severity: should fix.

---

6. --output-interval excludes all child-process data until final shutdown

Periodic output remains:

RepeatedTimer(..., prof.dump_stats, options.outfile)

at kernprof.py around lines 1257–1260.

prof is only the main-process profiler.

Child stats are gathered only from _gather_child_prof_stats() during _manage_profiler.__exit__() around lines 1153–1160.

I tested this with a completed child task and a still-open pool.

After the periodic writer had run:

MIDRUN_CHILD_HITS 0

After the profiling session terminated and performed the final gather:

FINAL_CHILD_HITS 2

So --output-interval, documented as writing cumulative profiling results, is no longer actually cumulative with respect to --prof-child-procs.

This is especially relevant if --output-interval is being used as crash protection for a long-running job: child statistics held in parent memory are not preserved by the periodic snapshots.

Either incorporate currently received child snapshots into periodic output or explicitly make the option combination unsupported/documented.

Severity: should fix or explicitly document before calling the feature complete.

---

Architecture/maintenance observations

These are not blockers on their own.

The .pth startup design is much better than it was in May

Moving startup handling to the lean top-level _line_profiler_hooks.py resolves the import-overhead concern from my original review reasonably well. Nonparticipating interpreters do little more than import the small hook and inspect an environment variable.

I would keep this direction.

The new pool protocol is a substantial improvement over delaying Process.terminate()

Removing the old polling/timeouts/retries/signal-handling mechanism was the right move.

Sending profiling state through an existing pool result path is a better foundation. The race above is fixable without discarding that architecture.

Exact fork attribution is well tested

I ran:

tests/test_child_procs/test_fork_stats_attribution.py
tests/test_child_procs/test_pool_protocol.py

and got:

16 passed

The pre-fork-baseline subtraction design looks coherent.

I also ran the abnormal-execution tests that do not require constructing a new online virtualenv:

6 passed

A longer run through test_child_procs.py got through roughly the first hundred parametrized cases without a failure before the local review timeout.

The remaining local fresh-venv cases could not run because this sandbox cannot download their build dependencies. That is an environment limitation, not evidence against the PR.

git diff --check and compileall are clean.

There is a lot of CPython-private surface

The implementation currently depends on, among other things:

• BaseProcess._bootstrap
• Pool._handle_results
• Pool._terminate_pool
• Pool._join_exited_workers
• forkserver._forkserver
• ForkServer._stop()
• multiprocessing.spawn.runpy
• resource_tracker.main

For this particular feature, some use of internals is probably unavoidable. The broad 3.10–3.14 test matrix makes this an acceptable experimental maintenance cost.

I would not block the PR merely for using these APIs.

But each private boundary should have a fairly direct behavioral regression test, because the April history already demonstrated that CPython patch-level changes can break assumptions here.

Full cumulative LineStats on every pool task may become expensive

Every pool result transports the entire cumulative stats object for that worker.

In a small local test with 500 spawn tasks and a 122-line profiled function, wall time went from about:

1.48 s

without child profiling to:

3.53 s

with child profiling.

A large fraction is naturally the cost of line profiling itself, so this benchmark does not prove the full-snapshot protocol is the dominant overhead. I would therefore not block on it.

But the transport cost scales with:

number of tasks × accumulated profile surface

rather than the amount of new profiling information. A benchmark with large real-world LineStats objects would be worthwhile before removing the "experimental" designation.

---

Tests I would add before merge

The current suite is broad but concentrated on feature combinations rather than some lifecycle orderings. The missing tests correspond closely to the bugs above:

1. Pool reaping race

   • maxtasksperchild=1
   • deliberately delay result handling
   • require exact child hit counts.

2. Multiprocessing helper roles

   • profiling-target module writes PID/process role on import
   • spawn/forkserver
   • assert no target import in resource_tracker or forkserver.

3. Thread start-state transfer

   • construct disabled, start enabled
   • construct enabled, start disabled
   • subclass Thread.run
   • construct and start from different threads.

4. Profiler callback failure

   • force stats collection callback to raise
   • user pool result must still arrive
   • warning is permitted; user-visible workload failure is not.

5. Raw-fork setup failure

   • force _setup_in_child_process failure
   • fork() must still return 0 normally in child
   • partial profiler mutations must be unwound.

6. LineStats.from_files

   • missing file + warn / ignore
   • malformed pickle
   • valid pickle of wrong object type.

7. Periodic output

   • completed child work before an output-interval tick
   • intermediate output should either contain those stats or the combination should be explicitly rejected/documented.

---

Merge recommendation

I would require fixes for 1–4 before approving.

I would strongly prefer fixing 5 at the same time because it is small and directly supports robust child-stat gathering.

For 6, either implementation or explicit experimental limitation is defensible.

After those corrections, I would be comfortable doing a much narrower second review rather than another 11k-line review. The core approach—session cache + lean startup hook + explicit multiprocessing integration + parent-side result aggregation—does not currently look like it needs replacement.

I'm not sure all of these are actually blockers that require more implementation, it could be the case that we clearly state that this feature is only supported in specific simplified conditions. IIRC, we established that there were fundamental cases - I think that surfaced in the Fable review - where the idealized behavior breaks down and there isn't a way to work efficiently around it. What might be a way forward is to state that this feature is only available for 3.12+ so we don't have to spend so much effort to make the legacy path work and maintain parity in tools headings towards EOL in about a year.

Maybe we can separate out CuratedProfilerContext, cleanup utilities, stats aggregation, and some startup-hooks into a standalone PR to work on incrementally landing some of this and reduce the review burden? Even with AI-assisted code review the complexity is too much for me to feel confident in pressing the merge button.

[TTsangSC]

Thanks for the new review.

Yeah refactoring out the cleanup system and the threading patch is definitely the way to go. There's probably no way to do it in a way that preserves history, but then again it was mostly me mucking around refining the code iteratively, and probably not much of value will be lost¹ over streamlining the 100+ commits.

Will write a PR tonight or tomorrow. In the meantime, please check your company mail :)

Footnotes

1. EDIT: /gen. Tones are hard over the internet... ↩

[Erotemic]

I don't think the history needs to be preserved. It exists on Github for the time being in any case.

[TTsangSC]

Sorry for the delay in writing the PR; there's still a little bit of stuff that I have to iron out. Right now I think the first piecemeal PR would consist of:

• line_profiler.cleanup, .curated_profiling, and the associated changes made to kernprof
• line_profiler._threading_patches
• Associated extensions to line_profiler.line_profiler and .line_profiler_utils
• Misc. bug fixes
• Associated tests

Personally I'm somewhat against WONTFIX-ing the threading stuff when using the legacy trace system, if that is what you pointed towards when proposing that we limit the feature to 3.12+. After all, the legacy trace system in Python itself doesn't seem to be going anywhere, though the versions obliged to run them (owing to their lack of the sys.monitoring interface) are going EoL (3.10 this October, and 3.11 the next). And insofar as we plan on landing this feature as part of 5.X, I'd argue it's worth the minimal maintenance to keep it fully compatible.

And there really isn't much to maintain:

• The current behavior fixed by line_profiler._threading_patches I'd say is a bug; and both the fix (said module) and the tests (tests/test_threading.py) are reasonably small.
• Looking that the diffs with main, the only code that is solely here for compatibility is that, and line_profiler.line_profiler_utils.CallbackRepr, where we use a wrapper method instead of accessing <instance>.indent (3.12+) directly.

Now that the PR is getting smaller, I guess we also have the room to properly review and incorporate the C-/Cython-side stuff that you included in TTsangSC#5. Notably, some of the new tests pass on their own (when only the new test module is run), but fails with doubled line-hit counts when they are preceded by tests/test_sys_monitoring.py, presumably due to some thread-local weirdness, which however is fixed by c3b2915. Will also take a closer look at 2f36f08.

EDIT: that said, I'm not entirely convinced that c3b2915 is 100% correct. There's an assumption in _line_profiler.pyx that a _LineProfilerManager is thread-local, and yet now when using sys.monitoring it has an .active_instances shared between instances each associated with a separate thread; unless I'm missing something, I'd imagine that in some cases similar to (but distinct from) tests/test_cross_thread_profiling.py::test_disable_on_one_thread_keeps_other_threads_profiling() the fix would be problematic.