[Data] Break "UDF time" down into input prep, function body and output build - #65807
[Data] Break "UDF time" down into input prep, function body and output build#65807marwan116 wants to merge 18 commits into
Conversation
64b00c8 to
e7d29a7
Compare
There was a problem hiding this comment.
Code Review
This pull request decomposes the overall 'UDF time' metric in Ray Data into four distinct phases: input preparation, UDF body execution, output block building, and other fused stages. It introduces these granular metrics across execution stats, operator summaries, and block metadata, with an opt-in configuration (accurate_map_phase_timing) for row-based transforms to avoid overhead. The review feedback highlights a critical missing update to BlockExecStatsBuilder.build that would cause a runtime TypeError when constructing block stats, and suggests a formatting improvement to ensure core UDF phases are consistently displayed in verbose logs even when their sum is zero.
…t build "UDF time" covers a map stage's whole transform, not the user's function: the timed window spans turning input blocks into batches, calling the function, and assembling the output back into blocks. On a batch that carries Python objects the two ends can dominate -- a UDF that never touches an object column still reports the time spent unpickling it -- and there is no way to tell which part is which. Decompose it. `udf_time_s` keeps meaning the whole chain, so nothing that reads it today changes, and four new figures say where inside it the time went: input prep, the UDF body, output block build, and the bodies of non-UDF stages fused into the same chain. They sum back to the total, which a test asserts. `ds.stats()` renders them as a breakdown under the existing line, and all four are `metric_field`s on `OpRuntimeMetrics`, so they reach Prometheus per operator the same way the existing task metrics do. Timing a phase reuses the nesting subtraction already in `_UDFTimingIterator`: it measures inclusive time and subtracts what the timers below it added, so splitting one timer per stage into three per stage needs no new mechanism, only new wrap points inside `MapTransformFn.__call__`. Row-based transforms are not decomposed by default. Each wrapper costs a Python frame per item it yields, which is noise for a batch transform and roughly 1us per row across a three-stage chain for a row transform. Those keep the existing one-timer-per-stage arrangement -- same cost, same total, no breakdown -- and `DataContext.accurate_map_phase_timing` opts into the breakdown for them. Note the timers stay per stage even without decomposition rather than collapsing to one for the whole chain: `MapTransformFn.__call__` runs `_pre_process` eagerly, so with `batch_size="auto"` a later stage pulls data through earlier ones while the chain is still being built, and a single timer installed at the end would miss it. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Three cases: - The components add up to `udf_time`. This is what makes the breakdown a decomposition rather than four loosely related numbers, and it is the property that would break first if a phase were double counted or missed. - Input prep and output block build are visible separately from the body. The UDF reads only the `id` column and never touches the column of Python objects beside it, so input prep dominates -- time the single figure used to attribute to user code. - Row transforms report only a total by default, and flipping `accurate_map_phase_timing` buys the breakdown without moving the total. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
…e line Three changes from review of the phase breakdown. The breakdown no longer appears in the default `ds.stats()`. It is rendered only under `verbose_stats_logs`, the same flag and the same treatment `extra_metrics` already gets, so the default output is byte-identical to before and `test_dataset_stats_basic` passes unchanged. The figures are still always on `OperatorStatsSummary` for anyone reading it programmatically -- gating display is not a reason to withhold data. "Other stages" is now "Built-in stages". The old name said what the line was not, which collided with its three siblings: they are all non-UDF work too. The new one says what it is -- the body of a stage Ray Data supplied, as against the function you passed. Reads, writes, downloads and file listing all land there, so the label generalises where an enumeration would not. The phase figures are `None` rather than zero when a chain measured only its total, so a consumer can tell "not measured" from "measured as zero", and the five metrics are `map_only`: an operator with no UDF transform chain has no UDF phases to report, and emitting zeros for it is noise. Tests: the phase timings are canonicalized to a stable placeholder like `obj_store_mem_used`. A trivial UDF spends sub-microsecond in each phase, so the figure rounds to zero or not depending on the run -- observed flipping between two consecutive runs. The measured-vs-not distinction that would have tested is asserted directly in `test_row_transform_phases_are_opt_in` instead. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
… non-UDF operators Four review findings on this PR, two of them real bugs. Non-UDF operators reported UDF time. The `decomposed` branch wrapped every stage in a timer, so a standalone read or projection reported its whole transform under "UDF time" -- an operator that runs nothing the user wrote. The parent branch and master both install a timer only `if _is_udf`, and report zero for those operators. `apply_transform` now skips timing entirely when no UDF is in the chain, so there is no timer to pay for either. Eagerly-consuming stage bodies went untimed. `generate_write_fn` has no `yield`: it calls `datasink.write(it1, ctx)`, which performs the whole upload before returning the iterable. That work happened inside `_apply_transform`, which was evaluated before `wrap_phase` had anything to wrap, so it landed in no phase and not in the total. A datasink sleeping 0.3s per block over two blocks reported 155us of built-in stage time against 600ms of I/O. `PhaseWrapFn` now takes a thunk instead of an iterable, so the hook owns the call and can time it. `UDFTimeScope.attribute_call` times that call with the same nesting subtraction as `__next__` -- an eager stage pulls its input through the timers already in the chain, so subtracting what they credited leaves its own work. The window runs once per stage per task, off the per-row path, so it applies on both the decomposed and total-only paths and the two totals stay in agreement. The same workload now reports 606ms, and UDF time accounts for 99.5% of remote wall time rather than 25.6%. The three phases every chain runs are now printed even at 0.0, so the lines visibly sum to the total above them. Previously a phase was dropped at zero, which both broke that arithmetic and made line presence vary run to run for a fast UDF -- a latent flaky test. Built-in stages is still dropped at zero, since most chains fuse nothing built-in. Docs: the operator-stats section described "UDF time" as excluding input prep and output block build. It includes them -- they are its components, and `Function body` is the line that excludes them. Restructured to nest the four phases under the total they decompose, documented `Function body` and `Built-in stages`, and noted that the breakdown is verbose-only and that row transforms need `accurate_map_phase_timing`. Added it to the Verbose stats list alongside `extra_metrics`, which it follows. Tests: `test_operator_without_a_udf_reports_no_udf_time` and `test_eagerly_consuming_stage_body_is_timed`, each confirmed to fail before being confirmed to pass. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
84cdde4 to
72281ba
Compare
iamjustinhsu
left a comment
There was a problem hiding this comment.
Nice, left some questions and some higher-level feedback since I think the code is getting a bit complicated
| what they return back into blocks. Set ``DataContext.verbose_stats_logs`` to break it into the following phases, which sum to | ||
| this total: | ||
|
|
||
| * **Input prep**: Time spent turning input blocks into the batches or rows your functions receive, including converting them |
There was a problem hiding this comment.
So just from the description of the breakdown(not looking at code yet), I'm still a bit uncertain how the timing phases work. So if there is something like this:
Read -> select_columns -> map1 -> map2does the function body only include the sum of map1, map2. Does the built-in stage include the sum of Read and select_columns? And then we in between each phase there is input and output batching?
There was a problem hiding this comment.
Built-in stages is now gone: Function body holds all four bodies: ReadRange, Project, map1 and map2. Input prep and Output block build span all four too, since every stage forms its own batches and builds its own blocks.
So the breakdown tells you which phase the time went to, not which stage. Your exact pipeline is now a worked example in the docs.
| operator summary of the time each operator took to complete and the fraction of the total execution time that the operator took | ||
| to complete. As there are potentially multiple concurrent operators, these percentages don't necessarily sum to 100%. Instead, | ||
| they show how long running each of the operators is in the context of the full dataset execution. | ||
| * **UDF time breakdown**: Each operator's **UDF time** is split into the input prep, function body, output block build and |
There was a problem hiding this comment.
Is UDF time here the same as total task time? Or is UDF time per block?
There was a problem hiding this comment.
Per output block. The scope drains after each output block, so min/max/mean are per block and sum is the operator total. I've put "per output block" into the opening sentence of the bullet.
There was a problem hiding this comment.
Updating this after the rename: the figure is Block transform time now. Still per output block — min, max and mean are across a task's output blocks, and the total is the operator's.
| ``total_s`` is the whole chain, which is what Ray Data has always reported as | ||
| "UDF time". The rest decompose it and sum back to it, saying where inside the |
There was a problem hiding this comment.
I think UDF time could be misleading because it sounds like the function-body time. I think we should rename this to total_task_s or total_task_per_block_s depending on how its broken down
There was a problem hiding this comment.
I went with block_transform_time_s:
BlockExecStats.udf_time_s,OperatorStatsSummary.udf_timeandOpRuntimeMetrics.udf_time_sare all renamed, so the Prometheus metric isray_data_block_transform_time_s.ds.stats()now prints Block transform time: instead of UDF time.
| self.target_max_block_size_override | ||
| ) | ||
|
|
||
| # Splitting a stage into phases means a timer around each of the three, |
There was a problem hiding this comment.
Higher level feedback for this map transformer (lmk if this makes sense, and whether you want to tackle this in ur PR).
So to give context, during planning operators that launch tasks (read, write, map) use the MapTransformer. The map transformer takes in a MapTransformFn, which also contains pre- and post-processing. I think with all the lazy iterators it's getting harder to interpret what is getting timed, and what is being wrapped, since iterators don't show upstream iterators well. To make this clear, I'm wondering if you could take some time experimenting an approach that is bit more explicit on what's being timed. My suggestion would be:
_map_taskis the main entrypoint for running a task. It contains referrences to the input blocks.- Remove
apply_transformin_map_task. Instead, create another function that returns an iterable ofMapTransformFn. Suppose we call thatget_transform_fns(). It should contain the function bodies as well as well as pre and post processing. - Then, for each input block, we should call
get_transform_fns(), and apply those functions. So something like
transform_fns = map_transformer.get_transform_fns()
for input_block in blocks:
for transform_fn in transform_fns:
# here you can time each of these very explicity
out = transform_fn.preprocess(input_block)
out = transform_fn(out)
out = transform_fn.postprocess(out)This ^ will require some work because the transform_fns right now accept an input iterable, since everything is passed by reference. If you go this route, we'll need to change the API signature
Also, 2 side notes
- we should treat built-in stages the same as UDFs. I don't think we need a separate breakdown, since at the end of the day it's just a function (whether it be read or write)
- Operators who eagerly compute (like write) should don't need special casing since we are running the function-body per block
There was a problem hiding this comment.
Also note that there is room for optimization here. We might be able to skip consecutive pre and postprocess in the same fused task, but we can worry about that later
There was a problem hiding this comment.
agreed with you that the lazy chain is hard to follow.
One concrete obstacle with the sketch as written: batches span input blocks.
E.g. with 4 input blocks of 1 row each and batch_size=4, a for input_block in blocks: outer loop can't express that correctly - i.e. it would silently turn batch_size=4 into four batches of 1.
Output block shaping buffers across inputs the same way. So the refactor needs an answer for cross-block buffering.
There was a problem hiding this comment.
@iamjustinhsu I iterated on this with Claude — let me know if the code now reads as sufficiently simpler.
Both side notes are addressed:
Built-in stagesis gone as a bucket; a read or write body lands inFunction bodylike any UDF's.- Deferring each step's
applyto its first pull removed the write special case — the upload now happens inside the same window as the pulls. It did surface a real 2PC ordering bug in the checkpoint chain, fixed in c89db16.
Two review nits from @iamjustinhsu, neither functional. The "UDF time" bullet spelled out that the figure covers "the work Ray Data does on either side of them to hand them batches and to turn what they return back into blocks", which is a mouthful for something the breakdown right below it already itemises. Shortened to say it covers the functions plus the work around them that feeds and collects them, and stated up front that the figure is per output block -- a second question the reviewer raised about the same paragraph. The comment above the breakdown table had grown to 17 lines for 12 lines of code, restating rationale that lives in the PR description and in the `accurate_map_phase_timing` docstring. Cut to the three things a reader of this function cannot get elsewhere: the lines sum to the total, they are verbose-only, and the trailing bool is whether to print at 0.0. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Answers a review comment on #65807 asking for an approach that is explicit about what gets timed, rather than one where the timing emerges from nested lazy iterators. `MapTransformFn.timed_steps()` returns the transform as a flat list of `TimedStep`s -- label, phase, stage index, and an `Iterable -> Iterable` body. `MapTransformer.get_timed_steps()` concatenates them and `TransformClock.chain()` builds the pipeline, so the answer to "what is getting timed?" is a list that can be printed and asserted on. A step measures only itself, with no coordination: def __next__(self): start = time.perf_counter() try: if self._iter is None: self._iter = iter(self._apply(self._upstream)) return next(self._iter) finally: self._totals[self._idx] += time.perf_counter() - start That total is inclusive of everything upstream. The chain is linear -- step k is only ever pulled by step k+1 -- so all of a step's time lies inside its consumer's windows, and subtracting neighbouring totals at drain recovers each step's own work. #65807 does the same arithmetic per item, threading a shared cursor through every `__next__`; doing it once over a list is easier to follow and measures 580 ns/item against 1016. Deferring `apply` to the first pull removes the eager special case. A write performs its whole upload while its iterable is built, which on #65807 needed its own timing window (`attribute_call`); here that work simply happens inside the same window as the pulls. `accurate_map_phase_timing` stops being a second code path and becomes a rewrite of the step list: fold a stage's three steps into one, whose `bucket` is None because it spans all three. A phase no step carries is then absent from the grouping, so "not measured" falls out of the data rather than being tracked by a flag. Accruing per step also means the per-phase and per-fused-stage breakdowns are two groupings of one array, with no second accumulator to keep in sync. `UDFTimeScope` becomes `TransformClock` and the `udf_time_scope=` keyword becomes `clock=`; the old name stopped describing an object that times every step, including the ones that are not user code. Removes `PhaseWrapFn`, `_no_phase_wrapping`, `wrap_phase`, `attribute_call` and `_UDFTimingIterator`. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
`from ray.data.datasource import Datasink`, added with the eager-stage test, sat above the `ray.data._internal` block. Ray's pre-commit runs ruff a second time with `--select I`, which is not in the default select set, so a plain `ruff check` passes while CI does not. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Answers a review comment on #65807 asking for an approach that is explicit about what gets timed, rather than one where the timing emerges from nested lazy iterators. `MapTransformFn.timed_steps()` returns the transform as a flat list of `TimedStep`s -- label, phase, stage index, and an `Iterable -> Iterable` body. `MapTransformer.get_timed_steps()` concatenates them and `TransformClock.chain()` builds the pipeline, so the answer to "what is getting timed?" is a list that can be printed and asserted on. A step measures only itself, with no coordination: def __next__(self): start = time.perf_counter() try: if self._iter is None: self._iter = iter(self._apply(self._upstream)) return next(self._iter) finally: self._totals[self._idx] += time.perf_counter() - start That total is inclusive of everything upstream. The chain is linear -- step k is only ever pulled by step k+1 -- so all of a step's time lies inside its consumer's windows, and subtracting neighbouring totals at drain recovers each step's own work. #65807 does the same arithmetic per item, threading a shared cursor through every `__next__`; doing it once over a list is easier to follow and measures 580 ns/item against 1016. Deferring `apply` to the first pull removes the eager special case. A write performs its whole upload while its iterable is built, which on #65807 needed its own timing window (`attribute_call`); here that work simply happens inside the same window as the pulls. `accurate_map_phase_timing` stops being a second code path and becomes a rewrite of the step list: fold a stage's three steps into one, whose `bucket` is None because it spans all three. A phase no step carries is then absent from the grouping, so "not measured" falls out of the data rather than being tracked by a flag. Accruing per step also means the per-phase and per-fused-stage breakdowns are two groupings of one array, with no second accumulator to keep in sync. `UDFTimeScope` becomes `TransformClock` and the `udf_time_scope=` keyword becomes `clock=`; the old name stopped describing an object that times every step, including the ones that are not user code. Removes `PhaseWrapFn`, `_no_phase_wrapping`, `wrap_phase`, `attribute_call` and `_UDFTimingIterator`. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com> Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Justin asked, on the verbose breakdown bullet, what UDF time means when a task has several input or output blocks. It is measured per output block: min, max and mean are across blocks, the total is the operator's. Say so in both bullets -- the one he commented on and the primary definition, which also now distinguishes UDF time from the task's total time. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
…f steps Folds the RFC branch in. It answers the review comment asking for an approach that is explicit about what gets timed, rather than one where the timing emerges from nested lazy iterators, and it replaces the per-item subtraction cursor this branch had. `MapTransformFn.timed_steps()` returns the transform as a flat list of `TimedStep`s -- label, bucket, stage index, and an `Iterable -> Iterable` body. `MapTransformer.get_timed_steps()` concatenates them and `TransformClock.chain()` builds the pipeline, so "what is getting timed?" is answered by a list you can print and assert on. Each step measures only itself, with no cross-step coordination: a step's total is inclusive of everything upstream, the chain is linear, so subtracting neighbouring totals once at drain recovers each step's own work. That is 580 ns/item against the 1016 ns/item the shared cursor cost. Deferring `apply` to the first pull also removes the eager special case: a write performs its whole upload while its iterable is built, which previously needed its own timing window (`attribute_call`); here that work lands inside the same window as the pulls. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com>
…nding Cursor Bugbot caught this on the merge of #65855. `TransformClock.chain` hands every `_TimedStep` a reference to `self.inclusive`, and `drain` replaced that list with a new one -- so after the first drain the steps kept adding to a list the clock no longer read. `_map_task` drains once per output block, so a task's first block reported its time and every block after it reported zero. Zeroing the list in place keeps the steps and the clock pointing at the same object. The per-drain window is still self-contained: both a step and its upstream neighbour start from zero at the same instant, so the adjacent-difference arithmetic is unchanged. Unit-level, one stage sleeping 0.05s with one output block per batch: before block 0: 0.0573s block 1: 0.0000s block 2: 0.0000s after block 0: 0.0826s block 1: 0.0537s block 2: 0.0548s `test_every_output_block_is_timed` covers it, and fails on the old line. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Vale is what fails microcheck's lint job, and all four of its errors were
in lines this PR added:
396:93 Google.EmDash Don't put a space before or after a dash.
396:94 Google.EnDash Use an em dash ('---') instead of '--'.
397:50 Google.Contractions Use 'it's' instead of 'It is'.
464:73 Google.WordList Use 'preceding' instead of 'above'.
Rather than switch to `---`, drop the dash: this file has no em dashes in
prose, so the only one would have been mine. The "described above"
cross-reference goes too -- the phases are named in the same sentence, so
it added nothing. Both bullets are active voice now, which also clears
three of Vale's suggestions on the same lines.
`pre-commit run vale --all-files` passes (it needs `rst2html` from
docutils on PATH, which is why this went unnoticed locally).
Signed-off-by: Marwan Sarieddine <marwan@anyscale.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa
Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Justin asked, of a `Read -> select_columns -> map1 -> map2` pipeline, whether Function body is just map1 + map2, whether Built-in stages is Read + select_columns, and where the batching in between lands. I answered on the thread and said the doc should carry it; this is that. The new "Reading the UDF time breakdown" section runs his exact pipeline and reads the output line by line: Function body holds the two functions alone (616 ms against 0.6 s slept), Built-in stages holds ReadRange and Project, and Input prep and Output block build cover all four stages rather than only the two the caller wrote. Numbers are measured, not illustrative. `MapTransformPhaseTimes` also now says outright that `total_s` is not the function-body time and that `udf_body_s` is -- the ambiguity behind his rename request, stated where he raised it. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Justin's point: the name reads as the function-body time, and it isn't. The figure covers a map stage's whole transform -- batch formation, the stage bodies, and output block building -- for every stage of a (possibly fused) chain. `block_transform_time_s` says what it measures: the time to transform one output block. `ds.stats()` prints "Block transform time". This is a user-visible rename, so it lands on its own: - `BlockExecStats.udf_time_s` -> `block_transform_time_s` - `OperatorStatsSummary.udf_time` -> `block_transform_time` - `OpRuntimeMetrics.udf_time_s` -> `block_transform_time_s`, so the Prometheus metric is `ray_data_block_transform_time_s` - the `* UDF time:` line in `ds.stats()` -> `* Block transform time:` The metric is the reason to do it now rather than later: this PR introduces it, so nothing is scraping `ray_data_udf_time_s` yet. The other three names predate the PR, and renaming them changes a printed label, a summary attribute and an `extra_metrics` key. `block.py` and `MapTransformPhaseTimes` keep a note of the old name, so the rename is discoverable from the code rather than only from git. `udf_body_time_s` keeps its name here: it really is the UDF bodies. The next commit widens it and renames it accordingly. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Justin's side note on the restructure thread: built-in stages should be
treated the same as UDFs, since a read or a write is a function like any
other and doesn't need its own breakdown.
`MapTransformPhase.OTHER` is gone, so a stage body lands in
`FUNCTION_BODY` whoever wrote it. `udf_body_*` becomes `function_body_*`
throughout, because the figure no longer covers only UDF bodies, and
`other_stage_time_s` disappears from `BlockExecStats`,
`OpRuntimeMetrics` and `OperatorStatsSummary`. The breakdown is three
lines rather than four.
That drops the "print at 0.0?" flag the rendering carried: it existed
only so `Built-in stages` could hide itself on a chain with no built-in
stage fused in. All three remaining lines always print, so `breakdown`
is a list of pairs and the loop is one condition shorter.
The same pipeline as the doc's worked example, before and after:
before after
* Block transform time: 697.95ms total * Block transform time: 648.79ms total
* Input prep: 3.19ms * Input prep: 1.69ms
* Function body: 616.17ms * Function body: 645.66ms
* Output block build: 2.61ms * Output block build: 1.44ms
* Built-in stages: 75.99ms
What this costs, stated plainly: `Function body` now mixes ReadRange and
Project in with map1 and map2, so "my code or Ray Data's?" is no longer
answerable from the breakdown. `TimedStep.stage_idx` already carries what
answers it properly, per stage and by name, which is #65810.
Also renames a `udf_stats` local the previous commit missed.
Signed-off-by: Marwan Sarieddine <marwan@anyscale.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa
Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes using default effort and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit c3e49a8. Configure here.
…ering
`apply_transform` used to skip timing when no stage in the chain was a
UDF, so a standalone read or write reported nothing. That made sense when
the figure was called "UDF time"; under `block_transform_time_s` it reads
as a gap, and a read's body is a function like a UDF's. The gate is gone,
along with `MapTransformFn`'s `is_udf` parameter, which nothing else read
once `FUNCTION_BODY` stopped depending on it.
Removing the gate exposed a real ordering bug rather than just widening
coverage, and this is the part worth reviewing. The untimed path applied
every stage eagerly:
for step in steps:
data = step.apply(data)
`TransformClock.chain` instead defers each `apply` to the first pull,
which is what lets it measure a datasink that uploads inside `apply`. The
checkpoint write chain is prepare -> write -> commit, and
`commit_checkpoints` read `ctx.kwargs` **before** consuming its input, so
with the applies deferred it ran first, found no pending checkpoints, and
committed nothing. The pending checkpoint was written and never
committed, so recovery treated the run's data files as orphaned:
4 failed, 56 passed test_checkpoint.py
test_partial_failure_no_duplicates
test_partial_failure_no_duplicates_partitioned
test_2pc_fail_retry_cleans_pending_checkpoints
test_checkpoint_restore_after_full_execution
`commit_checkpoints` now drains upstream before reading `ctx`, which is
what "AFTER the data write succeeds" means -- the write is upstream, so
consuming its output is what waits for it. That is already how
`generate_collect_write_stats_fn` does it on the non-checkpoint write
path, which is why that one was unaffected. Back to 60 passed.
`test_operator_without_a_udf_reports_no_block_transform_time` becomes
`test_operator_without_a_udf_is_still_timed`, and asserts the phases are
measured, that they sum to the total, and that the total stays inside the
task's wall time.
Signed-off-by: Marwan Sarieddine <marwan@anyscale.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa
Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
Cursor Bugbot: the three phase metrics were summed with `or 0`, so a
default `map` or `filter` -- which is timed as a whole rather than phase
by phase -- exported three zeros beside a non-zero
`block_transform_time_s`. A dashboard couldn't tell that from "these
phases took no time", and the zeros don't add up to the total.
`BlockExecStats` and `OperatorStatsSummary` already keep the distinction;
only `OpRuntimeMetrics` flattened it. The three are `Optional[float]`
defaulting to `None` now, and accumulation skips a `None` rather than
adding zero for it, so they stay absent until a block reports a phase.
`Optional` metrics are already routine here -- `average_num_outputs_per_task`
and friends return `None` before any task finishes, through the same
export path.
Measured, same three pipelines:
row map (default) total=0.0024 prep=None body=None build=None
map_batches total=0.00052 prep=0.000168 body=0.000109 build=0.000239
row map (flag on) total=0.00054 prep=0.000082 body=0.000110 build=0.000350
The two measured rows sum to their totals; the first no longer claims to.
`test_phase_metrics_stay_none_when_unmeasured` covers it and fails on the
old `or 0`, with `test_phase_metrics_accumulate_when_measured` guarding
the other direction. The stats repr tests canonicalize `None` alongside
the numbers, as they already did to keep sub-microsecond figures stable.
Also documents the four metrics in the Task metrics table, which this PR
had added to Prometheus without listing.
Signed-off-by: Marwan Sarieddine <marwan@anyscale.com>
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa
Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
`TransformClock.chain` runs nothing until the result is pulled, which is what puts an eagerly consuming stage's work inside a timed window. The requirement that places on a stage was implicit, and the checkpoint 2PC break in c89db16 was the first thing to violate it: a stage that depends on an upstream stage's side effects has to consume upstream to get them. Stating it at the mechanism rather than only at the one victim, and naming both transforms that drain first so the next author has an example. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
|
@iamjustinhsu this has moved a lot since your review — worth re-reading the description rather than the old threads.
Four things need your call; they're listed under What needs review in the description. |
Six lines to say one thing. The reader at that line only needs to know why `list(blocks)` isn't dead code, given the function returns `blocks` anyway: pulling upstream is what makes the prepare stage run. The rest of what the old comment said is on `TransformClock.chain`, where it applies to every stage rather than just this one. Signed-off-by: Marwan Sarieddine <marwan@anyscale.com> Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01FfAW6hXHCMinYkJ3W7nfBa Signed-off-by: Marwan Sarieddine <sarieddine.marwan@gmail.com>
dstrodtman
left a comment
There was a problem hiding this comment.
Docs-team style pass from Douglas Strodtman (Anyscale docs). Claude Code assisted; I read every comment below and stand behind each one.
Scope: prose style, grammar, and docs conventions only. I'm deliberately staying out of the naming (UDF time → Block transform time) and the phase-model questions in @iamjustinhsu's open threads — those are the Data team's call, and they look like they're still in motion. The new prose reads clearly; the notes below are all mechanical.
Four small fixes inline, all serial-comma and filler-word nits against the Google developer style guide (Ray's stated fallback for anything the Ray writing-style guide doesn't cover). Nothing here blocks — take or leave each individually. No technical review implied, and no approval: a Data maintainer is already reviewing.
| etc. You can use this stat to track the time spent in functions you define and how much time optimizing those functions could save. | ||
| * **Block transform time**: The time an operator spends transforming data, which Ray Data measures **per output block**. The min, max, and | ||
| mean are therefore across blocks, and the total is the operator's. This isn't the same as the task's total time, which also | ||
| covers scheduling and writing blocks to the object store. Read, write and map operators all report it, because a read and a |
There was a problem hiding this comment.
Serial comma: with three items, put a comma before the final and (Google developer style guide).
| covers scheduling and writing blocks to the object store. Read, write and map operators all report it, because a read and a | |
| covers scheduling and writing blocks to the object store. Read, write, and map operators all report it, because a read and a |
| the functions you passed in and the ones Ray Data supplies, such as a read or a write that Ray Data fused into the same | ||
| operator, because a read or a write is a function like any other. | ||
| * **Output block build**: Time spent assembling what your functions return back into blocks, including materializing Python | ||
| objects into Arrow. Note that this is separate from the object store write, which Ray Data reports as the |
There was a problem hiding this comment.
Note that is filler — the sentence is just as clear without it.
| objects into Arrow. Note that this is separate from the object store write, which Ray Data reports as the | |
| objects into Arrow. This is separate from the object store write, which Ray Data reports as the |
|
|
||
| Every figure covers all four stages: | ||
|
|
||
| * **Function body** holds all four stage bodies: ``ReadRange``, ``Project``, ``map1`` and ``map2``. Two tasks each slept 0.1 |
There was a problem hiding this comment.
Serial comma before the final and in the four-item list.
| * **Function body** holds all four stage bodies: ``ReadRange``, ``Project``, ``map1`` and ``map2``. Two tasks each slept 0.1 | |
| * **Function body** holds all four stage bodies: ``ReadRange``, ``Project``, ``map1``, and ``map2``. Two tasks each slept 0.1 |
| to complete. As there are potentially multiple concurrent operators, these percentages don't necessarily sum to 100%. Instead, | ||
| they show how long running each of the operators is in the context of the full dataset execution. | ||
| * **Block transform time breakdown**: Ray Data splits each operator's **block transform time**, which it measures per output | ||
| block, into the input prep, function body and output block build phases, so you can see which part of the transform the |
There was a problem hiding this comment.
Serial comma before the final and.
| block, into the input prep, function body and output block build phases, so you can see which part of the transform the | |
| block, into the input prep, function body, and output block build phases, so you can see which part of the transform the |

Why are these changes needed?
ds.stats()reports one figure per operator for a map stage's transform and calls it "UDF time". It isn't the user's function: it spans turning input blocks into batches or rows, calling the function, and assembling the output back into blocks. So a slow operator tells you nothing about whether to optimise your code or your data layout.That bites hardest when rows carry Python objects, because both ends of the window get expensive. A UDF that never reads an object column is still charged for unpickling it, and nothing in the output says so.
What this change does
Renames the figure to say what it measures, and breaks it down.
ds.stats()prints* Block transform time:where it printed* UDF time:, and underverbose_stats_logssplits it into three lines that sum to it:The total and all three phases are
metric_fields onOpRuntimeMetrics, so they reach Prometheus per operator taggeddatasetandoperator. The three phases stayNonerather than zero when a chain is timed only as a whole, so a dashboard can tell "not measured" from "took no time".Default output is unchanged: the breakdown renders only under
verbose_stats_logs, the same treatmentextra_metricsgets, and the figures are always onget_stats_summary()regardless. Row transforms (map,filter) report only a total by default, since a timer per row costs roughly 0.6µs across a three-stage chain;DataContext.accurate_map_phase_timingopts them in.The docs gain a worked example that runs a fused
ReadRange->Project->MapBatches(map1)->MapBatches(map2)and reads the three figures off its output, because "which stages land in which bucket?" was the first thing review asked.Under the hood
map_transformer.pyis rewritten by #65855, merged in here: a task's transform is now a flat list ofTimedSteps you can print and assert on, each timing itself with no coordination. Subtracting neighbouring totals once at drain recovers each step's own work, at 580 ns/item against the 1016 the per-item cursor cost.Timing is no longer gated on the chain containing a UDF, so reads and writes are measured too and
MapTransformFn.is_udfis gone, along with the separateBuilt-in stagesbucket. Removing the gate surfaced an ordering bug in the checkpoint 2PC chain, fixed in c89db16.What needs review
ray_data_block_transform_time_sis introduced here, so it is free to change now and expensive after a release. @iamjustinhsu suggestedtotal_task_per_block_s.Built-in stagesintoFunction bodycosts the "my code or Ray Data's?" split until per-stage attribution lands in [Data] Report UDF time per fused stage, behind a flag #65810. @iamjustinhsu asked for it; worth confirming the interim is fine.ds.stats()output for every read operator.Related issue number
None. Closed #55052 raised adjacent complaints about operator-level metric granularity and was addressed by
ds.explain(); it did not cover this.Checks
git commit -s).scripts/format.shto lint the changes in this PR.DataContext.accurate_map_phase_timingis documented in theDataContextdocstring; no new public API)Testing
Eight tests added:
test_block_transform_time_phases_sum_to_the_totaltest_block_transform_time_phases_separate_object_serdetest_row_transform_phases_are_opt_intest_eagerly_consuming_stage_body_is_timedFunction bodyinstead of being reported as microsecondstest_operator_without_a_udf_is_still_timedtest_map_transformer.py::test_every_output_block_is_timedtest_op_runtime_metrics.py::test_phase_metrics_stay_none_when_unmeasuredtest_op_runtime_metrics.py::test_phase_metrics_accumulate_when_measuredNonedefault doesn't swallow a measured phaseExisting tests that assert on the rendered
ds.stats()string keep their non-verbose expectations unchanged, which is what gating the breakdown buys; the verbose ones gained three lines. The newOpRuntimeMetricskeys are canonicalized to a placeholder in those expectations, asobj_store_mem_usedalready is, because a trivial UDF's phases round to zero or not depending on the run.Run locally against a source build, with
PYTHONPATH=python/ray/data/tests:test_stats.pytest_map.pytest_checkpoint.pytest_consumption.pytest_map_transformer.py,unit/test_auto_batch_size.py,test_op_runtime_metrics.py,test_context.pydatasource/{test_datasink,test_file_datasink,test_parquet}.pyEvery failure above was A/B'd against master and traces to something absent from my machine rather than to this change: the dashboard API server isn't running, pandas 3.0 breaks an untouched conversion helper, and the rest are s3 fixtures.
pre-commit run --all-filespasses.AI assistance
AI assistance (Claude Code) was used to investigate the attribution gap, write the change and the tests, and draft this description. Per
AGENTS.md, the author has reviewed every changed line and the tests reported above were run locally.Duplicate check
gh pr list --repo ray-project/ray --state openwas searched forudf time phase breakdown input prepandmap_transformer phase timing; neither returns anything. The open PRs touching nearby code — #61379 (caching the serialized map transformer), #64090 (per-actor placement groups), #65663 (exposing backpressure policy in diagnostics) — do not touch this timing.