ftime-trace: add tracing of CTFE ! (#4339)

dmd/dinterpret.d

@@ -98,6 +98,12 @@ public Expression ctfeInterpret(Expression e)
 
     auto rgnpos = ctfeGlobals.region.savePos();
 
+    version (IN_LLVM)
+    {
+        import driver.timetrace, std.format, std.conv;
+        auto timeScope = TimeTraceScope(text("CTFE start: ", e.toChars()), e.toChars().to!string, e.loc);
+    }
+
     Expression result = interpret(e, null);
 
     // Report an error if the expression contained a `ThrowException` and
@@ -429,6 +435,31 @@ private Expression interpretFunction(UnionExp* pue, FuncDeclaration fd, InterSta
     {
         printf("\n********\n%s FuncDeclaration::interpret(istate = %p) %s\n", fd.loc.toChars(), istate, fd.toChars());
     }
+
+    version (IN_LLVM)
+    {
+        import driver.timetrace, std.format, std.conv;
+        scope dlg = () {
+                            import dmd.common.outbuffer;
+                            auto strbuf = OutBuffer(20);
+                            strbuf.writestring(fd.toPrettyChars());
+                            strbuf.write("(");
+                            if (arguments)
+                            {
+                                foreach (i, arg; *arguments)
+                                {
+                                    if (i > 0)
+                                        strbuf.write(", ");
+                                    strbuf.writestring(arg.toChars());
+                                }
+                            }
+                            strbuf.write(")");
+                            return strbuf.extractSlice();
+                        };
+        auto timeScope = TimeTraceScopeDelayedDetail(text("CTFE func: ", fd.toChars()), dlg, fd.loc);
+    }
+
+
     assert(pue);
     if (fd.semanticRun == PASS.semantic3)
     {

driver/timetrace.d

@@ -209,6 +209,24 @@ struct TimeTraceProfiler
         }
     }
 
+    /// Takes ownership of the string returned by `details`.
+    void endScopeUpdateDetails(scope const(char)[] delegate() details)
+    {
+        TimeTicks timeEnd = getTimeTicks();
+
+        DurationEvent event = durationStack.pop();
+        event.timeDuration = timeEnd - event.timeBegin;
+        if (event.timeDuration >= timeGranularity)
+        {
+            // Event passes the logging threshold
+            event.details = details();
+            event.timeBegin -= beginningOfTime;
+            durationEvents.push(event);
+            counterEvents.push(generateCounterEvent(timeEnd-beginningOfTime));
+        }
+    }
+
+
     CounterEvent generateCounterEvent(TimeTicks timepoint)
     {
         static import dmd.root.rmem;
@@ -388,14 +406,61 @@ struct TimeTraceScope
             timeTraceProfiler.beginScope(name.dup, detail.dup, loc);
         }
     }
+    /// Takes ownership of string returned by `detail`.
+    this(lazy string name, scope const(char)[] delegate() detail, Loc loc = Loc())
+    {
+        if (timeTraceProfilerEnabled())
+        {
+            assert(timeTraceProfiler);
+            // `loc` contains a pointer to a string, so we need to duplicate that too.
+            import core.stdc.string : strdup;
+            if (loc.filename)
+                loc.filename = strdup(loc.filename);
+            timeTraceProfiler.beginScope(name.dup, detail(), loc);
+        }
+    }
 
     ~this()
     {
         if (timeTraceProfilerEnabled())
-            timeTraceProfilerEnd();
+            timeTraceProfiler.endScope();
     }
 }
 
+/// RAII helper class to call the begin and end functions of the time trace
+/// profiler.  When the object is constructed, it begins the section; and when
+/// it is destroyed, it stops it.
+/// Delays string evaluation (via delegate) until the object is destroyed and the delegate
+/// is only called when the event passes the granularity threshold.
+struct TimeTraceScopeDelayedDetail
+{
+    @disable this();
+    @disable this(this);
+
+    const(char)[] delegate() details_dlg;
+
+    /// Takes ownership of string returned by `detail`.
+    /// `detail` is stored in the struct, but does not escape the lifetime of the struct object.
+    this(lazy string name, scope const(char)[] delegate() detail, Loc loc = Loc()) scope @system
+    {
+        if (timeTraceProfilerEnabled())
+        {
+            assert(timeTraceProfiler);
+            // `loc` contains a pointer to a string, so we need to duplicate that too.
+            import core.stdc.string : strdup;
+            if (loc.filename)
+                loc.filename = strdup(loc.filename);
+            details_dlg = detail;
+            timeTraceProfiler.beginScope(name.dup, "", loc);
+        }
+    }
+
+    ~this()
+    {
+        if (timeTraceProfilerEnabled())
+            timeTraceProfiler.endScopeUpdateDetails(details_dlg);
+    }
+}
 
 private void writeEscapeJSONString(OutBuffer* buf, const(char[]) str)
 {

tests/driver/ftime-trace-ctfe.d

@@ -0,0 +1,55 @@
+// Test --ftime-trace functionality: CTFE
+
+// RUN: %ldc -c --ftime-trace --ftime-trace-granularity=100 --ftime-trace-file=%t.1 %s && FileCheck %s < %t.1
+
+// CHECK: traceEvents
+
+// CHECK-DAG: CTFE func: mulmul
+// CHECK-DAG: CTFE start: Thing
+// CHECK-DAG: CTFE func: muloddmul
+// CHECK-DAG: ExecuteCompiler
+
+module ftimetrace;
+
+int mulmul(int i) {
+    int mul = 666;
+    for (; i > 0; i--)
+    {
+        mul *= i;
+    }
+    return mul;
+}
+
+
+int times(int mul, int i){
+    return mul * i;
+}
+
+int muloddmul(int i) {
+    int mul = 666;
+    for (; i > 0; i--)
+    {
+        mul = times(mul, i);
+    }
+    return mul;
+}
+
+struct Thing {
+    int m;
+    this(int i) {
+        if (i % 2) {
+            m = muloddmul(i);
+        } else {
+            m = mulmul(i);
+        }
+    }
+}
+
+static immutable Thing thing = Thing(123000);
+
+int foo() {
+    auto thing2 = new Thing(123001);
+    return 1;
+}
+
+enum f = foo();

tests/driver/ftime-trace.d

@@ -1,6 +1,6 @@
 // Test --ftime-trace functionality
 
-// RUN: %ldc --ftime-trace --ftime-trace-file=%t.1 --ftime-trace-granularity=1 %s && FileCheck --check-prefix=ALL --check-prefix=FINE %s < %t.1
+// RUN: %ldc --ftime-trace --ftime-trace-file=%t.1 --ftime-trace-granularity=10 %s && FileCheck --check-prefix=ALL --check-prefix=FINE %s < %t.1
 // RUN: %ldc --ftime-trace --ftime-trace-file=%t.2 --ftime-trace-granularity=20000 %s && FileCheck --check-prefix=ALL --check-prefix=COARSE %s < %t.2
 
 // RUN: %ldc --ftime-trace --ftime-trace-file=- --ftime-trace-granularity=20000 %s | FileCheck --check-prefix=ALL --check-prefix=COARSE %s