|
| 1 | +// Licensed to the Apache Software Foundation (ASF) under one |
| 2 | +// or more contributor license agreements. See the NOTICE file |
| 3 | +// distributed with this work for additional information |
| 4 | +// regarding copyright ownership. The ASF licenses this file |
| 5 | +// to you under the Apache License, Version 2.0 (the |
| 6 | +// "License"); you may not use this file except in compliance |
| 7 | +// with the License. You may obtain a copy of the License at |
| 8 | +// |
| 9 | +// http://www.apache.org/licenses/LICENSE-2.0 |
| 10 | +// |
| 11 | +// Unless required by applicable law or agreed to in writing, |
| 12 | +// software distributed under the License is distributed on an |
| 13 | +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY |
| 14 | +// KIND, either express or implied. See the License for the |
| 15 | +// specific language governing permissions and limitations |
| 16 | +// under the License. |
| 17 | + |
| 18 | +//! Diagnostic instrumentation for tokio `RwLock` hot paths in the scheduler. |
| 19 | +//! |
| 20 | +//! Wraps `RwLock::write().await` and `RwLock::read().await` with timing |
| 21 | +//! around acquire (time-to-acquire) and hold (time-from-acquire-to-drop). |
| 22 | +//! Both thresholds surface as `warn!` logs so a stuck or slow path is |
| 23 | +//! visible without overwhelming the log in healthy operation. |
| 24 | +//! |
| 25 | +//! Added while investigating spiceai/spiceai#10832 — the scheduler's |
| 26 | +//! `QueryStageScheduler` event loop wedges mid-query, and three call paths |
| 27 | +//! share the per-job `execution_graph` write lock. The pattern matches a |
| 28 | +//! leaked or never-released `RwLockWriteGuard`. Instrumenting these |
| 29 | +//! acquisitions identifies (a) which call site holds the lock, (b) for how |
| 30 | +//! long, and (c) whether the contention is at acquire-time or hold-time. |
| 31 | +
|
| 32 | +use std::ops::{Deref, DerefMut}; |
| 33 | +use std::time::{Duration, Instant}; |
| 34 | + |
| 35 | +use log::warn; |
| 36 | +use tokio::sync::{RwLock, RwLockReadGuard, RwLockWriteGuard}; |
| 37 | + |
| 38 | +/// Threshold for slow acquisitions. Healthy paths acquire in microseconds; |
| 39 | +/// over 100ms means real contention. |
| 40 | +const SLOW_ACQUIRE_THRESHOLD: Duration = Duration::from_millis(100); |
| 41 | + |
| 42 | +/// Threshold for slow holds. A graph write lock held for over 500ms is |
| 43 | +/// suspicious — the critical sections under it are in-memory bookkeeping |
| 44 | +/// plus DashMap operations. |
| 45 | +const SLOW_HOLD_THRESHOLD: Duration = Duration::from_millis(500); |
| 46 | + |
| 47 | +/// Acquires a write lock on `lock`, logging if either acquisition or |
| 48 | +/// release takes longer than the slow thresholds. |
| 49 | +/// |
| 50 | +/// `label` should identify the call site, e.g. `"task_manager::update_job"`. |
| 51 | +pub async fn traced_write<'a, T>( |
| 52 | + lock: &'a RwLock<T>, |
| 53 | + label: &'static str, |
| 54 | +) -> TracedWriteGuard<'a, T> { |
| 55 | + let acquire_start = Instant::now(); |
| 56 | + let guard = lock.write().await; |
| 57 | + let acquire = acquire_start.elapsed(); |
| 58 | + if acquire >= SLOW_ACQUIRE_THRESHOLD { |
| 59 | + warn!( |
| 60 | + "slow rwlock_write acquire: label={label} acquire_ms={}", |
| 61 | + acquire.as_millis() |
| 62 | + ); |
| 63 | + } |
| 64 | + TracedWriteGuard { |
| 65 | + guard, |
| 66 | + held_since: Instant::now(), |
| 67 | + label, |
| 68 | + } |
| 69 | +} |
| 70 | + |
| 71 | +/// Acquires a read lock on `lock`, logging if either acquisition or release |
| 72 | +/// takes longer than the slow thresholds. |
| 73 | +pub async fn traced_read<'a, T>( |
| 74 | + lock: &'a RwLock<T>, |
| 75 | + label: &'static str, |
| 76 | +) -> TracedReadGuard<'a, T> { |
| 77 | + let acquire_start = Instant::now(); |
| 78 | + let guard = lock.read().await; |
| 79 | + let acquire = acquire_start.elapsed(); |
| 80 | + if acquire >= SLOW_ACQUIRE_THRESHOLD { |
| 81 | + warn!( |
| 82 | + "slow rwlock_read acquire: label={label} acquire_ms={}", |
| 83 | + acquire.as_millis() |
| 84 | + ); |
| 85 | + } |
| 86 | + TracedReadGuard { |
| 87 | + guard, |
| 88 | + held_since: Instant::now(), |
| 89 | + label, |
| 90 | + } |
| 91 | +} |
| 92 | + |
| 93 | +/// Write guard that logs at warn level if the lock is held longer than |
| 94 | +/// `SLOW_HOLD_THRESHOLD`. |
| 95 | +pub struct TracedWriteGuard<'a, T> { |
| 96 | + guard: RwLockWriteGuard<'a, T>, |
| 97 | + held_since: Instant, |
| 98 | + label: &'static str, |
| 99 | +} |
| 100 | + |
| 101 | +impl<T> Deref for TracedWriteGuard<'_, T> { |
| 102 | + type Target = T; |
| 103 | + fn deref(&self) -> &T { |
| 104 | + &self.guard |
| 105 | + } |
| 106 | +} |
| 107 | + |
| 108 | +impl<T> DerefMut for TracedWriteGuard<'_, T> { |
| 109 | + fn deref_mut(&mut self) -> &mut T { |
| 110 | + &mut self.guard |
| 111 | + } |
| 112 | +} |
| 113 | + |
| 114 | +impl<T> Drop for TracedWriteGuard<'_, T> { |
| 115 | + fn drop(&mut self) { |
| 116 | + let held = self.held_since.elapsed(); |
| 117 | + if held >= SLOW_HOLD_THRESHOLD { |
| 118 | + warn!( |
| 119 | + "slow rwlock_write hold: label={} hold_ms={}", |
| 120 | + self.label, |
| 121 | + held.as_millis() |
| 122 | + ); |
| 123 | + } |
| 124 | + } |
| 125 | +} |
| 126 | + |
| 127 | +/// Read guard that logs at warn level if the lock is held longer than |
| 128 | +/// `SLOW_HOLD_THRESHOLD`. |
| 129 | +pub struct TracedReadGuard<'a, T> { |
| 130 | + guard: RwLockReadGuard<'a, T>, |
| 131 | + held_since: Instant, |
| 132 | + label: &'static str, |
| 133 | +} |
| 134 | + |
| 135 | +impl<T> Deref for TracedReadGuard<'_, T> { |
| 136 | + type Target = T; |
| 137 | + fn deref(&self) -> &T { |
| 138 | + &self.guard |
| 139 | + } |
| 140 | +} |
| 141 | + |
| 142 | +impl<T> Drop for TracedReadGuard<'_, T> { |
| 143 | + fn drop(&mut self) { |
| 144 | + let held = self.held_since.elapsed(); |
| 145 | + if held >= SLOW_HOLD_THRESHOLD { |
| 146 | + warn!( |
| 147 | + "slow rwlock_read hold: label={} hold_ms={}", |
| 148 | + self.label, |
| 149 | + held.as_millis() |
| 150 | + ); |
| 151 | + } |
| 152 | + } |
| 153 | +} |
0 commit comments