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..329493733468 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,21 @@ immutable MetricDef[] initials = [ MetricDef("phobos_max_rss", "peak RSS (compile Phobos)", "kb", "time -v"), ]; +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 +52,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..1989734b44f5 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,37 @@ 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([ + "hello": traceJson(rep.helloBase, rep.helloHead), + "phobos": traceJson(rep.phobosBase, rep.phobosHead), + ]), ]; return root.toPrettyString(); } +private JSONValue pair(long base, long head) +{ + return JSONValue(["base": JSONValue(base), "head": JSONValue(head)]); +} + +private JSONValue traceJson(Trace b, Trace h) +{ + JSONValue[string] phases; + foreach (id; phaseIds) + phases[id] = pair(b.phase(id), h.phase(id)); + + return JSONValue([ + "total_us": pair(b.total, h.total), + "phases": JSONValue(phases), + ]); +} + unittest { auto rep = Report("base1", "merge-base", "head1", 7, "ubuntu-latest", "2.112.0", @@ -61,7 +85,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..489c4c76d5b6 --- /dev/null +++ b/tools/perfrunner/source/timetrace.d @@ -0,0 +1,104 @@ +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; + +// Phase buckets, in the order we report them. +immutable string[] phaseIds = ["parse", "sema1", "sema2", "sema3", "ctfe", "inline", "codegen"]; + +struct Trace +{ + long[string] selfUs; + + long phase(string id) const { return selfUs.get(id, 0); } + long total() const + { + long sum; + foreach (id; phaseIds) + sum += phase(id); + return sum; + } +} + +// 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"); + 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)) + throw new Exception("-ftime-trace compile failed:\n" ~ r.output); + return parseTrace(readText(tracePath)); +} + +// Map a trace event name to its phase bucket +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; +} + +// 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 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; + 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.phase("parse") == 100); + assert(t.phase("sema1") == 80); + assert(t.phase("codegen") == 40); + assert(t.total == 220); +}