Skip to content

Commit 83cd46f

Browse files
committed
fix: count each memory pool once in analyze_trace
analyze_trace derived the total pool reservation by summing the per-thread thread_NNN_comet_memory_reserved counters. Those come from total_reserved_for_thread, which deduplicates shared pools only within a thread, so a task-shared pool reports its full reservation on every thread that references it and summing multiplies it by the thread count. Measured on TPC-H SF100 with tracing enabled, the reported total reached 500x the real allocation, 27% of samples claimed more memory reserved than the allocator had handed out, and the median total was 0 because threads with no registered pools contribute nothing. The tool's peak gap then landed on samples where the total happened to be zero, reporting peak allocation rather than a gap. Add total_reserved_across_tasks(), which sums reserved() over the distinct entries of TASK_SHARED_MEMORY_POOLS, and emit it as a single comet_memory_reserved_total counter beside the existing allocation counter so both halves of a sample are true at the same instant. analyze_trace prefers it, and still reads older traces from the per-thread sum while saying plainly that those totals over-count. The new counter has to be matched before the existing name.contains("comet_memory_reserved") branch, which would otherwise fold the process-wide total into the per-thread map. The per-thread counters are unchanged: they remain useful for per-thread attribution in a trace viewer.
1 parent 20faa23 commit 83cd46f

4 files changed

Lines changed: 136 additions & 17 deletions

File tree

‎docs/source/contributor-guide/tracing.md‎

Lines changed: 15 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -78,10 +78,13 @@ cargo run --bin analyze_trace -- /path/to/comet-event-trace.json
7878

7979
The tool reads counter events from the trace log. Because tracing logs metrics per thread, `native_allocated`
8080
and `jemalloc_allocated` are process-wide values (the same global allocation reported from whichever thread
81-
logs it), while `thread_NNN_comet_memory_reserved` values are per-thread pool reservations that are summed to
82-
get the total tracked memory. The tool analyzes `native_allocated` when the trace contains it, since that
83-
counts only what Rust code holds from the allocator, and otherwise falls back to `jemalloc_allocated`. The
84-
output names the counter it used. A trace with neither counter is rejected.
81+
logs it). The total tracked memory comes from `comet_memory_reserved_total`, which counts each pool once
82+
process-wide. The per-thread `thread_NNN_comet_memory_reserved` values must not be summed to obtain it: a
83+
task-shared pool reports its full reservation on every thread that references it, so summing multiplies it by
84+
the thread count. Traces recorded before that counter existed are still analyzed from the per-thread sum, and
85+
the tool warns that the total over-counts. The tool analyzes `native_allocated` when the trace contains it,
86+
since that counts only what Rust code holds from the allocator, and otherwise falls back to
87+
`jemalloc_allocated`. The output names the counter it used. A trace with neither counter is rejected.
8588

8689
Sample output:
8790

@@ -121,10 +124,11 @@ not being tracked by the pool.
121124

122125
## Definition of Labels
123126

124-
| Label | Meaning |
125-
| -------------------------------- | -------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
126-
| jvm_heap_used | JVM heap memory usage of live objects for the executor process |
127-
| jemalloc_allocated | Native memory usage for the executor process (requires `jemalloc` feature) |
128-
| native_allocated | Bytes handed out by the Rust global allocator, process-wide (requires `alloc-accounting` feature). Approximate to within 64 KiB of un-flushed delta per live thread. |
129-
| thread_NNN_comet_memory_reserved | Memory reserved by Comet's DataFusion memory pool (summed across all contexts on the thread). NNN is the Rust thread ID. |
130-
| thread_NNN_comet_jvm_shuffle | Off-heap memory allocated by Comet for columnar shuffle. NNN is the Rust thread ID. |
127+
| Label | Meaning |
128+
| -------------------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
129+
| jvm_heap_used | JVM heap memory usage of live objects for the executor process |
130+
| jemalloc_allocated | Native memory usage for the executor process (requires `jemalloc` feature) |
131+
| native_allocated | Bytes handed out by the Rust global allocator, process-wide (requires `alloc-accounting` feature). Approximate to within 64 KiB of un-flushed delta per live thread. |
132+
| comet_memory_reserved_total | Total memory reserved across every live Comet memory pool, process-wide. Counts each task-shared pool once, so unlike the per-thread counters it can be compared directly against an allocation counter. |
133+
| thread_NNN_comet_memory_reserved | Memory reserved by Comet's DataFusion memory pool (summed across all contexts on the thread). NNN is the Rust thread ID. Do not sum these across threads: a task-shared pool reports its full reservation on every thread that references it. |
134+
| thread_NNN_comet_jvm_shuffle | Off-heap memory allocated by Comet for columnar shuffle. NNN is the Rust thread ID. |

‎native/common/src/bin/analyze_trace.rs‎

Lines changed: 39 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,14 @@ use std::{env, fs::File};
3737
/// analyzed.
3838
const ALLOCATED_COUNTERS: [&str; 2] = ["native_allocated", "jemalloc_allocated"];
3939

40+
/// The process-wide total of Comet's memory pool reservations.
41+
///
42+
/// Preferred over summing the per-thread `thread_NNN_comet_memory_reserved` counters. Those report
43+
/// the full reservation of a task-shared pool once per thread that references it, so adding them
44+
/// across threads multiplies a shared pool by its thread count. A trace without this counter is
45+
/// still analyzed from the per-thread sum, with a warning, so older traces remain readable.
46+
const POOL_TOTAL_COUNTER: &str = "comet_memory_reserved_total";
47+
4048
/// A single Chrome trace event (only the fields we care about).
4149
#[derive(Deserialize)]
4250
struct TraceEvent {
@@ -75,8 +83,11 @@ fn main() {
7583
let mut source: Option<usize> = None;
7684
// Latest allocated value (global, not per-thread)
7785
let mut latest_allocated: u64 = 0;
78-
// Per-thread pool reservations: thread_NNN -> bytes
86+
// Per-thread pool reservations: thread_NNN -> bytes. Only used when the trace lacks the
87+
// process-wide total, since summing these over-counts task-shared pools.
7988
let mut pool_by_thread: HashMap<String, u64> = HashMap::new();
89+
// Process-wide pool total, when the trace carries it.
90+
let mut pool_total_counter: Option<u64> = None;
8091
// Points where allocated exceeded pool total
8192
let mut violations: Vec<MemorySnapshot> = Vec::new();
8293
// Track peak values
@@ -146,6 +157,12 @@ fn main() {
146157
peak_allocated = latest_allocated;
147158
}
148159
}
160+
} else if event.name == POOL_TOTAL_COUNTER {
161+
// Must be matched before the per-thread branch below, whose `contains` check would
162+
// otherwise also match this name and fold the process-wide total into the map.
163+
if let Some(val) = event.args.get(&event.name) {
164+
pool_total_counter = Some(val.as_u64().unwrap_or(0));
165+
}
149166
} else if event.name.contains("comet_memory_reserved") {
150167
// Name format: thread_NNN_comet_memory_reserved
151168
let thread_key = event.name.clone();
@@ -161,12 +178,13 @@ fn main() {
161178
// After each allocated or pool update, check the current state. A comparison needs one
162179
// sample of each side: an observed zero reservation is a real value that allocation can
163180
// exceed, so only the absence of any pool sample defers the check.
164-
let pool_total: u64 = pool_by_thread.values().sum();
181+
let pool_total: u64 = pool_total_counter.unwrap_or_else(|| pool_by_thread.values().sum());
165182
if pool_total > peak_pool_total {
166183
peak_pool_total = pool_total;
167184
}
168185

169-
if source.is_some() && !pool_by_thread.is_empty() && latest_allocated > pool_total {
186+
let have_pool_sample = pool_total_counter.is_some() || !pool_by_thread.is_empty();
187+
if source.is_some() && have_pool_sample && latest_allocated > pool_total {
170188
let excess = latest_allocated - pool_total;
171189
if excess > peak_excess {
172190
peak_excess = excess;
@@ -198,7 +216,19 @@ fn main() {
198216
println!("=== Comet Trace Memory Analysis ===\n");
199217
println!("Counter events parsed: {counter_events}");
200218
println!("Allocation counter: {source}");
201-
println!("Threads with memory pools: {}", pool_by_thread.len());
219+
if pool_total_counter.is_some() {
220+
println!("Pool total source: {POOL_TOTAL_COUNTER} (process-wide)");
221+
} else {
222+
println!(
223+
"Pool total source: sum of {} per-thread counters",
224+
pool_by_thread.len()
225+
);
226+
println!(
227+
"WARNING: this trace predates {POOL_TOTAL_COUNTER}. Summing the per-thread counters\n\
228+
over-counts: a task-shared pool reports its full reservation on every thread that\n\
229+
references it, so the totals below are upper bounds and the excess is understated."
230+
);
231+
}
202232
println!("Peak {source}: {}", format_bytes(peak_allocated));
203233
println!(
204234
"Peak pool total: {}",
@@ -210,7 +240,7 @@ fn main() {
210240
);
211241
println!();
212242

213-
if pool_by_thread.is_empty() {
243+
if pool_total_counter.is_none() && pool_by_thread.is_empty() {
214244
println!(
215245
"No pool reservation samples in the trace, so there is nothing to compare against."
216246
);
@@ -245,5 +275,8 @@ fn main() {
245275
for (thread, bytes) in &threads {
246276
println!(" {thread}: {}", format_bytes(**bytes));
247277
}
248-
println!("\n Total: {}", format_bytes(pool_by_thread.values().sum()));
278+
println!(
279+
"\n Total: {}",
280+
format_bytes(pool_total_counter.unwrap_or_else(|| pool_by_thread.values().sum()))
281+
);
249282
}

‎native/core/src/execution/jni_api.rs‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1107,6 +1107,13 @@ pub unsafe extern "system" fn Java_org_apache_comet_Native_executePlan(
11071107
&exec_context.tracing_memory_metric_name,
11081108
total_reserved_for_thread(exec_context.rust_thread_id) as u64,
11091109
);
1110+
// Process-wide total, emitted here so it is true at the same instant as the
1111+
// allocation counter above. The per-thread counter cannot be summed across threads:
1112+
// it reports a shared pool's full reservation once per referencing thread.
1113+
log_memory_usage(
1114+
"comet_memory_reserved_total",
1115+
crate::execution::memory_pools::total_reserved_across_tasks() as u64,
1116+
);
11101117
}
11111118

11121119
result

‎native/core/src/execution/memory_pools/task_shared.rs‎

Lines changed: 75 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -94,6 +94,22 @@ impl Drop for TaskSharedMemoryPool {
9494
}
9595
}
9696

97+
/// Total bytes reserved across every live task-shared pool, process-wide.
98+
///
99+
/// Each registry entry is one task attempt's pool, so summing the entries counts each pool exactly
100+
/// once. This is deliberately not the sum of the per-thread `thread_NNN_comet_memory_reserved`
101+
/// tracing counters: each of those reports the full reservation of a shared pool once per thread
102+
/// that references it, so adding them across threads multiplies a task-shared pool by its thread
103+
/// count.
104+
pub(crate) fn total_reserved_across_tasks() -> usize {
105+
TASK_SHARED_MEMORY_POOLS
106+
.lock()
107+
.values()
108+
.filter_map(Weak::upgrade)
109+
.map(|pool| pool.reserved())
110+
.sum()
111+
}
112+
97113
/// Returns the memory pool shared by every native plan in `task_attempt_id`, creating it with
98114
/// `create` if no live pool exists for the task. The returned `Arc` is the RAII handle: the pool
99115
/// stays registered until the last reference to it drops.
@@ -121,6 +137,7 @@ pub(crate) fn acquire_task_shared_pool(
121137
mod tests {
122138
use super::*;
123139
use datafusion::execution::memory_pool::UnboundedMemoryPool;
140+
use std::sync::{Mutex, MutexGuard};
124141

125142
/// Tests share the process-wide pool map, so each uses its own task attempt id.
126143
fn acquire(task_attempt_id: i64) -> Arc<dyn MemoryPool> {
@@ -133,6 +150,64 @@ mod tests {
133150
.contains_key(&task_attempt_id)
134151
}
135152

153+
/// `TASK_SHARED_MEMORY_POOLS` is process-wide and the crate's tests run in parallel, so any
154+
/// test that reserves memory perturbs another's view of the total. The two tests below take
155+
/// this lock so their deltas are exact; without it they observe each other's reservations.
156+
static SERIAL: Mutex<()> = Mutex::new(());
157+
158+
fn serial() -> MutexGuard<'static, ()> {
159+
SERIAL
160+
.lock()
161+
.unwrap_or_else(|poisoned| poisoned.into_inner())
162+
}
163+
164+
/// The property the per-thread tracing counters get wrong: a task-shared pool contributes its
165+
/// reservation once, however many execution contexts hold it.
166+
#[test]
167+
fn a_task_shared_pool_is_counted_once_however_many_contexts_hold_it() {
168+
let _guard = serial();
169+
let before = total_reserved_across_tasks();
170+
171+
let first = acquire(-1010);
172+
let reservation = MemoryConsumer::new("counted").register(&first);
173+
reservation.try_grow(4096).unwrap();
174+
let with_one_context = total_reserved_across_tasks();
175+
assert_eq!(
176+
with_one_context - before,
177+
4096,
178+
"a live pool's reservation must appear in the total"
179+
);
180+
181+
// A second execution context in the same task resolves to the same pool. The total must
182+
// not double: summing the per-thread counters instead is exactly what over-counts.
183+
let second = acquire(-1010);
184+
assert!(Arc::ptr_eq(&first, &second));
185+
assert_eq!(
186+
total_reserved_across_tasks(),
187+
with_one_context,
188+
"a shared pool must be counted once, not once per holder"
189+
);
190+
191+
drop(reservation);
192+
}
193+
194+
#[test]
195+
fn released_pools_leave_the_total() {
196+
let _guard = serial();
197+
let before = total_reserved_across_tasks();
198+
{
199+
let pool = acquire(-1011);
200+
let reservation = MemoryConsumer::new("transient").register(&pool);
201+
reservation.try_grow(8192).unwrap();
202+
assert_eq!(total_reserved_across_tasks() - before, 8192);
203+
}
204+
assert_eq!(
205+
total_reserved_across_tasks(),
206+
before,
207+
"dropping the last reference must remove the pool from the total"
208+
);
209+
}
210+
136211
#[test]
137212
fn plans_in_the_same_task_share_one_pool() {
138213
let first = acquire(-1001);

0 commit comments

Comments
 (0)