Add --ftime-trace to dmd #16363

dkorpel · 2024-04-07T19:13:54Z

Reboot of #13965

This feature has been in LDC for a while now with success, and inclusion into dmd has been pre-approved a long time ago by Walter, but the PR has stalled since then. There's improvements possible with choosing better zones and refactoring the code, but for now I focused on making it closely match LDC's current implementation.

For this PR, I still need to include the timetrace2txt tool, and test it a bit better.

dlang-bot · 2024-04-07T19:13:57Z

Thanks for your pull request and interest in making D better, @dkorpel! We are looking forward to reviewing it, and you should be hearing from a maintainer soon.
Please verify that your PR follows this checklist:

My PR is fully covered with tests (you can see the coverage diff by visiting the details link of the codecov check)
My PR is as minimal as possible (smaller, focused PRs are easier to review than big ones)
I have provided a detailed rationale explaining my changes
New or modified functions have Ddoc comments (with Params: and Returns:)

Please see CONTRIBUTING.md for more information.

If you have addressed all reviews or aren't sure how to proceed, don't hesitate to ping us with a simple comment.

Bugzilla references

Your PR doesn't reference any Bugzilla issue.

If your PR contains non-trivial changes, please reference a Bugzilla issue or create a manual changelog.

Testing this PR locally

If you don't have a local development environment setup, you can use Digger to test this PR:

dub run digger -- build "master + dmd#16363"

ibuclaw · 2024-04-07T20:04:09Z

compiler/src/dmd/timetrace.d

+extern(C++)
+void timeTraceProfilerBegin(const(char)* name_ptr, const(char)* detail_ptr, Loc loc)
+{
+    import dmd.root.rmem : xarraydup;
+    import core.stdc.string : strdup;
+
+    assert(timeTraceProfiler);
+
+    timeTraceProfiler.beginScope(xarraydup(name_ptr.toDString()),
+                                 xarraydup(detail_ptr.toDString()), loc);
+}
+
+extern(C++)
+void timeTraceProfilerEnd()


These are defined but never used. Though actually using these would be preferable to a D struct, as it at least would be overridable to allow alternative time measuring engines to be used.

As mentioned in the PR description, it's currently closely matching LDC's code. I have lots of ideas to refactor the code to be better DMD style, but I'd like to know from LDC maintainers if they plan on keeping their own copy of timetrace.d or whether they want to share with upstream. In that case we need to keep a C++ interface.

In that case we need to keep a C++ interface.

That is what the second sentence is advocating for. The frontend semantic passes are using a D interface and RAII. It would integrate better if it used these C++ hooks instead.

(It would be even better if each stage being traced had an enum value, rather than passing a string name and detail, but one request at a time to nudge it in the right direction).

In LDC, we call these C++ functions in a RAII class and only the RAII class is ever used elsewhere. It is very bug prone to not use RAII, so the D code also uses a RAII struct.

I added an enum value for each stage, and now use D functions (because they take a delegate) with help of scope (exit) for safety, while also keeping the C++ interface for LDC.

ibuclaw · 2024-04-07T20:07:36Z

compiler/src/dmd/timetrace.d

+void writeTimeTraceProfile(const(char)* filename_cstr)
+{
+    if (!timeTraceProfiler)
+        return;
+
+    const filename = getTimeTraceProfileFilename(filename_cstr);
+
+    OutBuffer buf;


Consider returning an OutBuffer, or moving this buf local to a ref parameter. Doing IO inside public API is regarded as bad style, and rules it out from being unittest-able.

I moved file IO to main.d

JohanEngelen · 2024-04-19T11:49:13Z

changelog/dmd.ftime-trace.dd

@@ -11,6 +11,6 @@ This will output `app.o.time-trace`.

 A different output file can be selected with `-ftime-trace-file=trace.json`.

-The output is in Google Chrome's profiler format, which can be converted to readable text with the included `timetrace2txt` tool, or be viewed in an interactive viewer like [ui.perfetto.dev](https://ui.perfetto.dev).


I think the timetrace2txt tool is a necessity for practical use. Traces get very large quite quickly, and then the browser-based visual tooling becomes pretty slow (last time I looked). tracy https://github.com/wolfpld/tracy does have good performance on large traces though.

Yes, it probably needs to be added to https://github.com/dlang/tools and https://github.com/dlang/installer. My plan is to get this PR approved first and then follow up by adding timetrace2txt, since this PR is already pretty big.

JohanEngelen · 2024-04-19T15:40:54Z

compiler/src/dmd/timetrace.d

+This file is originally from LDC (the LLVM D compiler).
+
+Copyright: Copyright (C) 1999-2022 by The D Language Foundation, All Rights Reserved
+Authors:   Johan Engelen, Max Haughton


add yourself here :)

JohanEngelen · 2024-04-19T15:42:04Z

compiler/src/dmd/timetrace.d

+ *   sym = Dsymbol which was analyzed
+ *   e = Expression which was analyzed
+ */
+void timeTraceEndEvent(TimeTraceEventType eventType)


extern(C++) so it can be used by LDC.

overall: think a little about what interface to expose to C++. Delegates are not possible, but it'd be good if C++ can use the TimeTraceEventType, to have output be nicely uniform across backends, and also provide extra string input for that event.

JohanEngelen · 2024-04-19T15:43:49Z

compiler/src/dmd/timetrace.d

+void timeTraceProfilerEnd()
+{
+    assert(timeTraceProfiler);
+    timeTraceProfiler.endScope(TimeTraceEventType.generic, null, null, Loc.initial);


TimeTraceEventType.generic as (default) parameter

dkorpel · 2024-04-19T15:45:12Z

I've tested what the overhead is of normal compilation without -ftime-trace on a copy of Phobos.

hyperfine "dmds0 -i -c mystd/package.d" "dmds1 -i -c mystd/package.d"
Benchmark 1: dmds0 -i -c mystd/package.d
  Time (mean ± σ):      1.540 s ±  0.019 s    [User: 1.213 s, System: 0.316 s]
  Range (min … max):    1.520 s …  1.576 s    10 runs
 
Benchmark 2: dmds1 -i -c mystd/package.d
  Time (mean ± σ):      1.553 s ±  0.011 s    [User: 1.206 s, System: 0.335 s]
  Range (min … max):    1.538 s …  1.572 s    10 runs
 
Summary
  dmds0 -i -c mystd/package.d ran
    1.01 ± 0.01 times faster than dmds1 -i -c mystd/package.d

(dmds0 = master branch, dmds1 = ftime-trace branch)

So ~1% overhead, which is worth it when you see how much build time this feature can save.

ibuclaw · 2024-04-20T11:57:29Z

compiler/src/dmd/dsymbolsem.d

+        timeTraceBeginEvent();
+        scope (exit) timeTraceEndEvent(TimeTraceEventType.sema1Import, imp);


Suggested change

timeTraceBeginEvent();

scope (exit) timeTraceEndEvent(TimeTraceEventType.sema1Import, imp);

timeTraceBeginEvent(TimeTraceEventType.sema1Import);

scope (exit) timeTraceEndEvent(TimeTraceEventType.sema1Import, imp);

If the enum was passed at begin and end then that would be enough for this to work with gcc's time report engine as-is.

compiler/src/dmd/timetrace.d

Pass Outbuffer by ref, move timetrace filename logic to main.d

dkorpel force-pushed the ftime-trace branch 2 times, most recently from 7d5c46c to 8c9b81e Compare April 7, 2024 19:22

dkorpel mentioned this pull request Apr 7, 2024

Merge and use time trace sources into dmd #13965

Closed

ibuclaw reviewed Apr 7, 2024

View reviewed changes

dkorpel force-pushed the ftime-trace branch 5 times, most recently from 9d3e8c5 to 9f85656 Compare April 19, 2024 11:40

JohanEngelen reviewed Apr 19, 2024

View reviewed changes

dkorpel force-pushed the ftime-trace branch from 9f85656 to e3b6648 Compare April 19, 2024 11:53

dkorpel marked this pull request as ready for review April 19, 2024 12:10

JohanEngelen reviewed Apr 19, 2024

View reviewed changes

dkorpel force-pushed the ftime-trace branch 3 times, most recently from 82092ad to ca859c4 Compare April 19, 2024 16:11

ibuclaw reviewed Apr 20, 2024

View reviewed changes

dkorpel force-pushed the ftime-trace branch from ca859c4 to 75457d7 Compare April 22, 2024 12:51

dkorpel added 2 commits April 30, 2024 13:39

Add --ftime-trace to dmd

a7cfda9

Refactor timetrace code for dmd.

c040ad6

Pass Outbuffer by ref, move timetrace filename logic to main.d

dkorpel force-pushed the ftime-trace branch from 75457d7 to c040ad6 Compare April 30, 2024 11:42

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add --ftime-trace to dmd #16363

Add --ftime-trace to dmd #16363

dkorpel commented Apr 7, 2024

dlang-bot commented Apr 7, 2024

ibuclaw Apr 7, 2024 •

edited

dkorpel Apr 7, 2024

ibuclaw Apr 8, 2024

JohanEngelen Apr 12, 2024 •

edited

dkorpel Apr 19, 2024

ibuclaw Apr 7, 2024

maxhaton Apr 12, 2024

dkorpel Apr 19, 2024

JohanEngelen Apr 19, 2024

dkorpel Apr 19, 2024

JohanEngelen Apr 19, 2024

JohanEngelen Apr 19, 2024

JohanEngelen Apr 19, 2024

JohanEngelen Apr 19, 2024

dkorpel commented Apr 19, 2024

ibuclaw Apr 20, 2024 •

edited

		@@ -11,6 +11,6 @@ This will output `app.o.time-trace`.

		A different output file can be selected with `-ftime-trace-file=trace.json`.

		The output is in Google Chrome's profiler format, which can be converted to readable text with the included `timetrace2txt` tool, or be viewed in an interactive viewer like [ui.perfetto.dev](https://ui.perfetto.dev).

		timeTraceBeginEvent();
		scope (exit) timeTraceEndEvent(TimeTraceEventType.sema1Import, imp);

Add --ftime-trace to dmd #16363

Are you sure you want to change the base?

Add --ftime-trace to dmd #16363

Conversation

dkorpel commented Apr 7, 2024

dlang-bot commented Apr 7, 2024

Bugzilla references

Testing this PR locally

ibuclaw Apr 7, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

JohanEngelen Apr 12, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dkorpel commented Apr 19, 2024

ibuclaw Apr 20, 2024 • edited

Choose a reason for hiding this comment

ibuclaw Apr 7, 2024 •

edited

JohanEngelen Apr 12, 2024 •

edited

ibuclaw Apr 20, 2024 •

edited