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²
• 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 explicitly cleanup before exiting. Patches are inherited by forked child processes and reapplied by spawned ones.
• To make sure that multiprocessing child processes are allowed to fully clean up and write their profiling, even when the parallel workload errors out,³ additional patches are made to multiprocessing.
• 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/_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 starts with the same .enable_count on the new thread as with the parent thread; this is necessary for correctness because the profiler may otherwise not be enabled 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, 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.py::apply():
  Apply patches to these multiprocessing module components so that profiling results are properly gathered on child-process exit:
  • Process (read: multiprocessing.process.BaseProcess):
    • ._bootstrap():
      Wrapped call to:
      • Call LineProfilingCache.cleanup() on exit.
      • Where possible, register a SIGTERM handler to do the above as a failsafe.
    • .terminate():
      Wrapped call to poll on the child process, and soft-block (with a timeout) until it is deleted.
  • spawn.runpy:
    Replaced with a localized, patched clone of runpy (see runpy_patches.py below). This is necessary for profiling to function in non-eager-preimports mode (--no-preimports).
  • forkserver.ForkServer:
    Global instance rebooted if reboot_forkserver=True so that child processes fork with the profiling infrastructure set up properly.
• pth_hooks.py:
  Facilities for effecting profiling-code execution in child processes by injecting a temporary .pth file into the current venv. This module is kept as minimal as possible to minimize the amount of startup code run as the mere result of having said .pth file.
  • write_pth_hook():
    Set up a .pth file under the directory sysconfig.get_path('purelib') which calls load_pth_hook() (see below). The .pth file will be cleaned up by the supplied cache object.
  • load_pth_hook():
    For processes inheriting a matching "parent PID" from the environment (see LineProfilingCache above), load the cache and set up the LineProfiler instance used, like how the main kernprof process does.
• 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.
• threading_patches.py::apply():
  Patch threading.Thread.__init__() so that when using legacy tracing the profiler is suitably enabled on newly-spawn thread, depending on whether it is enabled on the current thread.

tests/conftest.py

Add the @pytest.mark.retry marker so that we can retry flaky tests.

• _RetryEntry:
  Object containing info on retried test items so that they can be summarized when the session ends.
• _RetryHelper:
  Object implementing the retrying of failing test functions (pytest.Function) and the teardown of function-scoped fixtures between retries.
  • pytest_pyfunc_call():
    Hook implementation for instantiating a helper to handle test rerunning if necessary.
  • get_helper():
    Instantiate from a pytest.Function marked with @pytest.mark.retry(...).
• pytest_addhooks():
  Hook implementation for registering _RetryHelper as a plugin.
• pytest_configure():
  Hook implementation for defining the @pytest.mark.retry marker, so that it doesn't produce a pytest.PytestUnknownMarkWarning when used.
• pytest_terminal_summary():
  Hook implementation for writing a summary section if any test is retried.

tests/test_retry_tests.py

Test that the @pytest.mark.retry marker:

• Properly handles fixture scoping (test_fixture_scoping()), esp. the teardown on non-persisted function-scoped fixtures between retries (test_fixture_teardown())
• Allows for constraining the "allowed" error classes where retries are attempted (test_exception_restrictions())
• Writes a summary of the retried tests at the end of the session.
• Does not produce a pytest.PytestUnknownMarkWarning when used.

tests/test_child_procs.py

• _ModuleFixture:
  Helper object which handles:
  • Module-name mangling (à la tests/test_cython.py::propose_name()) to avoid clashes; and
  • Installation into and cleanup from sys.path and os.environ['PYTHONPATH'].
• _Params:
  Helper object which handles concatenation and Cartesian products of parametrizations.
• ext_module:
  New _ModuleFixture representing a module defining the sum function used by test_module when run without the --local flag.
• _run_subproc():
  New wrapper around subprocess.run() which provide extra debugging output (standard streams, timing info, etc.)
• "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():
    Test the functionality of ~.multiprocessing_patches.apply().
• test_profiling_multiproc_script():
  "Main" new test for running the test_module (see Modified Code) with kernprof --prof-child-procs; heavily parametrized to check for profiling-result correctness in different contexts:
  • run_func: execution modes (kernprof <script>, kernprof -m <module>, and kernprof -c <code>)
  • 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
  • fail: whether the parallel workload errors out
  • 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 doesn't directly invoke multiprocessing, but spins up another Python process that does (via os.system() or subprocess.run()).

Modified code (click to expand)

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 argument on_defective: Literal['ignore', 'warn', 'error'], allowing for passing over bad files (e.g. empty ones) with optional warnings. The old behavior (on_defective='error') remains the default.

line_profiler/rc/line_profiler.toml

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

• [tool.line_profiler.multiprocessing]:
  New key-value pairs for controlling the application of the .multiprocessing_patches:

  • intercept_logs (bool):
    Whether to patch methods like multiprocessing.util.debug() to also capture the multiprocessing logs.
  • polling:
    Behavior for the polling for child-process termination:
    • cooldown (float):
      Time (s) to wait between polls.
    • timeout (float):
      Timeout (s) for the overall polling.
    • on_timeout (Literal['error', 'warn', 'ignore']):
      What to do when the polling timed out.

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

kernprof.py

• _add_core_parser_arguments():
  Now adding the new --[no-]prof-child-procs flags to the parser.

• _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.py

• test_module:
  • Refactored from a Path fixture into a _ModuleFixture (see above in New Code).
  • Added the following command-line flags to the code:
    • --start-method selects a specific multiprocessing "start method".
    • --local toggles between using a sum function defined locally in test_module or the one defined externally in ext_module (see New Code).
    • --force-failure toggles whether the sum function should return normally or raise an error.
• _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.
• _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 arguments:
    • 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).
  • 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).
• test_multiproc_script_sanity_check():
  • Now fuzzing the parametrizations use_local_func, fail, and start_method, to ensure that the test script is 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_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 sys.get_path('purelib'), it depends on said directory being writable. If we aren't in a venv or a similarly isolated environment (which is increasingly unlikely nowadays), all processes using the system Python will have to import and run line_profiler._child_process_profiling.load_pth_hook(). Though the function itself should quit rather quickly when we're not in a child process, it may still entail loading a significant portion of line_profiler into sys.modules.

• Blocking Process.terminate()³ is a bit dodgy:

  • To avoid uncontrolled hot-looping .poll()-ing for the activity of the child-process PID, I'm just using a 1/32-s cooldown.

  • After all, there's a reason Process.terminate() just SIGTERMs the child process with reckless regard – children which errored out are sporadically stuck in an unclean state, and the polling may enter a deadlock. To guard against that I added:

    • A 0.25-s timeout for the polling, after which we just issue a warning and the SIGTERM is sent anyway
    • For tests running kernprof --prof-child-procs or equivalent code:
      • A 5-s timeout for subprocess.run().
      • The opportunity to retry twice if the test failed by insufficient profiling data (because the child process did clean up properly) or if the polling timed out and errored out; the latter doesn't currently happen but can be configured to

    This seems to be enough to both get rid of the deadlocks in tests and preserve profiling data... but the problem is that for child processes to deadlock AT ALL, their cleanup routines must have (of yet) failed to complete, and thus there is still a risk of profiling data not being written. So there's probably either some race conditions hidden by the delays, or an error in how the PID statuses are detected.

• (Note however that on non-Windows platforms we can and do just setup a SIGTERM handler,⁴ which ensures that cleanup finishes before the child succumbs to termination. But yeah on Windows it's just the polling and the delays keeping us afloat.)

• Apparently coverage gets by alright by only patching Process._bootstrap(), without the above termination issue. Gotta figure out why...

TODO

• Add documentation on this new feature.
• 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.
• 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. 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. Had to do some rather hacky stuff to circumvent that (see Caveats)...³

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 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 we're only testing process creation with the most common multiprocessing[.get_context(...)].Pool. However, since none of the patched components are specific to multiprocessing.pool, it should also work with other model of parallelism built with the components of multiprocessing. ↩

3. From the docs for mulitprocessing.Process.terminate(): Note that exit handlers and finally clauses, etc., will not be executed. Normally this doesn't matter, but if the parallelly-executed function errors out, multiprocessing has a bad habit of just .terminate()-ing child processes without allowing for enough time to run cleanup, leading to incomplete profiling data. Hence the only workaround seems to be intercepting Process.terminate() calls and blocking them where appropriate. ↩ ↩² ↩³

4. 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. ↩

[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]

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.