diff --git a/tools/bench/vdm_bench.cpp b/tools/bench/vdm_bench.cpp index cdf954f..187f977 100644 --- a/tools/bench/vdm_bench.cpp +++ b/tools/bench/vdm_bench.cpp @@ -22,6 +22,18 @@ // for a --preset release run, where the number means something (a sanitizer roughly // doubles-to-quadruples RSS via redzones/shadow memory). // +// vdm_bench heap-profile [--tasks 20] [--task-size 4M] [--segments N] [--top N] +// Answers "where does the RSS actually go", for the M7 RSS target (docs/04 ยง8) -- +// no massif/heaptrack in this environment (no root to install them), so this is a +// small in-process equivalent: the same operator new/delete override tracks, per +// allocation, which call site made it (one return address, via +// __builtin_return_address(0) right in operator new -- cheap enough to run for the +// whole scenario, unlike a full backtrace) and keeps a live (not-yet-freed) byte +// count per site. Runs the same 20-task concurrent scenario as `load`, waits for +// peak RSS to stop growing, then prints the top sites by live bytes -- the +// breakdown ADR 0012's "45-50 MB" estimate needs to be checked against, and +// core/docs/m7-baseline.md's ~70 MB measurement needs explained. +// // vdm_bench alloc-check [--size 128M] [--window-s 2] // docs/agents/AGENT-CORE.md: "no allocation in the curl write callback... checked in // review and by a bench assertion." operator new/delete are overridden process-wide @@ -42,17 +54,22 @@ #include "vdm/engine.hpp" +#include +#include #include #include +#include #include #include #include #include #include #include +#include #include #include +#include #include #include "support/local_server.hpp" @@ -62,20 +79,194 @@ using namespace vdm; using namespace vdm::task; using namespace std::chrono_literals; -// --- allocation counting (alloc-check only; harmless overhead otherwise) -------------- +// --- allocation tracking: a plain counter for alloc-check, and (only when heap-profile +// turns it on) a per-call-site live-byte tracker standing in for massif/heaptrack, neither +// of which is installable here (no root). Both share one operator new/delete override +// since a process gets exactly one. --------------------------------------------------- namespace { std::atomic g_alloc_count{0}; + +std::atomic g_site_tracking{false}; +// Re-entrancy guard: our own bookkeeping below calls into std::unordered_map, which +// allocates. Without this, that nested operator new call would recurse into the same +// tracking logic -- not infinitely (the nested call's own bookkeeping call would itself be +// guarded the same way, so it terminates), but it would count the tracker's own node +// allocations as if they were the program's, polluting the profile. When set, an +// allocation is just satisfied via malloc/free with no bookkeeping. +thread_local bool g_in_tracker = false; + +struct LiveAlloc { + std::size_t size; + void *site; // __builtin_return_address(0) at the call to operator new +}; +struct SiteStats { + std::uint64_t live_bytes = 0; + std::uint64_t alloc_count = 0; // lifetime, not just live -- how *often* a site fires +}; + +std::mutex g_track_mu; +std::unordered_map g_live; // pointer -> what/where +std::unordered_map g_site_stats; // call site -> aggregate + +void track_alloc(void *p, std::size_t n) { + if (!g_site_tracking.load(std::memory_order_relaxed) || g_in_tracker) + return; + g_in_tracker = true; + void *site = __builtin_return_address(0); + { + std::lock_guard lk(g_track_mu); + g_live.emplace(p, LiveAlloc{n, site}); + auto &st = g_site_stats[site]; + st.live_bytes += n; + st.alloc_count += 1; + } + g_in_tracker = false; } +void track_free(void *p) { + if (!p || !g_site_tracking.load(std::memory_order_relaxed) || g_in_tracker) + return; + g_in_tracker = true; + { + std::lock_guard lk(g_track_mu); + if (auto it = g_live.find(p); it != g_live.end()) { + g_site_stats[it->second.site].live_bytes -= it->second.size; + g_live.erase(it); + } + } + g_in_tracker = false; +} + +std::string describe_site(void *site); // defined below; used as a per-site fallback here + +// Resolves a batch of call-site addresses to "function (file:line)" via one `addr2line` +// invocation (reads .symtab + DWARF, unlike dladdr below -- most of this codebase's +// call sites are internal-linkage or file-static and never make it into the *dynamic* +// symbol table dladdr is limited to). `sites` and the returned vector are in the same +// order. dladdr's `dli_fbase` (the object's runtime load base -- works even when it can't +// name the specific symbol, which is exactly the "site not in .dynsym" case this exists +// for) converts each ASLR'd runtime address into the file-relative offset addr2line wants. +// Falls back to a raw "0x..." string per site if addr2line isn't on PATH or the batch call +// otherwise fails -- describe_site() below still has dladdr as a second-line fallback for +// an individual site in that case. +std::vector resolve_sites_via_addr2line(const std::vector &sites) { + std::vector out(sites.size()); + for (std::size_t i = 0; i < sites.size(); ++i) { + char buf[32]; + std::snprintf(buf, sizeof buf, "%p", sites[i]); + out[i] = buf; + } + if (sites.empty()) + return out; + + // `-e /proc/self/exe` would resolve inside the *addr2line* process this spawns, i.e. + // to addr2line's own binary, not vdm_bench's -- readlink it here, in-process, first. + char exe_path[4096]; + ssize_t exe_len = ::readlink("/proc/self/exe", exe_path, sizeof(exe_path) - 1); + if (exe_len <= 0) + return out; + exe_path[exe_len] = '\0'; + + std::string cmd = std::string("addr2line -f -C -e '") + exe_path + "'"; + for (void *site : sites) { + Dl_info info{}; + std::uintptr_t off = reinterpret_cast(site); + if (::dladdr(site, &info) && info.dli_fbase) + off -= reinterpret_cast(info.dli_fbase); + char buf[24]; + std::snprintf(buf, sizeof buf, " %zx", off); + cmd += buf; + } + cmd += " 2>/dev/null"; + + FILE *pipe = ::popen(cmd.c_str(), "r"); + if (!pipe) + return out; + std::vector lines; + char line[1024]; + while (std::fgets(line, sizeof line, pipe)) { + std::string s = line; + while (!s.empty() && (s.back() == '\n' || s.back() == '\r')) s.pop_back(); + lines.push_back(std::move(s)); + } + ::pclose(pipe); + + // addr2line -f prints two lines per address: function name, then file:line. + for (std::size_t i = 0; i * 2 + 1 < lines.size() && i < sites.size(); ++i) { + const std::string &fn = lines[i * 2]; + const std::string &loc = lines[i * 2 + 1]; + if (fn == "??" && loc == "??:0") + out[i] = describe_site(sites[i]); // addr2line drew a blank -- try dladdr + else + out[i] = fn + " (" + loc + ")"; + } + return out; +} + +// Single-site fallback (dladdr only) for when addr2line can't place an address (it read +// only .symtab -- e.g. no debug/symbol data at all for that address) or isn't available. +std::string describe_site(void *site) { + Dl_info info{}; + if (!::dladdr(site, &info) || !info.dli_sname) { + char buf[32]; + std::snprintf(buf, sizeof buf, "%p", site); + return buf; + } + std::string name = info.dli_sname; + int status = 0; + if (char *dem = abi::__cxa_demangle(name.c_str(), nullptr, nullptr, &status); + dem && status == 0) { + name = dem; + std::free(dem); + } + auto off = static_cast(reinterpret_cast(site) - + reinterpret_cast(info.dli_saddr)); + return name + " +0x" + [&] { + char buf[24]; + std::snprintf(buf, sizeof buf, "%zx", off); + return std::string(buf); + }(); +} + +} // namespace + void *operator new(std::size_t n) { g_alloc_count.fetch_add(1, std::memory_order_relaxed); - if (void *p = std::malloc(n ? n : 1)) - return p; - throw std::bad_alloc(); + void *p = std::malloc(n ? n : 1); + if (!p) + throw std::bad_alloc(); + track_alloc(p, n); + return p; +} +// The nothrow overload is a distinct allocation function from the plain one above, not an +// alternate spelling of it: leaving it un-overridden means it falls through to ASan's own +// default (nothrow) operator new, while a deallocation of that same pointer still reaches +// the plain `operator delete` override below -- a real alloc-dealloc-mismatch ASan catches +// (hit via std::stable_sort's std::get_temporary_buffer, which allocates this way; see +// core/src/segment/budget.cpp's SegmentBudget::run() for why that path no longer uses +// stable_sort at all, but this override is fixed too since anything else pulling in a +// nothrow allocation -- directly or via another std:: temp-buffer user -- would hit it +// again otherwise). +void *operator new(std::size_t n, const std::nothrow_t &) noexcept { + g_alloc_count.fetch_add(1, std::memory_order_relaxed); + void *p = std::malloc(n ? n : 1); + if (p) + track_alloc(p, n); + return p; +} +void operator delete(void *p) noexcept { + track_free(p); + std::free(p); +} +void operator delete(void *p, std::size_t) noexcept { + track_free(p); + std::free(p); +} +void operator delete(void *p, const std::nothrow_t &) noexcept { + track_free(p); + std::free(p); } -void operator delete(void *p) noexcept { std::free(p); } -void operator delete(void *p, std::size_t) noexcept { std::free(p); } namespace { @@ -336,6 +527,102 @@ int cmd_load(const Args &a) { return 0; } +int cmd_heap_profile(const Args &a) { + const int tasks = static_cast(a.get_long("--tasks", 20)); + const std::uint64_t task_size = a.get_size("--task-size", "4M"); + const auto segments_override = static_cast(a.get_long("--segments", 0)); + const int top_n = static_cast(a.get_long("--top", 20)); + + std::string dir = tmp_workdir(); + const std::uint64_t assumed_segments = segments_override ? segments_override : 8; + const std::uint64_t per_conn_bps = + std::max(1, task_size / (5 * assumed_segments)); + vdm::bench::TestServerProc srv(per_conn_bps); + if (!srv.available()) { + std::fprintf(stderr, + "vdm_bench: tools/testserver unavailable -- skipping heap-profile.\n"); + return 0; + } + + // On from before Engine's own construction, so its fixed cost (http worker threads, + // curl_multi handles, ...) shows up in the profile too, not just what the tasks add. + g_site_tracking.store(true, std::memory_order_relaxed); + Engine eng; + + std::vector handles; + handles.reserve(tasks); + for (int i = 0; i < tasks; ++i) { + DownloadSpec spec; + spec.url = srv.url("/throttled/file/" + std::to_string(task_size)); + spec.save_path = dir + "/out" + std::to_string(i) + ".bin"; + if (segments_override) + spec.segments = segments_override; + handles.push_back(eng.start(std::move(spec), DownloadCallbacks{})); + } + + // Wait for peak RSS to stop growing (5 consecutive 200ms samples with no increase, or + // a generous cap) -- that's the moment whose live-allocation breakdown answers "where + // does the RSS actually go", the same question core/docs/m7-baseline.md's ~70 MB + // number raises against ADR 0012's ~45-50 MB estimate. + long last_rss = 0, stable_for = 0; + for (int i = 0; i < 300 && stable_for < 5; ++i) { + std::this_thread::sleep_for(200ms); + long rss = sample_rusage().peak_rss_kb; + stable_for = (rss <= last_rss) ? stable_for + 1 : 0; + last_rss = rss; + } + + // Cross-check against the budget's own accounting, independent of the allocator-site + // snapshot below: this is what caught the real find here (core/docs/m7-baseline.md, + // docs/adr/0012) -- sum(effective_segments) tracked budget.active well past + // budget.total before the SegmentBudget fix these numbers are now reported alongside. + std::uint32_t total_effective_segments = 0; + for (auto &h : handles) total_effective_segments += h.progress().effective_segments; + auto eb = eng.segment_budget().budget(); + std::fprintf(stderr, + "segment budget: %u live across tasks, engine reports total=%u active=%u " + "starved=%u\n", + total_effective_segments, eb.total, eb.active, eb.tasks_starved); + + // Turn tracking off *before* touching g_site_stats: the snapshot below allocates its + // own vector storage through the very same overridden operator new. With tracking + // still on and g_track_mu already held for the snapshot, that allocation would recurse + // into track_alloc() and try to lock g_track_mu again -- self-deadlock on a + // non-recursive mutex (hit this exact hang while first wiring this subcommand up: + // g_in_tracker only guards the tracker's own bookkeeping containers, not other code + // that allocates while holding g_track_mu directly). + g_site_tracking.store(false, std::memory_order_relaxed); + std::vector> sites; + { + std::lock_guard lk(g_track_mu); + sites.assign(g_site_stats.begin(), g_site_stats.end()); + } + std::sort(sites.begin(), sites.end(), [](const auto &x, const auto &y) { + return x.second.live_bytes > y.second.live_bytes; + }); + + std::fprintf(stderr, "heap-profile: peak RSS %.2f MiB, %d tasks, %llu segments assumed\n", + last_rss / 1024.0, tasks, (unsigned long long)assumed_segments); + std::fprintf(stderr, "%-10s %-10s %s\n", "live KiB", "#allocs", "call site"); + std::uint64_t total_live = 0; + for (auto &[site, st] : sites) total_live += st.live_bytes; + std::fprintf(stderr, "total tracked live: %.2f MiB across %zu sites\n\n", + total_live / 1024.0 / 1024.0, sites.size()); + std::vector top_addrs; + for (int i = 0; i < top_n && i < static_cast(sites.size()); ++i) top_addrs.push_back(sites[i].first); + auto labels = resolve_sites_via_addr2line(top_addrs); + for (std::size_t i = 0; i < top_addrs.size(); ++i) { + auto &[site, st] = sites[i]; + std::fprintf(stderr, "%-10.1f %-10llu %s\n", st.live_bytes / 1024.0, + (unsigned long long)st.alloc_count, labels[i].c_str()); + } + + // Handles/Engine go out of scope here: ~Engine quiesces every task (waits for its + // workers to actually drain -- see the quiesce() fix) rather than waiting for the + // downloads to run to completion, which isn't the point of this subcommand. + return 0; +} + int cmd_alloc_check(const Args &a) { const std::uint64_t size = a.get_size("--size", "128M"); const double window_s = a.get_double("--window-s", 2.0); @@ -416,12 +703,13 @@ int cmd_alloc_check(const Args &a) { void usage() { std::fprintf(stderr, - "usage: vdm_bench [options]\n" - " throughput [--size 5G] [--segments N] [--require-mbps N] " + "usage: vdm_bench [options]\n" + " throughput [--size 5G] [--segments N] [--require-mbps N] " "[--max-cpu-pct N]\n" - " load [--tasks 20] [--task-size 4M] [--segments N] " + " load [--tasks 20] [--task-size 4M] [--segments N] " "[--require-rss-kb N] [--task-timeout-s 300]\n" - " alloc-check [--size 128M] [--window-s 2] [--budget-per-s 5]\n"); + " heap-profile [--tasks 20] [--task-size 4M] [--segments N] [--top 20]\n" + " alloc-check [--size 128M] [--window-s 2] [--budget-per-s 5]\n"); } } // namespace @@ -437,6 +725,8 @@ int main(int argc, char **argv) { return cmd_throughput(args); if (cmd == "load") return cmd_load(args); + if (cmd == "heap-profile") + return cmd_heap_profile(args); if (cmd == "alloc-check") return cmd_alloc_check(args); usage();