CreeperBeatz commented on PR #70690:
URL: https://github.com/apache/airflow/pull/70690#issuecomment-5662117805
Independent production reproduction of this, on released versions, in case a
real-world
data point is useful while the PR is under review.
**Versions:** Airflow 3.3.0, `apache-airflow-providers-celery` 3.21.0,
celery 5.6.3,
kombu 5.6.2, redis-py 6.4.0, Python 3.12, 6 cores, redis broker local to the
scheduler,
Postgres result backend. `[celery] sync_parallelism` unset, so it resolved to
`max(1, cpu_count()-1)` = 5.
The scheduler stopped scheduling at 08:20:09 UTC and stayed wedged for 23
minutes until
restarted by hand. Its last log line is the enqueue itself:
```
08:20:09 Trying to enqueue tasks: [...] for executor:
CeleryExecutor(parallelism=256)
```
Rather than py-spy I captured `/proc/<pid>/stack` from the host, which shows
the same
thing from the kernel side and may be a useful complement to the dump in the
description:
```
child 2747820 -- Threads: 1
[<0>] futex_do_wait+0x3a/0x70 <-- waiting on a lock, but the process
has ONE thread,
[<0>] __futex_wait+0x99/0x100 so no thread in it can ever release
that lock
[<0>] futex_wait+0x72/0x120
child 2747819 -- Threads: 1
[<0>] ksys_read+0xc6/0xf0 <-- blocked reading the result pipe
parent 2774404 -- Threads: 2
[<0>] futex_do_wait+0x3a/0x70 <-- waiting on the pool
```
Both children were forked at 08:20:10, matching the last log line exactly.
The single-thread
child blocked in `futex_wait` is, I think, the clearest possible signature
of the inherited-lock
mechanism described here: there is no owning thread left in that process to
release it.
Supporting evidence that nothing else was involved:
- redis healthy: 2.6 MB used, every queue at depth 0,
`rejected_connections:0` - the
workloads were never published
- Postgres: no lock waits, no long-running queries, connection count well
under the limit
- `SchedulerJob` heartbeat age 1036 s, while `TriggererJob` and
`DagProcessorJob` on the same
host kept beating every 5-7 s
- the host itself was not resource constrained - CPU load and free memory
both well within
normal for this deployment
Two notes that may be worth folding into the docs part of this change:
**1. Nothing can restart a scheduler in this state**
The process never exits, so a container restart policy never
fires and the orchestrator reports a perfectly healthy container throughout.
Meanwhile
`[scheduler] enable_health_check` defaults to `False`, so there is no
scheduler-side
liveness signal either, and the webserver's `/api/v2/monitor/health` kept
reporting the
scheduler healthy right up until we queried the `Job` heartbeat directly.
The failure is
therefore invisible to every automatic recovery path at once, and only
manual intervention
ended it. A line in the docs pointing out that this hang cannot be caught
without
`enable_health_check` (or an `airflow jobs check --job-type SchedulerJob`
probe) would have
saved us the outage.
**2. `[celery] sync_parallelism = 1` is an effective mitigation on the
released versions above, and is what we deployed.**
It takes the existing in-process branch and never forks,
so the hazard is gone rather than made less likely. Worth noting the cost is
close to zero
in a setup like ours: publishing is one short round-trip to a local broker,
`[scheduler] max_tis_per_query` defaults to 16 so batches are far below
where a pool could
pay back its own startup, and with a `DatabaseBackend` result backend
`BulkStateFetcher`
already uses the bulk `SELECT ... WHERE task_id IN (...)` path, so lowering
it has no effect
on state fetching at all. That last point may be worth stating explicitly
for anyone on an
affected version who wants to mitigate before this lands.
--
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]
