Integrating time tracing metrics in perf

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;

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`

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,24 +47,45 @@ 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",
         [MetricResult("compile_hello_debug_instr", "compile hello.d (instr)",
             "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);

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;
+
+// Ordered phase buckets we report. Frontend = parse..ctfe, backend = inline+codegen.
+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);
+}