From a590f36cbde33f57e423b64a59f1d8acb4f408e0 Mon Sep 17 00:00:00 2001 From: Abul Date: Fri, 24 Jul 2026 00:18:42 +0530 Subject: [PATCH 1/3] time-trace metrics --- tools/perfrunner/source/app.d | 5 +- tools/perfrunner/source/metrics.d | 17 ++++- tools/perfrunner/source/report.d | 34 ++++++++- tools/perfrunner/source/timetrace.d | 107 ++++++++++++++++++++++++++++ 4 files changed, 157 insertions(+), 6 deletions(-) create mode 100644 tools/perfrunner/source/timetrace.d diff --git a/tools/perfrunner/source/app.d b/tools/perfrunner/source/app.d index 98830374a4f6..536e6328628b 100644 --- a/tools/perfrunner/source/app.d +++ b/tools/perfrunner/source/app.d @@ -56,9 +56,10 @@ int main(string[] args) MetricResult[] metrics; foreach (def; initials) metrics ~= MetricResult(def.id, def.label, def.unit, def.method, - base[def.id], head[def.id]); + base.metrics[def.id], head.metrics[def.id]); - auto rep = Report(baseSha, "merge-base", headSha, pr, os, hostDmd, metrics); + auto rep = Report(baseSha, "merge-base", headSha, pr, os, hostDmd, metrics, + base.helloTrace, head.helloTrace, base.phobosTrace, head.phobosTrace); write(outPath, render(rep)); writeln("wrote ", outPath); return 0; diff --git a/tools/perfrunner/source/metrics.d b/tools/perfrunner/source/metrics.d index f22cdcdf5690..d1ed4cf1fe05 100644 --- a/tools/perfrunner/source/metrics.d +++ b/tools/perfrunner/source/metrics.d @@ -8,6 +8,7 @@ import std.regex : ctRegex, matchFirst; import std.process : execute; import cachegrind : instructions; +import timetrace : Trace, collectTrace; struct MetricDef { @@ -28,13 +29,22 @@ immutable MetricDef[] initials = [ MetricDef("phobos_max_rss", "peak RSS (compile Phobos)", "kb", "time -v"), ]; +// The flat metrics plus the informational -ftime-trace breakdowns. +struct Measurement +{ + long[string] metrics; + Trace helloTrace; + Trace phobosTrace; +} + // Measure every metric for one dmd binary. `tag` ("base"/"head") // keeps the two runs' temp files apart -long[string] measure(string dmd, string workload, string phobos, string tmp, string tag) +Measurement measure(string dmd, string workload, string phobos, string tmp, string tag) { auto stdPackage = buildPath(phobos, "std", "package.d"); auto phobosFlags = ["-i=std", "-preview=dip1000"]; - return [ + Measurement m; + m.metrics = [ "compile_hello_debug_instr": instructions(dmd, [], workload, tmp, tag ~ "-dbg"), "compile_hello_release_instr": instructions(dmd, ["-O", "-release"], workload, tmp, tag ~ "-rel"), "compile_phobos_instr": instructions(dmd, phobosFlags, stdPackage, tmp, tag ~ "-phobos"), @@ -43,6 +53,9 @@ long[string] measure(string dmd, string workload, string phobos, string tmp, str "hello_max_rss": maxRss(dmd, [], workload, tmp, tag), "phobos_max_rss": maxRss(dmd, phobosFlags, stdPackage, tmp, tag ~ "-phobos"), ]; + m.helloTrace = collectTrace(dmd, [], workload, tmp, tag ~ "-hello"); + m.phobosTrace = collectTrace(dmd, phobosFlags, stdPackage, tmp, tag ~ "-phobos"); + return m; } // Byte size of `binary` diff --git a/tools/perfrunner/source/report.d b/tools/perfrunner/source/report.d index a28e7217a086..88c613bf1a57 100644 --- a/tools/perfrunner/source/report.d +++ b/tools/perfrunner/source/report.d @@ -4,6 +4,7 @@ import std.json : JSONValue, parseJSON; import std.math : round; import stats : deltaPct; +import timetrace : Trace, phaseIds; struct MetricResult { @@ -24,6 +25,8 @@ struct Report string os; string hostDmd; MetricResult[] metrics; + Trace helloBase, helloHead; + Trace phobosBase, phobosHead; } // Serialise a report to the initial schema @@ -44,16 +47,43 @@ string render(Report rep) } JSONValue root = [ - "schema_version": JSONValue(1), + "schema_version": JSONValue(2), "base": JSONValue(["sha": JSONValue(rep.baseSha), "ref": JSONValue(rep.baseRef)]), "head": JSONValue(["sha": JSONValue(rep.headSha), "pr": JSONValue(rep.pr)]), "runner": JSONValue(["os": JSONValue(rep.os), "host_dmd": JSONValue(rep.hostDmd)]), "metrics": JSONValue(metrics), + "time_trace": JSONValue([ + "note": JSONValue("informational, wall-clock, non-gating"), + "hello": traceJson(rep.helloBase, rep.helloHead), + "phobos": traceJson(rep.phobosBase, rep.phobosHead), + ]), ]; return root.toPrettyString(); } +// Base/head pair of self-times (microseconds). Percentages are derived later. +private JSONValue pair(long base, long head) +{ + return JSONValue(["base": JSONValue(base), "head": JSONValue(head)]); +} + +// Serialise one workload's base/head -ftime-trace breakdown (raw self-times). +private JSONValue traceJson(Trace b, Trace h) +{ + JSONValue[string] phases; + foreach (id; phaseIds) + phases[id] = pair(b.phase(id), h.phase(id)); + + return JSONValue([ + "available": JSONValue(["base": JSONValue(b.available), "head": JSONValue(h.available)]), + "total_us": pair(b.total, h.total), + "frontend": pair(b.frontend, h.frontend), + "backend": pair(b.backend, h.backend), + "phases": JSONValue(phases), + ]); +} + unittest { auto rep = Report("base1", "merge-base", "head1", 7, "ubuntu-latest", "2.112.0", @@ -61,7 +91,7 @@ unittest "count", "cachegrind", 1000, 1010)]); auto j = parseJSON(render(rep)); - assert(j["schema_version"].integer == 1); + assert(j["schema_version"].integer == 2); assert(j["base"]["sha"].str == "base1"); assert(j["head"]["pr"].integer == 7); assert(j["metrics"].array.length == 1); diff --git a/tools/perfrunner/source/timetrace.d b/tools/perfrunner/source/timetrace.d new file mode 100644 index 000000000000..f0e3523583c9 --- /dev/null +++ b/tools/perfrunner/source/timetrace.d @@ -0,0 +1,107 @@ +module timetrace; + +import std.algorithm : sort, startsWith; +import std.file : exists, readText; +import std.json : JSONValue, parseJSON; +import std.path : buildPath; +import std.process : execute; + +// Ordered phase buckets we report. Frontend = parse..ctfe, backend = inline+codegen. +immutable string[] phaseIds = ["parse", "sema1", "sema2", "sema3", "ctfe", "inline", "codegen"]; + +// Per-phase self-time (microseconds) aggregated from one -ftime-trace run. +// `available` is false when the compiler doesn't support -ftime-trace (old base). +struct Trace +{ + bool available; + long[string] selfUs; + + long phase(string id) const { return selfUs.get(id, 0); } + long frontend() const { return phase("parse") + phase("sema1") + phase("sema2") + phase("sema3") + phase("ctfe"); } + long backend() const { return phase("inline") + phase("codegen"); } + long total() const { return frontend + backend; } +} + +// Compile the workload with -ftime-trace and aggregate the trace into phases. +Trace collectTrace(string dmd, string[] dflags, string workload, string tmp, string tag) +{ + auto obj = buildPath(tmp, tag ~ "-tt.o"); + auto tracePath = buildPath(tmp, tag ~ ".trace"); + auto cmd = [dmd, "-ftime-trace", "-ftime-trace-file=" ~ tracePath, "-c"] + ~ dflags ~ [workload, "-of=" ~ obj]; + auto r = execute(cmd); + if (r.status != 0 || !exists(tracePath)) + return Trace(false); + return parseTrace(readText(tracePath)); +} + +// Map a trace event name to its phase bucket, or null to ignore it. +private string phaseOf(string name) +{ + if (name.startsWith("Pars")) return "parse"; + if (name.startsWith("Sema1")) return "sema1"; + if (name.startsWith("Sema2")) return "sema2"; + if (name.startsWith("Sema3")) return "sema3"; + if (name.startsWith("Ctfe")) return "ctfe"; + if (name.startsWith("Import")) return "sema1"; + if (name.startsWith("Semantic")) return "sema1"; + if (name.startsWith("Inlin")) return "inline"; + if (name.startsWith("Codegen") || name.startsWith("Code generation")) return "codegen"; + if (name.startsWith("DFA")) return "codegen"; + return null; +} + +// Parse a chrome-trace JSON string into per-phase self-times. +Trace parseTrace(string json) +{ + struct Ev { string name; long ts; long dur; } + Ev[] evs; + foreach (e; parseJSON(json)["traceEvents"].array) + { + if (e["ph"].str != "X") + continue; + evs ~= Ev(e["name"].str, e["ts"].integer, e["dur"].integer); + } + + // Reconstruct nesting (single-threaded, so intervals nest cleanly) and + // subtract each event's direct children to get its self-time. + sort!((a, b) => a.ts != b.ts ? a.ts < b.ts : a.dur > b.dur)(evs); + auto childUs = new long[evs.length]; + size_t[] stack; + foreach (i, e; evs) + { + while (stack.length && evs[stack[$ - 1]].ts + evs[stack[$ - 1]].dur <= e.ts) + stack = stack[0 .. $ - 1]; + if (stack.length) + childUs[stack[$ - 1]] += e.dur; + stack ~= i; + } + + Trace t = { available: true }; + foreach (i, e; evs) + if (auto ph = phaseOf(e.name)) + t.selfUs[ph] += e.dur - childUs[i]; + return t; +} + +unittest +{ + auto sample = `{ +"beginningOfTime":0, +"traceEvents": [ +{"ph":"M","name":"process_name"}, +{"ph":"X","name": "Parsing","ts":0,"dur":100}, +{"ph":"X","name": "Semantic analysis","ts":100,"dur":80}, +{"ph":"X","name": "Sema1: Function add","ts":100,"dur":50}, +{"ph":"X","name": "Code generation","ts":200,"dur":40} +] +}`; + auto t = parseTrace(sample); + assert(t.available); + assert(t.phase("parse") == 100); + assert(t.phase("sema1") == 80); // 30 self of container + 50 of the function + assert(t.phase("codegen") == 40); + assert(t.frontend == 180); + assert(t.backend == 40); + assert(t.total == 220); +} From a1d157f8ebb5b859a54241589912ff19fc850de0 Mon Sep 17 00:00:00 2001 From: Abul Date: Fri, 24 Jul 2026 19:59:14 +0530 Subject: [PATCH 2/3] simplify total time calculation --- tools/perfrunner/source/report.d | 8 ++------ tools/perfrunner/source/timetrace.d | 22 ++++++++++------------ 2 files changed, 12 insertions(+), 18 deletions(-) diff --git a/tools/perfrunner/source/report.d b/tools/perfrunner/source/report.d index 88c613bf1a57..f2c225c64635 100644 --- a/tools/perfrunner/source/report.d +++ b/tools/perfrunner/source/report.d @@ -53,7 +53,6 @@ string render(Report rep) "runner": JSONValue(["os": JSONValue(rep.os), "host_dmd": JSONValue(rep.hostDmd)]), "metrics": JSONValue(metrics), "time_trace": JSONValue([ - "note": JSONValue("informational, wall-clock, non-gating"), "hello": traceJson(rep.helloBase, rep.helloHead), "phobos": traceJson(rep.phobosBase, rep.phobosHead), ]), @@ -76,11 +75,8 @@ private JSONValue traceJson(Trace b, Trace h) phases[id] = pair(b.phase(id), h.phase(id)); return JSONValue([ - "available": JSONValue(["base": JSONValue(b.available), "head": JSONValue(h.available)]), - "total_us": pair(b.total, h.total), - "frontend": pair(b.frontend, h.frontend), - "backend": pair(b.backend, h.backend), - "phases": JSONValue(phases), + "total_us": pair(b.total, h.total), + "phases": JSONValue(phases), ]); } diff --git a/tools/perfrunner/source/timetrace.d b/tools/perfrunner/source/timetrace.d index f0e3523583c9..9d6f5656873a 100644 --- a/tools/perfrunner/source/timetrace.d +++ b/tools/perfrunner/source/timetrace.d @@ -9,20 +9,21 @@ import std.process : execute; // Ordered phase buckets we report. Frontend = parse..ctfe, backend = inline+codegen. immutable string[] phaseIds = ["parse", "sema1", "sema2", "sema3", "ctfe", "inline", "codegen"]; -// Per-phase self-time (microseconds) aggregated from one -ftime-trace run. -// `available` is false when the compiler doesn't support -ftime-trace (old base). struct Trace { - bool available; long[string] selfUs; long phase(string id) const { return selfUs.get(id, 0); } - long frontend() const { return phase("parse") + phase("sema1") + phase("sema2") + phase("sema3") + phase("ctfe"); } - long backend() const { return phase("inline") + phase("codegen"); } - long total() const { return frontend + backend; } + long total() const + { + long sum; + foreach (id; phaseIds) + sum += phase(id); + return sum; + } } -// Compile the workload with -ftime-trace and aggregate the trace into phases. +// Compile the workload with -ftime-trace Trace collectTrace(string dmd, string[] dflags, string workload, string tmp, string tag) { auto obj = buildPath(tmp, tag ~ "-tt.o"); @@ -31,7 +32,7 @@ Trace collectTrace(string dmd, string[] dflags, string workload, string tmp, str ~ dflags ~ [workload, "-of=" ~ obj]; auto r = execute(cmd); if (r.status != 0 || !exists(tracePath)) - return Trace(false); + throw new Exception("-ftime-trace compile failed:\n" ~ r.output); return parseTrace(readText(tracePath)); } @@ -77,7 +78,7 @@ Trace parseTrace(string json) stack ~= i; } - Trace t = { available: true }; + Trace t; foreach (i, e; evs) if (auto ph = phaseOf(e.name)) t.selfUs[ph] += e.dur - childUs[i]; @@ -97,11 +98,8 @@ unittest ] }`; auto t = parseTrace(sample); - assert(t.available); assert(t.phase("parse") == 100); assert(t.phase("sema1") == 80); // 30 self of container + 50 of the function assert(t.phase("codegen") == 40); - assert(t.frontend == 180); - assert(t.backend == 40); assert(t.total == 220); } From 91631e7b11bc0e2bfde3432962220230fc4ac361 Mon Sep 17 00:00:00 2001 From: Abul Date: Fri, 24 Jul 2026 20:31:39 +0530 Subject: [PATCH 3/3] clean up --- tools/perfrunner/source/metrics.d | 1 - tools/perfrunner/source/report.d | 2 -- tools/perfrunner/source/timetrace.d | 11 +++++------ 3 files changed, 5 insertions(+), 9 deletions(-) diff --git a/tools/perfrunner/source/metrics.d b/tools/perfrunner/source/metrics.d index d1ed4cf1fe05..329493733468 100644 --- a/tools/perfrunner/source/metrics.d +++ b/tools/perfrunner/source/metrics.d @@ -29,7 +29,6 @@ immutable MetricDef[] initials = [ MetricDef("phobos_max_rss", "peak RSS (compile Phobos)", "kb", "time -v"), ]; -// The flat metrics plus the informational -ftime-trace breakdowns. struct Measurement { long[string] metrics; diff --git a/tools/perfrunner/source/report.d b/tools/perfrunner/source/report.d index f2c225c64635..1989734b44f5 100644 --- a/tools/perfrunner/source/report.d +++ b/tools/perfrunner/source/report.d @@ -61,13 +61,11 @@ string render(Report rep) return root.toPrettyString(); } -// Base/head pair of self-times (microseconds). Percentages are derived later. private JSONValue pair(long base, long head) { return JSONValue(["base": JSONValue(base), "head": JSONValue(head)]); } -// Serialise one workload's base/head -ftime-trace breakdown (raw self-times). private JSONValue traceJson(Trace b, Trace h) { JSONValue[string] phases; diff --git a/tools/perfrunner/source/timetrace.d b/tools/perfrunner/source/timetrace.d index 9d6f5656873a..489c4c76d5b6 100644 --- a/tools/perfrunner/source/timetrace.d +++ b/tools/perfrunner/source/timetrace.d @@ -6,7 +6,7 @@ import std.json : JSONValue, parseJSON; import std.path : buildPath; import std.process : execute; -// Ordered phase buckets we report. Frontend = parse..ctfe, backend = inline+codegen. +// Phase buckets, in the order we report them. immutable string[] phaseIds = ["parse", "sema1", "sema2", "sema3", "ctfe", "inline", "codegen"]; struct Trace @@ -36,7 +36,7 @@ Trace collectTrace(string dmd, string[] dflags, string workload, string tmp, str return parseTrace(readText(tracePath)); } -// Map a trace event name to its phase bucket, or null to ignore it. +// Map a trace event name to its phase bucket private string phaseOf(string name) { if (name.startsWith("Pars")) return "parse"; @@ -52,7 +52,7 @@ private string phaseOf(string name) return null; } -// Parse a chrome-trace JSON string into per-phase self-times. +// Chrome-trace JSON string into per-phase self-times. Trace parseTrace(string json) { struct Ev { string name; long ts; long dur; } @@ -64,8 +64,7 @@ Trace parseTrace(string json) evs ~= Ev(e["name"].str, e["ts"].integer, e["dur"].integer); } - // Reconstruct nesting (single-threaded, so intervals nest cleanly) and - // subtract each event's direct children to get its self-time. + // Reconstruct nesting and subtract each event's direct children to get its self-time. sort!((a, b) => a.ts != b.ts ? a.ts < b.ts : a.dur > b.dur)(evs); auto childUs = new long[evs.length]; size_t[] stack; @@ -99,7 +98,7 @@ unittest }`; auto t = parseTrace(sample); assert(t.phase("parse") == 100); - assert(t.phase("sema1") == 80); // 30 self of container + 50 of the function + assert(t.phase("sema1") == 80); assert(t.phase("codegen") == 40); assert(t.total == 220); }