From 15da933d48ee8a9af1172514e04f63a2a6f41b6f Mon Sep 17 00:00:00 2001 From: Johan Engelen Date: Fri, 3 Mar 2023 20:51:58 +0100 Subject: [PATCH] ftime-trace: add tracing of CTFE ! (#4339) --- dmd/dinterpret.d | 31 +++++++++++++++ driver/timetrace.d | 67 ++++++++++++++++++++++++++++++++- tests/driver/ftime-trace-ctfe.d | 55 +++++++++++++++++++++++++++ tests/driver/ftime-trace.d | 2 +- 4 files changed, 153 insertions(+), 2 deletions(-) create mode 100644 tests/driver/ftime-trace-ctfe.d diff --git a/dmd/dinterpret.d b/dmd/dinterpret.d index 7920df79991..ff0957e6b86 100644 --- a/dmd/dinterpret.d +++ b/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) { diff --git a/driver/timetrace.d b/driver/timetrace.d index f3a23034342..8b40964db27 100644 --- a/driver/timetrace.d +++ b/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) { diff --git a/tests/driver/ftime-trace-ctfe.d b/tests/driver/ftime-trace-ctfe.d new file mode 100644 index 00000000000..5c9eb1ef391 --- /dev/null +++ b/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(); diff --git a/tests/driver/ftime-trace.d b/tests/driver/ftime-trace.d index fd235ed534b..e8c7ab2cfaf 100644 --- a/tests/driver/ftime-trace.d +++ b/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