This is an archive of the discontinued LLVM Phabricator instance.

[LLD][ELF] Add time-trace to ELF LLD (2/2)
ClosedPublic

Authored by russell.gallop on Dec 5 2019, 5:12 AM.

Details

Summary

Following on from RFC here: https://reviews.llvm.org/D69043

This requires the previous patch: https://reviews.llvm.org/D71059

This adds some LLD specific scopes and picks up optimisation scopes via LTO/ThinLTO. This makes use of the TimeProfiler multi-thread support added in first in this series.

Diff Detail

Event Timeline

russell.gallop created this revision.Dec 5 2019, 5:12 AM
Herald added a project: Restricted Project. · View Herald Transcript
russell.gallop edited the summary of this revision. (Show Details)Dec 5 2019, 5:16 AM

Add tests to patch.

anton-afanasyev accepted this revision.Dec 10 2019, 12:27 PM
This revision is now accepted and ready to land.Dec 10 2019, 12:27 PM
ruiu added inline comments.Dec 10 2019, 8:48 PM
lld/ELF/Driver.cpp
533

I think it is better to make -time-trace to just print the result to stdout, as it is convenient.

979

Is u prefix supported?

edit: Oh, this is not for nanosecond but just an unsigned. I'd just remove u.

1624

I'm curious what is supposed to pass as a second argument.

russell.gallop marked 3 inline comments as done.Dec 11 2019, 2:56 AM
russell.gallop added inline comments.
lld/ELF/Driver.cpp
533

Hmm, I went for this as it was more consistent with the comparable compiler option.

I do find this behaviour useful if you are tracing a build such as llvm which has a lot of links. While this probably isn't typical, it does make it easy to send all of the link traces to separate files just by adding a single link option to all links.

What about an option like "-ftime-trace -" to send to stdout?

979

Thanks. Will fix.

1624

This is used for "Detail". E.g. optimisation passes specify which pass they are running on "OptModule" specifies which module it is running on. This helps to distinguish multiples of the same kind of scope in traces. I don't think there is anything useful to detail at this level.

I could add an overloaded constructor to TimeTraceScope with a default to not add "detail". That would cut down on the StringRef("") argument which come up quite a bit. It could also cut down on file size by not writing that block out.

Here are some examples of the output from LLD. One for a llvm-tblgen ThinLTO link (-time-trace-granularity=50000) and a clang Release build (-time-trace-granularity=500). The clang link has some significant gaps in it. I'll see if I can identify where they're from and trace them.

russell.gallop marked an inline comment as done.Dec 11 2019, 5:01 AM
russell.gallop added inline comments.
lld/ELF/Driver.cpp
1624

Created new review for TimeTraceScope constructor to avoid the need for StringRef("") in places like this: https://reviews.llvm.org/D71347

Removed StringRef("") in several places after D71347.
Added some more time scopes to account for gaps in time trace.
Updated tests for args/detail not always being present.

ruiu added inline comments.Dec 11 2019, 6:14 PM
lld/ELF/Driver.cpp
533

Yeah that makes sense, but I think that ".json" extension is the problem. We may want to add a different feature that outputs some data in the JSON format, and if we choose the same design, the option will conflict with the feature that you are adding. How about adding ".time-trace" to an output file then? Also, I don't think we should replace an extension -- usually Unix commands don't have extensions. I'd just append ".time-trace"

lld/ELF/Options.td
367–368

I think that giving two options the same name isn't very conventional as a Unix command, as --foo bar and --foo=bar are usually considered the same option. Could you rename the latter --time-trace-file?

ruiu added a comment.Dec 11 2019, 6:19 PM

Here are some examples of the output from LLD. One for a llvm-tblgen ThinLTO link (-time-trace-granularity=50000) and a clang Release build (-time-trace-granularity=500). The clang link has some significant gaps in it. I'll see if I can identify where they're from and trace them.

These JSON outputs look nice! One feature request -- is there any way to add a key-value to an output JSON file? I mean if we can add something like "argv": ["ld.lld", "-o", ...] to the JSON output it would be great. (You don't need to do that in this patch though.)

Change to appending .time-trace as default name.
Make -time-trace-file a separate option
Use temp names in tests

russell.gallop set the repository for this revision to rG LLVM Github Monorepo.Dec 12 2019, 8:34 AM
russell.gallop marked 4 inline comments as done.

Add test for writing trace to stdout

russell.gallop marked an inline comment as done.Dec 12 2019, 9:06 AM

Thanks for the comments. I believe I've fixed them all now.

ruiu added inline comments.Dec 12 2019, 9:40 PM
lld/ELF/Driver.cpp
504

s/time trace/time trace profiler/

504–508

I'd move this above initLLVM() so that we can measure time consumed by createFiles and other functions.

Please remove llvm::.

531

Let's use the same condition if (config->timeTraceEnabled) as before for consistency.

531

Add a single line comment -- // Write the result of the time trace profiler.

534–535

You could simplify this a little bit as shown below:

std::string path = args.getLastArgValue(OPT_time_trace_file_eq);
if (path.empty())
  path = (config->outputFile + ".time-trace").str();
536–537

Let's use shorter conventional names: ec and os

543

What does this cleanup function do? If some cleanup is needed, can we run it on timeTraceProfilerWrite?

lld/ELF/ICF.cpp
517

This is the entry point function of ICF, so please move the TimeTraceScope here.

MaskRay added inline comments.Dec 12 2019, 10:00 PM
lld/ELF/Driver.cpp
537

OF_Text. F_Text is for compatibility only.

lld/test/ELF/check-time-trace.s
1 ↗(On Diff #233635)

Just time-trace.s?

2 ↗(On Diff #233635)

Delete -unknown-linux

23 ↗(On Diff #233635)

Align keys. See other files (with a llvm-readobj RUN line) for examples

llvm/include/llvm/LTO/Config.h
120

Full stop

russell.gallop marked an inline comment as done.

Fix recent review comments.

russell.gallop marked 9 inline comments as done.Dec 16 2019, 3:26 AM
russell.gallop added inline comments.
lld/ELF/Driver.cpp
543

Cleanup disables the profiler and deletes the data.

This is the design as from the original addition of the time profiler (https://reviews.llvm.org/D58675). I think it allows more flexibility (e.g. we may want to write a text report of the same data) though I don't think we use that flexibility at the moment. I'm not sure what the original reason for this was. @anton-afanasyev please can you comment on why this is and whether timeTraceProfilerCleanup could be combined with timeTraceProfilerWrite? Thanks.

anton-afanasyev marked an inline comment as done.Dec 16 2019, 3:33 AM
anton-afanasyev added inline comments.
lld/ELF/Driver.cpp
543

Yes, that is for the flexibility in a future. We may want in follow-ups to support different Writers (for instance, to terminal). But you are right it could be combined with current Writer for now.

lld/ELF/Driver.cpp
543

*I mean any kind of another output format, short summary for terminal, for instance.

Fix to work with LLVM_ENABLE_THREADS=OFF. In this mode ThinLTO still uses tasks but need to avoid re-initialising the time profiler.

Requires https://reviews.llvm.org/D71548 to avoid thread_local in this mode.

ruiu accepted this revision.Dec 16 2019, 8:53 PM

LGTM

lld/ELF/Driver.cpp
543

OK, I prefer merging the cleanup function with write function because (1) it's less error-prone, and (2) if you need to write a result to two different stream, you can easily do that by writing to a string buffer and then write the buffer contents to two streams. Do you mind if I ask you do that as a follow-up patch?

I have a general question about the llvm::TimeTraceScope timeScope("LTO"); trace sites. Shall we just use the container function name if applicable?

lld/ELF/Driver.cpp
2019

This comment may be misleading.

It creates MergeSyntheticSection's and does other tasks that cannot be summaries by "Merge input sections".

Probably delete the trace here. It shouldn't take a lot of time anyway.

lld/ELF/MarkLive.cpp
327

Probably just reuse the function name: markLive

russell.gallop marked an inline comment as done.Dec 17 2019, 5:35 AM

I have a general question about the llvm::TimeTraceScope timeScope("LTO"); trace sites. Shall we just use the container function name if applicable?

The clang --time-trace feature (https://aras-p.info/blog/2019/01/16/time-trace-timeline-flame-chart-profiler-for-Clang/) is intended to be helpful for users understanding what the tools are doing with their code, not (just) LLVM developers, and I think that this should have the same aim in LLD.

As such, I tried to add scopes that correspond to user visible features (e.g. LTO, GC, ICF), rather than the functions which implement them. In some places this can be tricky as scopes don't always correspond to notional blocks (e.g. clang Frontend). I would prefer to stick with the current names if possible, though there may be better places for them.

lld/ELF/Driver.cpp
2019

Okay, I'll remove this.

russell.gallop marked 5 inline comments as done.

Removed "Merge input sections" scope.
Also moved "ExecuteLinker" to cover longer time period, including initLLVM() etc..

russell.gallop marked an inline comment as done.Dec 17 2019, 7:58 AM
russell.gallop added inline comments.
lld/ELF/Driver.cpp
543

Okay. I'll do that. Seems best as a follow up change as it will affect the time profiler usage in clang as well.

lld/ELF/MarkLive.cpp
327

As I mentioned above, I would like these to make sense to linker users. Is that okay?

Is there a better place to measure for GC?

For code blocks, using a descriptive name seems fine. For a trace added for a whole function, I still prefer using the function name as the trace point name. I think for users who are so familiar with the linker that they know the existence of --time-trace and will like to investigate the bottleneck, the function names should not impair their understanding of the pass names.

lld/ELF/Driver.cpp
1751

I'd prefer "LinkerDriver::link".

lld/ELF/MarkLive.cpp
327

This is the best place, though I still feel "GC" as the name is less ideal than the function name "markLive".

Rename scopes as requested.

@MaskRay, thanks for the comments. Are you happy this is okay to commit now?

lld/ELF/Driver.cpp
1751

Unified scope name like "Link" is good for grouping blocks by chrome://tracing app. Isn't it better to put "LinkerDriver::link" to Details field of timeScope? (though this field is usually used for _user_ source code names, but here it is unused).

russell.gallop marked an inline comment as done.Jan 28 2020, 10:09 AM
russell.gallop added inline comments.
lld/ELF/Driver.cpp
1751

I'll put "LinkerDriver::link" in the Details field.

Longer term it might be better to add another "args" field for function name to distinguish compiler source code names and user source code names.

This revision was automatically updated to reflect the committed changes.
dmajor added a subscriber: dmajor.Feb 10 2020, 7:01 AM

Should this go into the docs / man page / release notes / etc.?

Should this go into the docs / man page / release notes / etc.?

Probably. I'll take a look.

Should this go into the docs / man page / release notes / etc.?

Probably. I'll take a look.

Opened review here: https://reviews.llvm.org/D79780