Fix broken `dag_processing.total_parse_time` metric by nickstenning · Pull Request #62128 · apache/airflow

nickstenning · 2026-02-18T14:35:21Z

DagFileProcessorManager has been emitting a nonsense value for dag_processing.total_parse_time since 8774f28, which reversed the order in which emit_metrics and prepare_file_queue (then called prepare_file_path_queue) were called.

As prepare_file_queue was responsible for resetting the value of self._parsing_start_time, the assumption made by emit_metrics was that it would be called once the file queue had been cleared, but crucially before prepare_file_queue was called to refill the queue.

Additionally, there was no guarantee that we'd parsed any files at all since the last time the metric was emitted. If no work was due, we'd gladly emit near-zero metrics every time around the while loop.

I've rearranged things in such a way that I hope will be harder to accidentally break in future:

self._parsing_start_time may be reset whenever files are added to the queue, if it was not set already.
metrics are emitted when prepare_file_queue is called -- when the queue is empty -- but only if self._parsing_start_time is set, meaning only if we've actually parsed any files since the last time metrics were emitted.

Together, this means we should now emit metrics once per parsing loop. I've added a test which fails on main and passes on this branch.

nickstenning · 2026-02-20T14:45:00Z

Updated with a test and some slightly more invasive fixes, because it turns out this was even more broken than I thought! @kaxil PTAL.

DagFileProcessorManager has been emitting a nonsense value for `dag_processing.total_parse_time` since 8774f28, which reversed the order in which `emit_metrics` and `prepare_file_queue` (then called `prepare_file_path_queue`) were called. As `prepare_file_path_queue` was responsible for resetting the value of `self._parsing_start_time`, the assumption made by `emit_metrics` was that it would be called once the file queue had been cleared, but crucially before `prepare_file_queue` was called to refill the queue. Additionally, there was no guarantee that we'd parsed any files at all since the last time the metric was emitted. If no work was due, we'd gladly emit near-zero metrics every time around the while loop. I've rearranged things in such a way that I hope will be harder to accidentally break in future: - `self._parsing_start_time` may be reset whenever files are added to the queue, if it was not set already. - metrics are emitted when `prepare_file_queue` is called -- when the queue is empty -- but only if `self._parsing_start_time` is set, meaning only if we've actually parsed any files since the last time metrics were emitted. Together, this means we should now emit metrics once per parsing loop. I've added a test which fails on main and passes on this branch.

nickstenning · 2026-02-20T20:05:15Z

Thanks for re-review @kaxil. Should be ready to merge once CI passes.

nickstenning · 2026-02-20T22:46:33Z

If someone could rerun the tests that would be ace. Looks like a flake to me.

DagFileProcessorManager has been emitting a nonsense value for `dag_processing.total_parse_time` since 8774f28, which reversed the order in which `emit_metrics` and `prepare_file_queue` (then called `prepare_file_path_queue`) were called. As `prepare_file_path_queue` was responsible for resetting the value of `self._parsing_start_time`, the assumption made by `emit_metrics` was that it would be called once the file queue had been cleared, but crucially before `prepare_file_queue` was called to refill the queue. Additionally, there was no guarantee that we'd parsed any files at all since the last time the metric was emitted. If no work was due, we'd gladly emit near-zero metrics every time around the while loop. I've rearranged things in such a way that I hope will be harder to accidentally break in future: - `self._parsing_start_time` may be reset whenever files are added to the queue, if it was not set already. - metrics are emitted when `prepare_file_queue` is called -- when the queue is empty -- but only if `self._parsing_start_time` is set, meaning only if we've actually parsed any files since the last time metrics were emitted. Together, this means we should now emit metrics once per parsing loop. I've added a test which fails on main and passes on this branch.

DagFileProcessorManager has been emitting a nonsense value for `dag_processing.total_parse_time` since 8774f28, which reversed the order in which `emit_metrics` and `prepare_file_queue` (then called `prepare_file_path_queue`) were called. As `prepare_file_path_queue` was responsible for resetting the value of `self._parsing_start_time`, the assumption made by `emit_metrics` was that it would be called once the file queue had been cleared, but crucially before `prepare_file_queue` was called to refill the queue. Additionally, there was no guarantee that we'd parsed any files at all since the last time the metric was emitted. If no work was due, we'd gladly emit near-zero metrics every time around the while loop. I've rearranged things in such a way that I hope will be harder to accidentally break in future: - `self._parsing_start_time` may be reset whenever files are added to the queue, if it was not set already. - metrics are emitted when `prepare_file_queue` is called -- when the queue is empty -- but only if `self._parsing_start_time` is set, meaning only if we've actually parsed any files since the last time metrics were emitted. Together, this means we should now emit metrics once per parsing loop. I've added a test which fails on main and passes on this branch. (cherry picked from commit 57a7c64)

…) (#62764) * Fix broken `dag_processing.total_parse_time` metric (#62128) DagFileProcessorManager has been emitting a nonsense value for `dag_processing.total_parse_time` since 8774f28, which reversed the order in which `emit_metrics` and `prepare_file_queue` (then called `prepare_file_path_queue`) were called. As `prepare_file_path_queue` was responsible for resetting the value of `self._parsing_start_time`, the assumption made by `emit_metrics` was that it would be called once the file queue had been cleared, but crucially before `prepare_file_queue` was called to refill the queue. Additionally, there was no guarantee that we'd parsed any files at all since the last time the metric was emitted. If no work was due, we'd gladly emit near-zero metrics every time around the while loop. I've rearranged things in such a way that I hope will be harder to accidentally break in future: - `self._parsing_start_time` may be reset whenever files are added to the queue, if it was not set already. - metrics are emitted when `prepare_file_queue` is called -- when the queue is empty -- but only if `self._parsing_start_time` is set, meaning only if we've actually parsed any files since the last time metrics were emitted. Together, this means we should now emit metrics once per parsing loop. I've added a test which fails on main and passes on this branch. (cherry picked from commit 57a7c64) * fix static checks --------- Co-authored-by: Nick Stenning <nick@whiteink.com>

DagFileProcessorManager has been emitting a nonsense value for `dag_processing.total_parse_time` since 8774f28, which reversed the order in which `emit_metrics` and `prepare_file_queue` (then called `prepare_file_path_queue`) were called. As `prepare_file_path_queue` was responsible for resetting the value of `self._parsing_start_time`, the assumption made by `emit_metrics` was that it would be called once the file queue had been cleared, but crucially before `prepare_file_queue` was called to refill the queue. Additionally, there was no guarantee that we'd parsed any files at all since the last time the metric was emitted. If no work was due, we'd gladly emit near-zero metrics every time around the while loop. I've rearranged things in such a way that I hope will be harder to accidentally break in future: - `self._parsing_start_time` may be reset whenever files are added to the queue, if it was not set already. - metrics are emitted when `prepare_file_queue` is called -- when the queue is empty -- but only if `self._parsing_start_time` is set, meaning only if we've actually parsed any files since the last time metrics were emitted. Together, this means we should now emit metrics once per parsing loop. I've added a test which fails on main and passes on this branch.

nickstenning requested review from ephraimbuddy and jedcunningham as code owners February 18, 2026 14:35

boring-cyborg Bot added the area:DAG-processing label Feb 18, 2026

kaxil reviewed Feb 18, 2026

View reviewed changes