buhuipao opened a new pull request, #76885: URL: https://github.com/apache/airflow/pull/76885
The triggerer supervisor watches its runner subprocess. When it has not handled a message from the runner for `[triggerer] runner_health_check_threshold` seconds (30 by default), it logs "TriggerRunner subprocess event loop appears deadlocked" and skips its heartbeat, so that the triggerer looks unhealthy and its triggers are reassigned. That time also includes the supervisor's own work, so a healthy runner can be reported as deadlocked: * A loop pass reads the runner's sockets once, then does its database work (`handle_events`, `handle_failed_triggers`, `clean_unused`), and only then runs the check. If that work takes longer than the threshold, for example because many triggers fired at once, the check fails. The runner's next request is already waiting in the socket at that moment. * The timestamp is taken when the supervisor starts to handle a request. Slow handling, such as the remote log upload for many finished triggers, counts as runner silence, although the runner is only waiting for the reply. The error then points at trigger code when the cause is a slow database or a slow log upload, and a triggerer that works goes without a heartbeat for as long as its loop stays slow. The heartbeat is what `/health`, `airflow jobs check` and the reassignment of triggers look at. This change: * takes the timestamp when the handling of a request ends, whether it was answered or failed; * treats data that is waiting unread on the runner's request socket as a sign that the runner is not silent. Other output does not count: requests are written by the runner's event loop, which is what the watchdog is about, while log lines can also come from other threads. A runner that really stops is still reported. Nothing arrives on its request socket, and the time since the last handled request keeps growing. One limit remains. The supervisor reads one request per loop pass, so if the runner stops while several of its requests are still unread and every pass is slower than the threshold, the report comes that many passes later. #76423 drains the waiting requests in each pass, which shortens this delay. related: #76423. That PR keeps the runner from blocking on its log socket and does not change the watchdog. The two changes merge without conflict. #### Reproduction I ran the real `TriggerRunnerSupervisor` and runner process with only the database calls replaced: recording one trigger event sleeps 30 ms instead of calling `Trigger.submit_event`. Waves of 1,200 `DateTimeTrigger`s fire at the same moment, so a loop pass that receives a whole wave spends about 40 s on events. The logging level is WARNING, so runner logs play no part. The same script ran against `main` and against this change, 3 runs each, in Breeze (Linux, Python 3.11). 3 waves, 50 s apart, so the loop catches up between waves: | | main | this PR | |---|---|---| | Loop passes with more than 30 s of event handling | 3, 1, 1 | 2, 2, 3 | | "appears deadlocked" errors | 3, 1, 1 | 0, 0, 0 | | Heartbeats skipped | 3, 1, 1 | 0, 0, 0 | | Skipped heartbeats with a runner request waiting unread | 3, 1, 1 | none skipped | 4 waves, 20 s apart, so the loop has 3 slow passes in a row: | | main | this PR | |---|---|---| | "appears deadlocked" errors (logged once per silent period) | 1, 1, 1 | 0, 0, 0 | | Heartbeats skipped | 3, 3, 3 | 0, 0, 0 | | Longest time without a heartbeat | 122 s, 122 s, 123 s | 41 s, 41 s, 41 s | The same runs on macOS gave the same picture: every skipped heartbeat on `main` had a runner request waiting unread, and this change skipped none. #### Cost `heartbeat()` runs once per loop pass and the request path once per runner request. Time per call, medians of 3 alternating runs of the same script (macOS, Python 3.13): | | main | this PR | change | |---|---|---|---| | `handle_requests()` for one `TriggerStateChanges` frame | 4,513 ns | 4,464 ns | -1.1% | | `heartbeat()` with a talking runner | 694 ns | 704 ns | +1.4% | | control: `handle_events()` with no events | 26.2 ns | 26.6 ns | +1.5% | | control: `send_msg(TriggerStateSync)` | 1,290 ns | 1,350 ns | +4.6% | The differences are within the noise that the controls show. The socket check only runs when the threshold is already exceeded. #### Tests run * 3 of the 4 new test cases fail on `main` and pass with this change. The fourth is a control: unread log output alone does not count as a sign of life. Each case fails again when its part of the change is taken out. * `breeze testing core-tests --use-xdist --skip-db-tests --no-db-cleanup --backend none --parallel-test-types "API Always CLI Core Other Serialization"`: 5743 passed, 11 skipped, 2 xfailed. * `breeze testing core-tests --run-in-parallel --run-db-tests-only --backend sqlite --parallel-test-types "API Always CLI Core Other Serialization"`: all 6 test types passed (12,904 passed, 92 skipped). * `breeze build-docs apache-airflow task-sdk`: successful. * `prek run --from-ref upstream/main --stage pre-commit` and `--stage manual`: passed, including mypy for `airflow-core`. --- ##### Was generative AI tooling used to co-author this PR? - [X] Yes — Claude Code (Fable 5.2) Generated-by: Claude Code (Fable 5.2) following [the guidelines](https://github.com/apache/airflow/blob/main/contributing-docs/05_pull_requests.rst#gen-ai-assisted-contributions) -- This is an automated message from the Apache Git Service. To respond to the message, please log on to GitHub and use the URL above to go to the specific comment. To unsubscribe, e-mail: [email protected] For queries about this service, please contact Infrastructure at: [email protected]
