From 038b179db7c1df70ff95f60389d31413e6c1074a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gon=C3=A7alo=20Carvalho?= Date: Thu, 24 Sep 2026 15:04:41 +0100 Subject: [PATCH] fix(pool): !poolmap draws the map, but never said what the walk missed The extension is already a shim over the shared walk -- it calls query::prepare_index, resolves no types of its own, and shares the snapshot caches -- but the walk's own assessment stopped at the library boundary. render_pool_map listed every diagnostic verbatim and rendered none of complete, unplaced_bytes, stalls or refused_chunks, so an operator got a picture with no statement of how much of the pool was not in it. Measured on a live 29671 kernel (windbg-mcp FOLLOWUPS.md item 100): the structured surface reported coverage: partial with gaps.unplaced_bytes 15,626,240 for a walk whose map said nothing, under 3,616 diagnostic lines that say what went wrong without ever saying what it cost. render_pool_map now takes the PoolSnapshotReport for the walk behind the index and appends a --- pool walk --- summary, on the empty-map path too, which is the case this is really for: with nothing to draw, "no allocation matches" and "the walk never reached the pool" are otherwise the same two lines. A --address miss carries it as well, including when coverage is complete, since that is what turns the miss into a real negative. The report comes from query::report_of, now pub(crate), rather than from the index's fields. Coverage has three states collapsed from two flags, and re-deriving that in the renderer is exactly how the two surfaces would drift apart -- which is the whole point of the extension being a shim. It is the walk's report, not the rendered index's, because the filter path rebuilds the index from retained spans: a summary taken after --paged would report the filtered count as the number of chunks walked. A test pins that, and mutating the call to derive from the rendered index reports "chunks walked: 1" against 2 and fails it. All five new tests were mutation-verified: dropping the summary from either path, collapsing BudgetExpired into Partial, and deriving the report from the filtered index are each caught by the test that claims them, with the edit confirmed applied rather than assumed. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01MUhLUt9rB6zd42Y25btB3h --- src/pool/query.rs | 8 +- src/pool/render.rs | 237 +++++++++++++++++++++++++++++++++++++++++- src/pool_extension.rs | 15 ++- 3 files changed, 256 insertions(+), 4 deletions(-) diff --git a/src/pool/query.rs b/src/pool/query.rs index 714d0ac..93a932a 100644 --- a/src/pool/query.rs +++ b/src/pool/query.rs @@ -316,7 +316,13 @@ pub fn snapshot_report( Ok(report_of(&index)) } -fn report_of(index: &PoolIndex) -> PoolSnapshotReport { +/// The walk's own assessment of an index, which every surface reads rather than re-deriving. +/// +/// `pub(crate)` so the `!poolmap` renderer takes its coverage from here too. The map and the +/// programmatic answer describe one walk, and the only way they cannot disagree about it is to +/// compute it once — which is the whole reason this is a function rather than four field reads +/// repeated at each call site. +pub(crate) fn report_of(index: &PoolIndex) -> PoolSnapshotReport { PoolSnapshotReport { layout: index.layout.clone(), total_chunks: index.spans.len(), diff --git a/src/pool/render.rs b/src/pool/render.rs index f520773..ead8580 100644 --- a/src/pool/render.rs +++ b/src/pool/render.rs @@ -1,6 +1,7 @@ use std::collections::BTreeMap; use super::index::{Direction, PoolIndex}; +use super::query::{PoolSnapshotReport, WalkCoverage}; use super::{HeapIdentity, PoolBackend, PoolKind, PoolSpan, PoolState}; const OUTPUT_CHUNK: usize = 7_500; @@ -168,7 +169,17 @@ fn safe_dml_boundary(text: &str, limit: usize) -> usize { boundary } -pub(crate) fn render_pool_map(index: &PoolIndex, options: RenderOptions) -> Vec { +/// Render the pool map, then what the walk behind it managed. +/// +/// `walk` is the report for the walk that produced `index`, and on a filtered map it is +/// deliberately **not** a report of `index`: how much of the pool was covered is a property of the +/// walk, not of what was retained from its result, so a `--paged` map must still say how many +/// chunks were walked rather than how many survived the filter. +pub(crate) fn render_pool_map( + index: &PoolIndex, + walk: &PoolSnapshotReport, + options: RenderOptions, +) -> Vec { let selected_indices = options .tag .map(|tag| index.context_for_tag(tag)) @@ -207,6 +218,9 @@ pub(crate) fn render_pool_map(index: &PoolIndex, options: RenderOptions) -> Vec< "No matching pool allocations in the stopped-target snapshot.\n", options.dml, ); + // The summary matters most here: without it "nothing matched" and "the walk never + // reached the pool" are the same two lines of output. + push_chunked(&mut chunks, &render_walk_summary(walk), options.dml); return chunks; } for (key, indices) in rows { @@ -255,9 +269,74 @@ pub(crate) fn render_pool_map(index: &PoolIndex, options: RenderOptions) -> Vec< options.dml, ); } + push_chunked(&mut chunks, &render_walk_summary(walk), options.dml); chunks } +/// What the walk itself managed, rendered after the map. +/// +/// Without it the map is ambiguous in the worst way: a pool the walk covered completely and one it +/// reached a fraction of draw the same picture, and an *empty* map is worse still — "no allocation +/// matches" and "the walk never got there" render identically. The diagnostics above say what went +/// wrong without ever saying how much it cost, and a real walk emits thousands of them, so scrolling +/// is not a substitute for a total. +/// +/// Measured on a live 29671 kernel (`FOLLOWUPS.md` item 100 in `windbg-mcp`): 3,616 diagnostics and +/// 15,626,240 bytes the walk could not place a chunk boundary in, none of which this map said. The +/// structured surface carried `coverage: partial` and `gaps.unplaced_bytes` for the same walk. +/// +/// Taken from [`query::report_of`](super::query::report_of) rather than from the index's fields, so +/// the two surfaces cannot disagree about one walk — `coverage` in particular has three states +/// collapsed from two flags, and re-deriving that here is how they would drift apart. +pub(crate) fn render_walk_summary(walk: &PoolSnapshotReport) -> String { + let mut out = format!( + "\n--- pool walk ---\nchunks walked: {} ({} allocated), coverage: {}\n", + walk.total_chunks, + walk.allocated_chunks, + match (walk.stopped_after_matches, walk.coverage) { + (Some(matches), _) => format!( + "match_limit_reached - stopped after {matches} matching allocated chunk(s), so \ + what is above is intentionally partial" + ), + (None, WalkCoverage::Complete) => "complete".into(), + // Kept apart because they tell an operator to do different things: a deadline is + // worth re-running with more time, and a partial walk is not. + (None, WalkCoverage::BudgetExpired) => + "INCOMPLETE - the walk's deadline passed; more time reaches more of it".into(), + (None, WalkCoverage::Partial) => + "INCOMPLETE - the walk did not reach everything it set out to, and more time \ + changes nothing" + .into(), + } + ); + // Only when there is something to say, so a clean walk stays quiet and the line means + // something when it does appear. + if walk.unplaced_bytes > 0 { + out.push_str(&format!( + "not decoded: {:#x} bytes the walk could not place a chunk boundary in\n", + walk.unplaced_bytes + )); + } + if walk.stalls.pages > 0 { + out.push_str(&format!( + "stalled: {} page(s), {:#x} bytes skipped, {:#x} bytes recovered after the stall\n", + walk.stalls.pages, walk.stalls.skipped_bytes, walk.stalls.recovered_bytes + )); + } + if walk.refused_chunks > 0 { + out.push_str(&format!( + "refused: {} chunk header(s) that did not decode\n", + walk.refused_chunks + )); + } + out.push_str(&match walk.diagnostics.emitted() { + 0 => "the walk reported no diagnostics.\n".into(), + 1 => "1 diagnostic, listed above.\n".into(), + emitted => format!("{emitted} diagnostics, listed above.\n"), + }); + out +} + pub(crate) fn render_advice(index: &PoolIndex, tag: u32, dml: bool) -> String { let mut output = String::from("Observed geometry:\n"); for &allocation in index.postings.get(&tag).into_iter().flatten() { @@ -424,6 +503,7 @@ mod tests { }); let plain = render_pool_map( &index, + &crate::pool::query::report_of(&index), RenderOptions { tag: Some(tag), dml: false, @@ -444,6 +524,7 @@ mod tests { assert!(!plain.contains("A<&"")); let dml = render_pool_map( &index, + &crate::pool::query::report_of(&index), RenderOptions { tag: Some(tag), dml: true, @@ -480,6 +561,7 @@ mod tests { assert!( render_pool_map( &index, + &crate::pool::query::report_of(&index), RenderOptions { tag: Some(tag), dml: true @@ -520,6 +602,7 @@ mod tests { }); let dml_chunks = render_pool_map( &many_index, + &crate::pool::query::report_of(&many_index), RenderOptions { tag: Some(tag), dml: true, @@ -538,4 +621,156 @@ mod tests { assert!(chunk.len() <= OUTPUT_CHUNK); } } + + /// Build an index whose walk state is set by the caller, so a test can pin what the summary + /// says about a walk rather than about the spans it happened to produce. + fn index_with( + spans: Vec, + complete: bool, + budget_expired: bool, + unplaced_bytes: u64, + diagnostics: PoolDiagnostics, + ) -> PoolIndex { + PoolIndex::build(PoolSnapshot { + layout: Default::default(), + spans, + complete, + budget_expired, + stopped_after_matches: None, + match_limit: None, + matched_allocations: 0, + stalls: Default::default(), + refused_chunks: 0, + unplaced_bytes, + diagnostics, + }) + } + + fn one_span() -> Vec { + vec![span( + 0x1000, + u32::from_le_bytes(*b"Abcd"), + PoolKind::Paged, + PoolBackend::Vs, + PoolState::Allocated, + )] + } + + fn render(index: &PoolIndex) -> String { + render_pool_map( + index, + &crate::pool::query::report_of(index), + RenderOptions::default(), + ) + .join("") + } + + /// A map drawn from a walk that fell short has to say so on the map. + /// + /// This is `FOLLOWUPS.md` item 100 in `windbg-mcp`: on a live 29671 kernel the walk left + /// 15,626,240 bytes undecoded and the structured surface reported `coverage: partial` with + /// `gaps.unplaced_bytes`, while `!poolmap` drew the same walk as a finished picture. The + /// assertion is on the *shortfall being stated*, not on the wording: coverage must not read + /// as complete, and the byte total must be reachable. + #[test] + fn test_poolmap_states_a_walk_that_fell_short() { + let text = render(&index_with( + one_span(), + false, + false, + 0xee6000, + PoolDiagnostics::from_iter(["VS extent at 0x1 cannot be placed".to_string()]), + )); + assert!(text.contains("INCOMPLETE"), "{text}"); + assert!(!text.contains("coverage: complete"), "{text}"); + assert!(text.contains("0xee6000"), "{text}"); + assert!(text.contains("1 diagnostic, listed above."), "{text}"); + } + + /// A clean walk says so and stays quiet about gaps it does not have, or the line that reports + /// a shortfall means nothing when it appears. + #[test] + fn test_poolmap_clean_walk_reports_complete_and_no_gaps() { + let text = render(&index_with( + one_span(), + true, + false, + 0, + PoolDiagnostics::default(), + )); + assert!(text.contains("coverage: complete"), "{text}"); + assert!(!text.contains("INCOMPLETE"), "{text}"); + assert!(!text.contains("not decoded:"), "{text}"); + assert!(!text.contains("stalled:"), "{text}"); + assert!(!text.contains("refused:"), "{text}"); + assert!(text.contains("no diagnostics"), "{text}"); + } + + /// An expired deadline and a partial walk are different advice — re-run with more time, or + /// do not bother — so the summary must not collapse them into one word. + #[test] + fn test_poolmap_separates_an_expired_budget_from_a_partial_walk() { + let expired = render(&index_with( + one_span(), + false, + true, + 0, + PoolDiagnostics::default(), + )); + let partial = render(&index_with( + one_span(), + false, + false, + 0, + PoolDiagnostics::default(), + )); + assert!(expired.contains("deadline"), "{expired}"); + assert!(partial.contains("more time changes nothing"), "{partial}"); + assert_ne!( + expired, partial, + "an expired budget and a partial walk rendered identically" + ); + } + + /// The case the summary exists for: with nothing to draw, "no allocation matches" and "the + /// walk never reached the pool" are otherwise the same two lines. + #[test] + fn test_poolmap_empty_map_still_carries_the_walk() { + let text = render(&index_with( + Vec::new(), + false, + false, + 0x1000, + PoolDiagnostics::default(), + )); + assert!(text.contains("No matching pool allocations"), "{text}"); + assert!(text.contains("INCOMPLETE"), "{text}"); + assert!(text.contains("0x1000"), "{text}"); + } + + /// Coverage describes the walk, not what survived a filter. + /// + /// `!poolmap --paged` retains a subset of the spans and rebuilds the index, so a summary + /// derived from the *rendered* index would report the filtered count as the number of chunks + /// walked and shrink the pool to whatever was asked for. The extension takes the report + /// before filtering for this reason; this pins that the renderer honours it. + #[test] + fn test_poolmap_filtered_map_reports_the_whole_walk() { + let mut spans = one_span(); + spans.push(span( + 0x2000, + u32::from_le_bytes(*b"Efgh"), + PoolKind::NonPagedNx, + PoolBackend::Lfh, + PoolState::Allocated, + )); + let walked = index_with(spans, true, false, 0, PoolDiagnostics::default()); + let report = crate::pool::query::report_of(&walked); + assert_eq!(report.total_chunks, 2); + + let kept = index_with(one_span(), true, false, 0, PoolDiagnostics::default()); + let text = render_pool_map(&kept, &report, RenderOptions::default()).join(""); + assert!(text.contains("chunks walked: 2"), "{text}"); + assert!(!text.contains("chunks walked: 1"), "{text}"); + } } diff --git a/src/pool_extension.rs b/src/pool_extension.rs index 4fd5d7f..749d46a 100644 --- a/src/pool_extension.rs +++ b/src/pool_extension.rs @@ -8,7 +8,7 @@ use windows::core::{HRESULT, IUnknown, Interface, PCSTR}; use crate::dbgeng::DebugEngine; use crate::pool::decode::parse_tag; use crate::pool::query; -use crate::pool::render::{RenderOptions, render_pool_map}; +use crate::pool::render::{RenderOptions, render_pool_map, render_walk_summary}; const DEBUG_NOTIFY_SESSION_ACTIVE: u32 = 0x0000_0000; const DEBUG_NOTIFY_SESSION_INACTIVE: u32 = 0x0000_0001; @@ -127,6 +127,9 @@ fn command_poolmap(engine: &DebugEngine, args: &str) -> Result<(), String> { // have no such control; see `query::DEFAULT_WALK_BUDGET`. let walk = query::PoolWalk::from(command.refresh).unbounded(); let index = query::prepare_index(engine, walk).map_err(|error| error.to_string())?; + // Taken before the filter below, because coverage describes the walk and not what was + // retained from its result — a `--paged` map still walked the whole pool. + let walked = query::report_of(&index); if let Some(address) = command.address { let detail = index @@ -148,7 +151,14 @@ fn command_poolmap(engine: &DebugEngine, args: &str) -> Result<(), String> { span.backend ) }) - .unwrap_or_else(|| format!("{address:#x} is not in the cached pool snapshot\n")); + // A miss is only an answer if the walk covered the address. "No chunk holds it" and + // "the walk never reached it" are the same sentence otherwise, so the walk's own + // coverage goes out with the miss — including when it is `complete`, which is what + // turns the miss into a real negative. + .unwrap_or_else(|| { + format!("{address:#x} is not in the cached pool snapshot\n") + + &render_walk_summary(&walked) + }); engine.output(&detail).map_err(|error| error.to_string())?; return Ok(()); } @@ -179,6 +189,7 @@ fn command_poolmap(engine: &DebugEngine, args: &str) -> Result<(), String> { } for chunk in render_pool_map( &filtered, + &walked, RenderOptions { tag: command.tag, dml: true,