fix(profiling): workaround on-CPU Task race condition [backport 4.1]#15854
fix(profiling): workaround on-CPU Task race condition [backport 4.1]#15854KowalskiThomas merged 1 commit into4.1from
Conversation
|
|
## Description Related PRs - Related: #15712 - Dependent: #15789 - Research PR: https://github.com/DataDog/dd-trace-py/pull/15675/commits (if needed for code archeology...) ### What is this about? This PR updates the Task unwinding logic in the Profiler to (more) properly handle race conditions around running/"on CPU" Tasks. A Task can be either in a _running_ state (i.e. actively _computing_ something itself, like executing a regular Python function) or in a _sleeping_ state (i.e. waiting for something else to happen to wake up). <img width="1076" height="434" alt="image" src="https://github.com/user-attachments/assets/be6759eb-0255-43ef-b3ce-d47486bb653c" /> After those changes, this problem does not appear anymore: only Frames that are actually from the same Stack appear within a given Stack. <img width="1387" height="445" alt="image" src="https://github.com/user-attachments/assets/31287863-f918-47a8-a39b-b3a0d27dce8f" /> ### Why do we need it? Because we don't take a "snapshot of the whole Python process at once", there is a race condition in our Sampler. We first capture the Thread Stack (i.e. for the current Thread, if it is running, what Python code the interpreter is running), then for each Task in the Thread's Event Loop [if it exists] we look at the Task's own Stack. (Since Task/Coroutines are pausable, they have their own Stack that is kept in memory when they're paused, then re-loaded into context when they're resumed. Walking each Task's Stack allows us to e.g. know what code they're "running", even when they aren't actually currently running code...) Going back to the race condition question, we may have a discrepancy between what the Python Thread Stack tells us (what the interpreter is running) and what Task objects themselves tell us (because a tiny amount of time actually elapses between the moment we capture the Thread Stack and the moment we inspect the Task objects, so _what is happening_ may have changed in the meantime). I've already in the past gone into more detail regarding what buggy/unexpected behaviour may result from that race condition; this PR improves this. Note that there is a pretty obvious tradeoff here. When we detect a discrepancy, we can: - Ignore the fact we know something bad is going to happen – I'd rather not do that because it can look terrible for customers (and we don't want to look _obviously wrong_ to them). That would mean _quantity over quality_. - Try to recover by doing clever tricks (this can be somewhat costly because we have to interleave the various Stacks we have... I think we may want to do that at some point but not without putting more thought into it; plus those clever tricks can also sometimes be brittle tricks). That would mean _quality and quantity over cost_ (which in practice probably also means _quality over quantity_ because increasing costs will most probably lead to more adaptive sampling). - Give up and just pretend this never happened – skip that Sample (for the current Task, and in certain cases for the current Thread altogether). That would mean _quality over quantity_. For the time being, things can only get better because we're in a state where we don't deal with the problem at all. The current PR biases towards a mix: we detect more reliably the depth of the pure Python Stack (which allows us not to rely on un-unwinding Task Stacks), and then we skip Samples that we know will be bogus. If the latter happens sufficiently rarely [a claim I still need numbers to back] then this is OK. ### How does it work? The main problem we are trying to avoid here is having some of Task A's Frames appearing as part of Task B's Stack. Working around this requires properly splitting the Python Stack when it says it is running a Task, such that we only push the `asyncio` runtime Frames on top of each non-Task A Task. Walking the Python Stack allows us to do that properly. We thus walk the Python Stack (once per Thread) to detect whether we see `Handle.run` Frames – those indicate that the Event Loop is currently _stepping_ the Coroutine – in other words executing code. (When that happens, we expect at least one Task to be marked as _running_ (there could be more – that's also a race condition, but it's OK, as far as CPU Time is not concerned...)) As soon as we see a `run` Frame, we know the depth of the "pure Python Stack" and we can push it on top of every Task's Stack! ### What does this cost us? This is not completely free – we're doing more work (namely, walking the stack at each Sample). Looking at Full Host Profiles on a high-CPU `asyncio`-based Python script, I'm getting the following difference. Note that the total Profiler overhead is about 360ms/minute, meaning the additional ~20ms we're using here represent an extra 5% overhead. Given the importance of getting Stacks right (or at least not completely wrong), I'd say it's worth it, but it's still noticeable. I tried to do otherwise – but as far as I can tell, as long as the race condition between unwinding the Python Stack and unwinding Task Stacks exists (which it can't not), we will not be able to tell for sure how many pure Python Stack Frames we need to push. There are heuristics that can get us there in theoretically better time (e.g. only walk the Python Stack if all Tasks reported as non-running), but those come at a correctness and code readability cost, and it's not even that certain their overhead would be lesser. I also have another PR that should reduce the cost of unwinding Tasks (that uses the fact we now walk the Python Stack only once): #15789 so hopefully it evens things out. <img width="1926" height="921" alt="image" src="https://github.com/user-attachments/assets/e21a6698-2b18-43bb-aff9-4e8d59354332" /> (cherry picked from commit 61b1799)
KowalskiThomas
force-pushed
the
backport-15780-to-4.1
branch
from
f53a101 to
05f8431
Compare
Bootstrap import analysisComparison of import times between this PR and base. SummaryThe average import time from this PR is: 259 ± 5 ms. The average import time from base is: 263 ± 4 ms. The import time difference between this PR and base is: -4.3 ± 0.2 ms. Import time breakdownThe following import paths have shrunk:
|
Performance SLOsComparing candidate backport-15780-to-4.1 (05f8431) with baseline 4.1 (548a674) 📈 Performance Regressions (4 suites)📈 iastaspects - 118/118✅ add_aspectTime: ✅ 18.209µs (SLO: <20.000µs -9.0%) vs baseline: 📈 +21.6% Memory: ✅ 42.939MB (SLO: <43.250MB 🟡 -0.7%) vs baseline: +4.5% ✅ add_inplace_aspectTime: ✅ 15.039µs (SLO: <20.000µs 📉 -24.8%) vs baseline: ~same Memory: ✅ 43.018MB (SLO: <43.250MB 🟡 -0.5%) vs baseline: +4.8% ✅ add_inplace_noaspectTime: ✅ 0.343µs (SLO: <10.000µs 📉 -96.6%) vs baseline: +1.4% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +5.0% ✅ add_noaspectTime: ✅ 0.549µs (SLO: <10.000µs 📉 -94.5%) vs baseline: +0.5% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ bytearray_aspectTime: ✅ 17.964µs (SLO: <30.000µs 📉 -40.1%) vs baseline: +0.3% Memory: ✅ 42.939MB (SLO: <43.500MB 🟡 -1.3%) vs baseline: +4.9% ✅ bytearray_extend_aspectTime: ✅ 23.835µs (SLO: <30.000µs 📉 -20.5%) vs baseline: +0.1% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ bytearray_extend_noaspectTime: ✅ 2.646µs (SLO: <10.000µs 📉 -73.5%) vs baseline: +0.2% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ bytearray_noaspectTime: ✅ 1.449µs (SLO: <10.000µs 📉 -85.5%) vs baseline: ~same Memory: ✅ 43.018MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +4.9% ✅ bytes_aspectTime: ✅ 16.702µs (SLO: <20.000µs 📉 -16.5%) vs baseline: +0.3% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.9% ✅ bytes_noaspectTime: ✅ 1.400µs (SLO: <10.000µs 📉 -86.0%) vs baseline: ~same Memory: ✅ 43.037MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +4.9% ✅ bytesio_aspectTime: ✅ 54.982µs (SLO: <70.000µs 📉 -21.5%) vs baseline: -0.9% Memory: ✅ 43.077MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +4.9% ✅ bytesio_noaspectTime: ✅ 3.209µs (SLO: <10.000µs 📉 -67.9%) vs baseline: -0.6% Memory: ✅ 43.037MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +4.7% ✅ capitalize_aspectTime: ✅ 14.760µs (SLO: <20.000µs 📉 -26.2%) vs baseline: +0.1% Memory: ✅ 42.959MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ capitalize_noaspectTime: ✅ 2.561µs (SLO: <10.000µs 📉 -74.4%) vs baseline: ~same Memory: ✅ 42.920MB (SLO: <43.500MB 🟡 -1.3%) vs baseline: +4.7% ✅ casefold_aspectTime: ✅ 14.697µs (SLO: <20.000µs 📉 -26.5%) vs baseline: ~same Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ casefold_noaspectTime: ✅ 3.101µs (SLO: <10.000µs 📉 -69.0%) vs baseline: +1.0% Memory: ✅ 42.959MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ decode_aspectTime: ✅ 15.579µs (SLO: <30.000µs 📉 -48.1%) vs baseline: -0.6% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ decode_noaspectTime: ✅ 1.601µs (SLO: <10.000µs 📉 -84.0%) vs baseline: +0.3% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ encode_aspectTime: ✅ 18.311µs (SLO: <30.000µs 📉 -39.0%) vs baseline: 📈 +21.5% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.9% ✅ encode_noaspectTime: ✅ 1.465µs (SLO: <10.000µs 📉 -85.4%) vs baseline: -1.2% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +5.0% ✅ format_aspectTime: ✅ 170.952µs (SLO: <200.000µs 📉 -14.5%) vs baseline: ~same Memory: ✅ 43.077MB (SLO: <43.250MB 🟡 -0.4%) vs baseline: +4.9% ✅ format_map_aspectTime: ✅ 191.416µs (SLO: <200.000µs -4.3%) vs baseline: -0.2% Memory: ✅ 43.136MB (SLO: <43.500MB 🟡 -0.8%) vs baseline: +4.7% ✅ format_map_noaspectTime: ✅ 3.753µs (SLO: <10.000µs 📉 -62.5%) vs baseline: -0.7% Memory: ✅ 43.037MB (SLO: <43.250MB 🟡 -0.5%) vs baseline: +4.9% ✅ format_noaspectTime: ✅ 3.154µs (SLO: <10.000µs 📉 -68.5%) vs baseline: +0.5% Memory: ✅ 42.900MB (SLO: <43.250MB 🟡 -0.8%) vs baseline: +4.5% ✅ index_aspectTime: ✅ 15.292µs (SLO: <20.000µs 📉 -23.5%) vs baseline: -0.5% Memory: ✅ 43.018MB (SLO: <43.250MB 🟡 -0.5%) vs baseline: +5.0% ✅ index_noaspectTime: ✅ 0.462µs (SLO: <10.000µs 📉 -95.4%) vs baseline: ~same Memory: ✅ 43.077MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +5.1% ✅ join_aspectTime: ✅ 16.964µs (SLO: <20.000µs 📉 -15.2%) vs baseline: +0.2% Memory: ✅ 43.018MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +4.9% ✅ join_noaspectTime: ✅ 1.489µs (SLO: <10.000µs 📉 -85.1%) vs baseline: -0.2% Memory: ✅ 42.959MB (SLO: <43.250MB 🟡 -0.7%) vs baseline: +4.4% ✅ ljust_aspectTime: ✅ 20.797µs (SLO: <30.000µs 📉 -30.7%) vs baseline: ~same Memory: ✅ 43.018MB (SLO: <43.250MB 🟡 -0.5%) vs baseline: +5.0% ✅ ljust_noaspectTime: ✅ 2.691µs (SLO: <10.000µs 📉 -73.1%) vs baseline: ~same Memory: ✅ 42.979MB (SLO: <43.250MB 🟡 -0.6%) vs baseline: +4.9% ✅ lower_aspectTime: ✅ 17.846µs (SLO: <30.000µs 📉 -40.5%) vs baseline: -1.0% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ lower_noaspectTime: ✅ 2.392µs (SLO: <10.000µs 📉 -76.1%) vs baseline: +1.4% Memory: ✅ 43.018MB (SLO: <43.250MB 🟡 -0.5%) vs baseline: +4.8% ✅ lstrip_aspectTime: ✅ 17.656µs (SLO: <20.000µs 📉 -11.7%) vs baseline: +0.4% Memory: ✅ 43.077MB (SLO: <43.250MB 🟡 -0.4%) vs baseline: +4.9% ✅ lstrip_noaspectTime: ✅ 1.847µs (SLO: <10.000µs 📉 -81.5%) vs baseline: +1.5% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.6% ✅ modulo_aspectTime: ✅ 166.727µs (SLO: <200.000µs 📉 -16.6%) vs baseline: +0.2% Memory: ✅ 43.077MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +4.7% ✅ modulo_aspect_for_bytearray_bytearrayTime: ✅ 180.261µs (SLO: <200.000µs -9.9%) vs baseline: +3.1% Memory: ✅ 43.077MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +4.7% ✅ modulo_aspect_for_bytesTime: ✅ 168.056µs (SLO: <200.000µs 📉 -16.0%) vs baseline: ~same Memory: ✅ 43.136MB (SLO: <43.500MB 🟡 -0.8%) vs baseline: +5.0% ✅ modulo_aspect_for_bytes_bytearrayTime: ✅ 171.723µs (SLO: <200.000µs 📉 -14.1%) vs baseline: ~same Memory: ✅ 43.037MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +4.4% ✅ modulo_noaspectTime: ✅ 3.734µs (SLO: <10.000µs 📉 -62.7%) vs baseline: +1.3% Memory: ✅ 43.077MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +5.0% ✅ replace_aspectTime: ✅ 214.728µs (SLO: <300.000µs 📉 -28.4%) vs baseline: ~same Memory: ✅ 43.195MB (SLO: <44.000MB 🟡 -1.8%) vs baseline: +5.2% ✅ replace_noaspectTime: ✅ 5.210µs (SLO: <10.000µs 📉 -47.9%) vs baseline: +0.2% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ repr_aspectTime: ✅ 1.385µs (SLO: <10.000µs 📉 -86.1%) vs baseline: -0.7% Memory: ✅ 42.959MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.4% ✅ repr_noaspectTime: ✅ 0.529µs (SLO: <10.000µs 📉 -94.7%) vs baseline: -0.4% Memory: ✅ 43.057MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +4.9% ✅ rstrip_aspectTime: ✅ 19.055µs (SLO: <30.000µs 📉 -36.5%) vs baseline: -0.1% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ rstrip_noaspectTime: ✅ 1.910µs (SLO: <10.000µs 📉 -80.9%) vs baseline: +2.6% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ slice_aspectTime: ✅ 16.034µs (SLO: <20.000µs 📉 -19.8%) vs baseline: ~same Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ slice_noaspectTime: ✅ 0.602µs (SLO: <10.000µs 📉 -94.0%) vs baseline: ~same Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.9% ✅ stringio_aspectTime: ✅ 53.566µs (SLO: <80.000µs 📉 -33.0%) vs baseline: -0.5% Memory: ✅ 42.920MB (SLO: <43.500MB 🟡 -1.3%) vs baseline: +4.5% ✅ stringio_noaspectTime: ✅ 3.531µs (SLO: <10.000µs 📉 -64.7%) vs baseline: -0.6% Memory: ✅ 43.037MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +5.0% ✅ strip_aspectTime: ✅ 17.725µs (SLO: <20.000µs 📉 -11.4%) vs baseline: +0.6% Memory: ✅ 43.018MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +4.8% ✅ strip_noaspectTime: ✅ 1.819µs (SLO: <10.000µs 📉 -81.8%) vs baseline: -1.3% Memory: ✅ 43.018MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +5.0% ✅ swapcase_aspectTime: ✅ 18.401µs (SLO: <30.000µs 📉 -38.7%) vs baseline: -0.3% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +5.0% ✅ swapcase_noaspectTime: ✅ 2.774µs (SLO: <10.000µs 📉 -72.3%) vs baseline: +0.8% Memory: ✅ 43.037MB (SLO: <43.500MB 🟡 -1.1%) vs baseline: +5.1% ✅ title_aspectTime: ✅ 18.237µs (SLO: <30.000µs 📉 -39.2%) vs baseline: -0.4% Memory: ✅ 42.998MB (SLO: <43.000MB 🟡 ~same) vs baseline: +5.0% ✅ title_noaspectTime: ✅ 2.651µs (SLO: <10.000µs 📉 -73.5%) vs baseline: +0.4% Memory: ✅ 42.959MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ translate_aspectTime: ✅ 24.170µs (SLO: <30.000µs 📉 -19.4%) vs baseline: 📈 +17.3% Memory: ✅ 42.998MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.8% ✅ translate_noaspectTime: ✅ 4.273µs (SLO: <10.000µs 📉 -57.3%) vs baseline: +0.2% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% ✅ upper_aspectTime: ✅ 17.922µs (SLO: <30.000µs 📉 -40.3%) vs baseline: -0.6% Memory: ✅ 43.057MB (SLO: <43.500MB 🟡 -1.0%) vs baseline: +4.8% ✅ upper_noaspectTime: ✅ 2.377µs (SLO: <10.000µs 📉 -76.2%) vs baseline: -1.1% Memory: ✅ 42.979MB (SLO: <43.500MB 🟡 -1.2%) vs baseline: +4.7% 📈 iastaspectsospath - 24/24✅ ospathbasename_aspectTime: ✅ 5.126µs (SLO: <10.000µs 📉 -48.7%) vs baseline: 📈 +21.2% Memory: ✅ 41.445MB (SLO: <43.500MB -4.7%) vs baseline: +5.0% ✅ ospathbasename_noaspectTime: ✅ 4.314µs (SLO: <10.000µs 📉 -56.9%) vs baseline: ~same Memory: ✅ 41.504MB (SLO: <43.500MB -4.6%) vs baseline: +4.9% ✅ ospathjoin_aspectTime: ✅ 6.164µs (SLO: <10.000µs 📉 -38.4%) vs baseline: +0.4% Memory: ✅ 41.445MB (SLO: <43.500MB -4.7%) vs baseline: +4.8% ✅ ospathjoin_noaspectTime: ✅ 6.261µs (SLO: <10.000µs 📉 -37.4%) vs baseline: +0.7% Memory: ✅ 41.425MB (SLO: <43.500MB -4.8%) vs baseline: +4.7% ✅ ospathnormcase_aspectTime: ✅ 3.534µs (SLO: <10.000µs 📉 -64.7%) vs baseline: +0.4% Memory: ✅ 41.445MB (SLO: <43.500MB -4.7%) vs baseline: +4.9% ✅ ospathnormcase_noaspectTime: ✅ 3.596µs (SLO: <10.000µs 📉 -64.0%) vs baseline: ~same Memory: ✅ 41.445MB (SLO: <43.500MB -4.7%) vs baseline: +5.0% ✅ ospathsplit_aspectTime: ✅ 4.802µs (SLO: <10.000µs 📉 -52.0%) vs baseline: -0.5% Memory: ✅ 41.504MB (SLO: <43.500MB -4.6%) vs baseline: +4.8% ✅ ospathsplit_noaspectTime: ✅ 4.957µs (SLO: <10.000µs 📉 -50.4%) vs baseline: +0.2% Memory: ✅ 41.406MB (SLO: <43.500MB -4.8%) vs baseline: +4.9% ✅ ospathsplitdrive_aspectTime: ✅ 3.761µs (SLO: <10.000µs 📉 -62.4%) vs baseline: +0.2% Memory: ✅ 41.327MB (SLO: <43.500MB -5.0%) vs baseline: +4.4% ✅ ospathsplitdrive_noaspectTime: ✅ 0.761µs (SLO: <10.000µs 📉 -92.4%) vs baseline: +1.9% Memory: ✅ 41.386MB (SLO: <43.500MB -4.9%) vs baseline: +4.8% ✅ ospathsplitext_aspectTime: ✅ 4.613µs (SLO: <10.000µs 📉 -53.9%) vs baseline: +0.2% Memory: ✅ 41.425MB (SLO: <43.500MB -4.8%) vs baseline: +4.9% ✅ ospathsplitext_noaspectTime: ✅ 4.696µs (SLO: <10.000µs 📉 -53.0%) vs baseline: ~same Memory: ✅ 41.366MB (SLO: <43.500MB -4.9%) vs baseline: +4.4% 📈 iastaspectssplit - 12/12✅ rsplit_aspectTime: ✅ 1.713µs (SLO: <10.000µs 📉 -82.9%) vs baseline: 📈 +10.1% Memory: ✅ 41.465MB (SLO: <43.500MB -4.7%) vs baseline: +4.8% ✅ rsplit_noaspectTime: ✅ 1.612µs (SLO: <10.000µs 📉 -83.9%) vs baseline: -1.2% Memory: ✅ 41.327MB (SLO: <43.500MB -5.0%) vs baseline: +4.7% ✅ split_aspectTime: ✅ 1.564µs (SLO: <10.000µs 📉 -84.4%) vs baseline: -0.3% Memory: ✅ 41.366MB (SLO: <43.500MB -4.9%) vs baseline: +4.8% ✅ split_noaspectTime: ✅ 1.646µs (SLO: <10.000µs 📉 -83.5%) vs baseline: +1.0% Memory: ✅ 41.347MB (SLO: <43.500MB -5.0%) vs baseline: +4.7% ✅ splitlines_aspectTime: ✅ 1.541µs (SLO: <10.000µs 📉 -84.6%) vs baseline: +2.0% Memory: ✅ 41.465MB (SLO: <43.500MB -4.7%) vs baseline: +5.0% ✅ splitlines_noaspectTime: ✅ 1.568µs (SLO: <10.000µs 📉 -84.3%) vs baseline: -0.4% Memory: ✅ 41.406MB (SLO: <43.500MB -4.8%) vs baseline: +4.9% 📈 telemetryaddmetric - 30/30✅ 1-count-metric-1-timesTime: ✅ 3.367µs (SLO: <20.000µs 📉 -83.2%) vs baseline: 📈 +12.1% Memory: ✅ 34.800MB (SLO: <35.500MB 🟡 -2.0%) vs baseline: +4.7% ✅ 1-count-metrics-100-timesTime: ✅ 201.823µs (SLO: <220.000µs -8.3%) vs baseline: +0.4% Memory: ✅ 34.819MB (SLO: <35.500MB 🟡 -1.9%) vs baseline: +4.7% ✅ 1-distribution-metric-1-timesTime: ✅ 3.352µs (SLO: <20.000µs 📉 -83.2%) vs baseline: -0.6% Memory: ✅ 34.839MB (SLO: <35.500MB 🟡 -1.9%) vs baseline: +5.1% ✅ 1-distribution-metrics-100-timesTime: ✅ 218.062µs (SLO: <230.000µs -5.2%) vs baseline: +0.4% Memory: ✅ 34.898MB (SLO: <35.500MB 🟡 -1.7%) vs baseline: +5.3% ✅ 1-gauge-metric-1-timesTime: ✅ 2.160µs (SLO: <20.000µs 📉 -89.2%) vs baseline: -1.5% Memory: ✅ 34.859MB (SLO: <35.500MB 🟡 -1.8%) vs baseline: +4.9% ✅ 1-gauge-metrics-100-timesTime: ✅ 136.701µs (SLO: <150.000µs -8.9%) vs baseline: -0.2% Memory: ✅ 34.800MB (SLO: <35.500MB 🟡 -2.0%) vs baseline: +4.8% ✅ 1-rate-metric-1-timesTime: ✅ 3.149µs (SLO: <20.000µs 📉 -84.3%) vs baseline: -0.4% Memory: ✅ 34.937MB (SLO: <35.500MB 🟡 -1.6%) vs baseline: +5.3% ✅ 1-rate-metrics-100-timesTime: ✅ 215.303µs (SLO: <250.000µs 📉 -13.9%) vs baseline: -0.4% Memory: ✅ 34.918MB (SLO: <35.500MB 🟡 -1.6%) vs baseline: +4.9% ✅ 100-count-metrics-100-timesTime: ✅ 20.032ms (SLO: <22.000ms -8.9%) vs baseline: -1.4% Memory: ✅ 34.819MB (SLO: <35.500MB 🟡 -1.9%) vs baseline: +4.8% ✅ 100-distribution-metrics-100-timesTime: ✅ 2.293ms (SLO: <2.550ms 📉 -10.1%) vs baseline: -0.5% Memory: ✅ 34.839MB (SLO: <35.500MB 🟡 -1.9%) vs baseline: +4.6% ✅ 100-gauge-metrics-100-timesTime: ✅ 1.392ms (SLO: <1.550ms 📉 -10.2%) vs baseline: -0.2% Memory: ✅ 34.760MB (SLO: <35.500MB -2.1%) vs baseline: +4.6% ✅ 100-rate-metrics-100-timesTime: ✅ 2.185ms (SLO: <2.550ms 📉 -14.3%) vs baseline: -1.1% Memory: ✅ 34.839MB (SLO: <35.500MB 🟡 -1.9%) vs baseline: +4.7% ✅ flush-1-metricTime: ✅ 4.620µs (SLO: <20.000µs 📉 -76.9%) vs baseline: +0.5% Memory: ✅ 35.232MB (SLO: <35.500MB 🟡 -0.8%) vs baseline: +4.7% ✅ flush-100-metricsTime: ✅ 174.313µs (SLO: <250.000µs 📉 -30.3%) vs baseline: +0.1% Memory: ✅ 35.330MB (SLO: <35.500MB 🟡 -0.5%) vs baseline: +5.1% ✅ flush-1000-metricsTime: ✅ 2.182ms (SLO: <2.500ms 📉 -12.7%) vs baseline: -0.7% Memory: ✅ 35.960MB (SLO: <36.500MB 🟡 -1.5%) vs baseline: +4.6% 🟡 Near SLO Breach (15 suites)🟡 coreapiscenario - 10/10 (1 unstable)
|
1 participant
Backport 61b1799 from #15780 to 4.1.
Description
Related PRs
What is this about?
This PR updates the Task unwinding logic in the Profiler to (more) properly handle race conditions around running/"on CPU" Tasks. A Task can be either in a running state (i.e. actively computing something itself, like executing a regular Python function) or in a sleeping state (i.e. waiting for something else to happen to wake up).
After those changes, this problem does not appear anymore: only Frames that are actually from the same Stack appear within a given Stack.
Why do we need it?
Because we don't take a "snapshot of the whole Python process at once", there is a race condition in our Sampler.
We first capture the Thread Stack (i.e. for the current Thread, if it is running, what Python code the interpreter is running), then for each Task in the Thread's Event Loop [if it exists] we look at the Task's own Stack. (Since Task/Coroutines are pausable, they have their own Stack that is kept in memory when they're paused, then re-loaded into context when they're resumed. Walking each Task's Stack allows us to e.g. know what code they're "running", even when they aren't actually currently running code...)
Going back to the race condition question, we may have a discrepancy between what the Python Thread Stack tells us (what the interpreter is running) and what Task objects themselves tell us (because a tiny amount of time actually elapses between the moment we capture the Thread Stack and the moment we inspect the Task objects, so what is happening may have changed in the meantime).
I've already in the past gone into more detail regarding what buggy/unexpected behaviour may result from that race condition; this PR improves this.
Note that there is a pretty obvious tradeoff here. When we detect a discrepancy, we can:
For the time being, things can only get better because we're in a state where we don't deal with the problem at all. The current PR biases towards a mix: we detect more reliably the depth of the pure Python Stack (which allows us not to rely on un-unwinding Task Stacks), and then we skip Samples that we know will be bogus. If the latter happens sufficiently rarely [a claim I still need numbers to back] then this is OK.
How does it work?
The main problem we are trying to avoid here is having some of Task A's Frames appearing as part of Task B's Stack. Working around this requires properly splitting the Python Stack when it says it is running a Task, such that we only push the
asyncioruntime Frames on top of each non-Task A Task. Walking the Python Stack allows us to do that properly.We thus walk the Python Stack (once per Thread) to detect whether we see
Handle.runFrames – those indicate that the Event Loop is currently stepping the Coroutine – in other words executing code. (When that happens, we expect at least one Task to be marked as running (there could be more – that's also a race condition, but it's OK, as far as CPU Time is not concerned...))As soon as we see a
runFrame, we know the depth of the "pure Python Stack" and we can push it on top of every Task's Stack!What does this cost us?
This is not completely free – we're doing more work (namely, walking the stack at each Sample). Looking at Full Host Profiles on a high-CPU
asyncio-based Python script, I'm getting the following difference.Note that the total Profiler overhead is about 360ms/minute, meaning the additional ~20ms we're using here represent an extra 5% overhead. Given the importance of getting Stacks right (or at least not completely wrong), I'd say it's worth it, but it's still noticeable.
I tried to do otherwise – but as far as I can tell, as long as the race condition between unwinding the Python Stack and unwinding Task Stacks exists (which it can't not), we will not be able to tell for sure how many pure Python Stack Frames we need to push. There are heuristics that can get us there in theoretically better time (e.g. only walk the Python Stack if all Tasks reported as non-running), but those come at a correctness and code readability cost, and it's not even that certain their overhead would be lesser.
I also have another PR that should reduce the cost of unwinding Tasks (that uses the fact we now walk the Python Stack only once): #15789 so hopefully it evens things out.