Skip to content

Commit 1d9be2e

Browse files
authored
feat: log drift between MemoryPool reservations and allocated bytes in SLT (#25651)
## Which issue does this PR close? - Part of #25650. ## Rationale for this change `MemoryPool` accounting only covers memory that operators explicitly reserve, so a process can be OOM killed while the pool reports plenty of headroom. As a first step, this makes the gap visible: it logs the difference between what pools have reserved and what's actually allocated, and it's on by default in SLT. It only logs and never fails a test, unlike #22626 which was reverted in #22860. ## What changes are included in this PR? - `datafusion-execution`: `MemoryDriftTracker` and `DriftLoggingPool`. The pool wraps any `MemoryPool` and reports reservation changes to a tracker, which can be shared by many pools. The tracker compares the reserved total against allocated bytes from a caller-supplied `Fn() -> usize`, since DataFusion doesn't choose the global allocator. It logs at `info` each time positive drift rises by 64 MB, naming the pool and consumer, and records the peak. - `sqllogictest`: a `CountingAllocator` global allocator, with every test file's pool wrapped against one process-wide tracker. The peak drift is printed at the end of the run. Disable it with `--memory-drift false`. Test files run concurrently, so the comparison is process-wide rather than per file. Files that `SET datafusion.runtime.memory_limit` replace their pool and drop out of the reserved total (6 of 504 files). Example output from a full local run: ``` Peak memory drift: drift=84.3 MB allocated=85.4 MB reserved=1176.3 KB pool=order.slt consumer=ExternalSorterMerge[0] ``` The allocator batches its counts per thread, so SLT runtime is unchanged locally (7s both with and without it). ## Are these changes tested? Yes. There are unit tests for the tracker and pool, plus a doc test. I also ran the full SLT suite locally with drift logging on and off. ## Are there any user-facing changes? New public types in `datafusion_execution::memory_pool`. No changes to existing APIs.
1 parent 5ecf291 commit 1d9be2e

10 files changed

Lines changed: 706 additions & 6 deletions

File tree

Lines changed: 392 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,392 @@
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+
//! Logs the drift between what [`MemoryPool`]s have reserved and what the
19+
//! process has actually allocated.
20+
//!
21+
//! [`MemoryPool`] accounting is voluntary: only allocations that an operator
22+
//! explicitly reserves are counted. Anything else (in-flight batches, kernel
23+
//! scratch space, untracked buffers) is invisible to the pool, so a process
24+
//! can run out of memory while its pool reports plenty of headroom. See
25+
//! <https://github.com/apache/datafusion/issues/25650>.
26+
//!
27+
//! This module only observes. Nothing here changes how memory is granted or
28+
//! limited; it logs the gap so that operators which under-report can be found.
29+
//!
30+
//! DataFusion is a library and does not choose the global allocator, so the
31+
//! allocated byte count is supplied by the caller, e.g. from a counting
32+
//! [`GlobalAlloc`](std::alloc::GlobalAlloc) wrapper or allocator statistics.
33+
//!
34+
//! [`MemoryPool`]: super::MemoryPool
35+
36+
use std::{
37+
fmt::{Debug, Display, Formatter},
38+
sync::{
39+
Arc,
40+
atomic::{AtomicIsize, AtomicUsize, Ordering},
41+
},
42+
};
43+
44+
use datafusion_common::human_readable_size;
45+
use parking_lot::Mutex;
46+
47+
/// Returns the number of bytes currently allocated by the process.
48+
///
49+
/// This is called on every reservation change (`grow`, `try_grow` and
50+
/// `shrink`) of every pool that reports to the tracker, so it must be cheap,
51+
/// e.g. a single atomic load. Do not read allocator statistics that need a
52+
/// refresh on each call (such as jemalloc's `epoch`).
53+
pub type AllocatedBytesFn = Arc<dyn Fn() -> usize + Send + Sync>;
54+
55+
/// Default rise in drift, in bytes, needed before another line is logged.
56+
pub const DEFAULT_DRIFT_LOG_THRESHOLD: usize = 64 * 1024 * 1024;
57+
58+
/// Compares allocated bytes against the total reserved by every pool that
59+
/// reports to it (see [`PeakRecordingPool::with_drift_tracker`]).
60+
///
61+
/// [`PeakRecordingPool::with_drift_tracker`]: super::PeakRecordingPool::with_drift_tracker
62+
///
63+
/// A single tracker can be shared by many pools, e.g. one pool per
64+
/// `SessionContext` in a process running several at once. The reserved total
65+
/// is then summed across all of them, which is what has to be compared with a
66+
/// process-wide allocated byte count.
67+
///
68+
/// Drift is `allocated - reserved`. A line is logged at `info` level each time
69+
/// drift rises by at least the log threshold, naming the pool and consumer
70+
/// whose reservation change triggered the check.
71+
///
72+
/// # Example
73+
///
74+
/// ```
75+
/// # use std::sync::Arc;
76+
/// # use datafusion_execution::memory_pool::{
77+
/// # MemoryConsumer, MemoryDriftTracker, MemoryPool, PeakRecordingPool, UnboundedMemoryPool,
78+
/// # };
79+
/// // A real caller would read a counting allocator or allocator stats here.
80+
/// let tracker = Arc::new(MemoryDriftTracker::new(Arc::new(|| 10_000)));
81+
/// let pool: Arc<dyn MemoryPool> = Arc::new(
82+
/// PeakRecordingPool::new(Arc::new(UnboundedMemoryPool::default()))
83+
/// .with_drift_tracker(Arc::clone(&tracker), "example"),
84+
/// );
85+
///
86+
/// let reservation = MemoryConsumer::new("op").register(&pool);
87+
/// reservation.grow(4_000);
88+
///
89+
/// assert_eq!(tracker.reserved(), 4_000);
90+
/// assert_eq!(tracker.peak_drift().unwrap().drift, 6_000);
91+
/// ```
92+
pub struct MemoryDriftTracker {
93+
allocated: AllocatedBytesFn,
94+
log_threshold: usize,
95+
/// Total reserved across every pool reporting to this tracker.
96+
reserved: AtomicUsize,
97+
/// Positive drift at the time of the last logged line.
98+
last_logged: AtomicIsize,
99+
/// Largest drift seen.
100+
peak_drift: AtomicIsize,
101+
/// Where the largest drift was seen.
102+
peak: Mutex<Option<DriftSample>>,
103+
}
104+
105+
/// One observation of drift, recorded by [`MemoryDriftTracker`].
106+
#[derive(Debug, Clone, PartialEq, Eq)]
107+
pub struct DriftSample {
108+
/// Label of the pool whose reservation change took this sample, or the source passed to [`MemoryDriftTracker::sample`]. When
109+
/// several pools share a tracker, the untracked memory can come from any
110+
/// of them.
111+
pub pool: String,
112+
/// Consumer whose reservation change took this sample (empty for
113+
/// [`MemoryDriftTracker::sample`]). This shows when drift was sampled,
114+
/// not what caused it.
115+
pub consumer: String,
116+
/// Bytes reserved across all pools reporting to the tracker.
117+
pub reserved: usize,
118+
/// Bytes allocated, as reported by the tracker's [`AllocatedBytesFn`].
119+
pub allocated: usize,
120+
/// `allocated - reserved`.
121+
pub drift: isize,
122+
}
123+
124+
impl Display for DriftSample {
125+
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
126+
let drift = if self.drift < 0 {
127+
format!("-{}", human_readable_size(self.drift.unsigned_abs()))
128+
} else {
129+
human_readable_size(self.drift as usize)
130+
};
131+
write!(
132+
f,
133+
"drift={drift} allocated={} reserved={} pool={} consumer={}",
134+
human_readable_size(self.allocated),
135+
human_readable_size(self.reserved),
136+
self.pool,
137+
self.consumer,
138+
)
139+
}
140+
}
141+
142+
impl MemoryDriftTracker {
143+
/// Create a tracker that reads allocated bytes from `allocated`, logging
144+
/// every [`DEFAULT_DRIFT_LOG_THRESHOLD`] of drift.
145+
pub fn new(allocated: AllocatedBytesFn) -> Self {
146+
Self {
147+
allocated,
148+
log_threshold: DEFAULT_DRIFT_LOG_THRESHOLD,
149+
reserved: AtomicUsize::new(0),
150+
last_logged: AtomicIsize::new(0),
151+
peak_drift: AtomicIsize::new(isize::MIN),
152+
peak: Mutex::new(None),
153+
}
154+
}
155+
156+
/// Log a line each time drift rises by `log_threshold` bytes.
157+
pub fn with_log_threshold(mut self, log_threshold: usize) -> Self {
158+
self.log_threshold = log_threshold;
159+
self
160+
}
161+
162+
/// Bytes currently reserved across all pools reporting to this tracker.
163+
pub fn reserved(&self) -> usize {
164+
self.reserved.load(Ordering::Relaxed)
165+
}
166+
167+
/// The largest drift seen so far, if any reservation has been made.
168+
pub fn peak_drift(&self) -> Option<DriftSample> {
169+
self.peak.lock().clone()
170+
}
171+
172+
/// Compare the current allocated bytes with the reserved total now,
173+
/// without a reservation change.
174+
///
175+
/// Drift is otherwise only sampled when a reservation changes, so memory
176+
/// allocated by code that reserves little can go unseen until some other
177+
/// reservation changes. Calling this periodically, e.g. from a timer,
178+
/// closes that gap. `source` is recorded as the pool label.
179+
pub fn sample(&self, source: &str) {
180+
self.observe(source, "", self.reserved());
181+
}
182+
183+
pub(super) fn grew(&self, pool: &str, consumer: &str, additional: usize) {
184+
let reserved =
185+
self.reserved.fetch_add(additional, Ordering::Relaxed) + additional;
186+
self.observe(pool, consumer, reserved);
187+
}
188+
189+
pub(super) fn shrank(&self, pool: &str, consumer: &str, shrink: usize) {
190+
let reserved = self.reserved.fetch_sub(shrink, Ordering::Relaxed) - shrink;
191+
self.observe(pool, consumer, reserved);
192+
}
193+
194+
/// Returns `true` if a line was logged.
195+
fn observe(&self, pool: &str, consumer: &str, reserved: usize) -> bool {
196+
let allocated = (self.allocated)();
197+
let drift = allocated as isize - reserved as isize;
198+
199+
let sample = || DriftSample {
200+
pool: pool.to_string(),
201+
consumer: consumer.to_string(),
202+
reserved,
203+
allocated,
204+
drift,
205+
};
206+
207+
// Lock-free check first so the lock is only taken for a new peak.
208+
if self.peak_drift.fetch_max(drift, Ordering::Relaxed) < drift {
209+
let mut peak = self.peak.lock();
210+
if peak.as_ref().is_none_or(|p| drift > p.drift) {
211+
*peak = Some(sample());
212+
}
213+
}
214+
215+
// Only rising positive drift is logged: that is untracked memory, which
216+
// is what leads to OOM kills. Negative drift (e.g. an operator
217+
// reserving ahead of allocating) counts as zero. Falling drift quietly
218+
// lowers the baseline so the next rise is seen.
219+
let untracked = drift.max(0);
220+
let last = self.last_logged.load(Ordering::Relaxed);
221+
let rose = untracked >= last.saturating_add_unsigned(self.log_threshold);
222+
if !rose && untracked >= last {
223+
return false;
224+
}
225+
let updated = self
226+
.last_logged
227+
.compare_exchange(last, untracked, Ordering::Relaxed, Ordering::Relaxed)
228+
.is_ok();
229+
let logged = updated && rose;
230+
if logged {
231+
log::info!("memory drift: {}", sample());
232+
}
233+
logged
234+
}
235+
}
236+
237+
impl Debug for MemoryDriftTracker {
238+
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
239+
f.debug_struct("MemoryDriftTracker")
240+
.field("log_threshold", &self.log_threshold)
241+
.field("reserved", &self.reserved())
242+
.field("peak", &self.peak_drift())
243+
.finish()
244+
}
245+
}
246+
247+
#[cfg(test)]
248+
mod tests {
249+
use crate::memory_pool::{
250+
MemoryConsumer, MemoryPool, PeakRecordingPool, UnboundedMemoryPool,
251+
};
252+
253+
use super::*;
254+
255+
/// A tracker whose allocated byte count is set by the test.
256+
fn tracker(log_threshold: usize) -> (Arc<AtomicUsize>, Arc<MemoryDriftTracker>) {
257+
let allocated = Arc::new(AtomicUsize::new(0));
258+
let source = Arc::clone(&allocated);
259+
let tracker =
260+
MemoryDriftTracker::new(Arc::new(move || source.load(Ordering::Relaxed)))
261+
.with_log_threshold(log_threshold);
262+
(allocated, Arc::new(tracker))
263+
}
264+
265+
fn pool(tracker: &Arc<MemoryDriftTracker>, label: &str) -> Arc<dyn MemoryPool> {
266+
Arc::new(
267+
PeakRecordingPool::new(Arc::new(UnboundedMemoryPool::default()))
268+
.with_drift_tracker(Arc::clone(tracker), label),
269+
)
270+
}
271+
272+
#[test]
273+
fn records_peak_drift_and_where_it_happened() {
274+
let (allocated, tracker) = tracker(DEFAULT_DRIFT_LOG_THRESHOLD);
275+
let pool = pool(&tracker, "q1");
276+
277+
let a = MemoryConsumer::new("a").register(&pool);
278+
let b = MemoryConsumer::new("b").register(&pool);
279+
280+
allocated.store(1000, Ordering::Relaxed);
281+
a.grow(800);
282+
allocated.store(5000, Ordering::Relaxed);
283+
b.grow(200);
284+
allocated.store(1500, Ordering::Relaxed);
285+
a.shrink(800);
286+
287+
assert_eq!(tracker.reserved(), 200);
288+
assert_eq!(
289+
tracker.peak_drift(),
290+
Some(DriftSample {
291+
pool: "q1".to_string(),
292+
consumer: "b".to_string(),
293+
reserved: 1000,
294+
allocated: 5000,
295+
drift: 4000,
296+
})
297+
);
298+
}
299+
300+
#[test]
301+
fn sums_reservations_across_pools_sharing_a_tracker() {
302+
let (allocated, tracker) = tracker(DEFAULT_DRIFT_LOG_THRESHOLD);
303+
let one = pool(&tracker, "one");
304+
let two = pool(&tracker, "two");
305+
306+
allocated.store(1000, Ordering::Relaxed);
307+
let a = MemoryConsumer::new("a").register(&one);
308+
let b = MemoryConsumer::new("b").register(&two);
309+
a.grow(300);
310+
b.grow(400);
311+
312+
// Drift is measured against the sum, so the second pool's growth
313+
// shrinks it rather than starting from zero.
314+
assert_eq!(tracker.reserved(), 700);
315+
let peak = tracker.peak_drift().unwrap();
316+
assert_eq!(peak.pool, "one");
317+
assert_eq!(peak.drift, 700);
318+
319+
drop(a);
320+
drop(b);
321+
assert_eq!(tracker.reserved(), 0);
322+
}
323+
324+
#[test]
325+
fn drift_can_be_negative() {
326+
let (_allocated, tracker) = tracker(DEFAULT_DRIFT_LOG_THRESHOLD);
327+
let pool = pool(&tracker, "over-reserved");
328+
329+
let reservation = MemoryConsumer::new("a").register(&pool);
330+
reservation.grow(2048);
331+
332+
let peak = tracker.peak_drift().unwrap();
333+
assert_eq!(peak.drift, -2048);
334+
assert_eq!(
335+
peak.to_string(),
336+
"drift=-2.0 KB allocated=0.0 B reserved=2.0 KB pool=over-reserved consumer=a"
337+
);
338+
}
339+
340+
#[test]
341+
fn logs_each_rise_by_the_threshold_and_rearms_after_a_fall() {
342+
let (allocated, tracker) = tracker(1000);
343+
let observe = |bytes: usize, reserved: usize| {
344+
allocated.store(bytes, Ordering::Relaxed);
345+
tracker.observe("p", "c", reserved)
346+
};
347+
348+
// Negative drift counts as zero, so the baseline stays at zero.
349+
assert!(!observe(0, 5000));
350+
// Below the threshold: nothing logged.
351+
assert!(!observe(999, 0));
352+
// Reaching the threshold logs and moves the baseline to 1000.
353+
assert!(observe(1000, 0));
354+
assert!(!observe(1999, 0));
355+
assert!(observe(2000, 0));
356+
// Falling drift is not logged but lowers the baseline to 500...
357+
assert!(!observe(500, 0));
358+
// ...so a rise of the threshold from there logs again.
359+
assert!(!observe(1499, 0));
360+
assert!(observe(1500, 0));
361+
}
362+
363+
#[test]
364+
fn a_threshold_above_isize_max_never_logs() {
365+
let (allocated, tracker) = tracker(usize::MAX);
366+
367+
allocated.store(1 << 40, Ordering::Relaxed);
368+
assert!(!tracker.observe("p", "c", 0));
369+
}
370+
371+
#[test]
372+
fn sample_observes_without_a_reservation_change() {
373+
let (allocated, tracker) = tracker(DEFAULT_DRIFT_LOG_THRESHOLD);
374+
let pool = pool(&tracker, "q1");
375+
let reservation = MemoryConsumer::new("a").register(&pool);
376+
reservation.grow(100);
377+
378+
allocated.store(5000, Ordering::Relaxed);
379+
tracker.sample("timer");
380+
381+
assert_eq!(
382+
tracker.peak_drift(),
383+
Some(DriftSample {
384+
pool: "timer".to_string(),
385+
consumer: String::new(),
386+
reserved: 100,
387+
allocated: 5000,
388+
drift: 4900,
389+
})
390+
);
391+
}
392+
}

0 commit comments

Comments
 (0)