Page MenuHomePhabricator

[RFC] Adding time-trace to LLD?
Needs ReviewPublic

Authored by russell.gallop on Wed, Oct 16, 8:18 AM.

Details

Summary

The clang -ftime-trace feature is useful for analysing build time in compiles. I've been experimenting with adding time-trace support to LLD for analysing link times.

Adding the option -time-trace produces a .json file alongside the output ELF file (just ELF so far). This works for LTO and ThinLTO, picking up the relevant markers from LLVM. Example ThinLTO build:

This is still work in progress so shouldn't be submitted in its present state. There are a few things that still need doing:

  • Improve how events are collected. (The current method combines multiple threads (ThinLTO) in one stack with a mutex which won't scale well. Making this thread local would probably be better.)
  • Adding test(s)
  • Re-enable the assertion for monotonically increasing times which I don't have working yet.

Do people think that this will be useful/worth pursuing?

Diff Detail

Event Timeline

russell.gallop created this revision.Wed, Oct 16, 8:18 AM
Herald added projects: Restricted Project, Restricted Project. · View Herald Transcript
ormris added a subscriber: ormris.Wed, Oct 16, 9:36 AM
dmajor added a subscriber: dmajor.Wed, Oct 16, 10:31 AM
aganea added a subscriber: aganea.Wed, Oct 16, 10:37 AM
ruiu added a comment.Thu, Oct 17, 3:28 AM

This seems useful. Can I see an example output?

Speaking of the output file, I'd make --time-trace option to take an output filename, as an output executable doesn't always have an extension (On Windows it's almost always .exe, but on Unix, extension is usually omitted).

This seems useful. Can I see an example output?

Thanks.

Here's an example from Building clang with ThinLTO:

Using linker flags: -Wl,-time-trace -Wl,-time-trace-granularity=50000

I increased the granularity from the default, otherwise the trace gets very large (~800MiB).

Speaking of the output file, I'd make --time-trace option to take an output filename, as an output executable doesn't always have an extension (On Windows it's almost always .exe, but on Unix, extension is usually omitted).

Okay. I'll look at doing that.

aganea added inline comments.Thu, Oct 17, 7:04 AM
lld/ELF/Driver.cpp
515

Could you possibly move this block (and the init block above) into a new file in lld/Common/ so we can use it in the COFF driver as well?

527

Extraneous return.

lld/ELF/Options.td
361

Given this option is a candidate for the other LLD drivers, I am wondering if we couldn't have a shared lld/Common/CommonOpt.td. @ruiu WDYT?

llvm/lib/Support/TimeProfiler.cpp
70

The lock is definitely not the way to go, it would skew all the timings especially on tens-of-cores machines. Like you're suggesting, make TimeTraceProfilerInstance a TLS, along with a new combiner upon the call to timeTraceProfilerWrite().

ruiu added a comment.Thu, Oct 17, 9:51 PM

I applied this patch and built clang with ThinLTO. Here is the generated file:

$ less bin/clang-10.json
{"traceEvents":[{"pid":1,"tid":185412,"ph":"X","ts":181,"dur":1441864,"name":"Parse input files","args":{"detail":""}},{"pid":1,"tid":185412,"ph":"X","ts":12564626,"dur":541606,"name":"OptModule","args":{"detail":"ld-temp.o"}},{"pid":1,"tid":185412,"ph":"X","ts":1454232,"dur":17946238,"name":"LTO","args":{"detail":""}},{"pid":1,"tid":185412,"ph":"X","ts":19461534,"dur":15275,"name":"GC","args":{"detail":""}},{"pid":1,"tid":185412,"ph":"X","ts":19721702,"dur":1241569,"name":"Write output file","args":{"detail":""}},{"pid":1,"tid":185412,"ph":"X","ts":2,"dur":20963276,"name":"ExecuteLinker","args":{"detail":""}},{"pid":1,"tid":185413,"ph":"X","ts":0,"dur":20963276,"name":"Total ExecuteLinker","args":{"count":1,"avg ms":20963}},{"pid":1,"tid":185414,"ph":"X","ts":0,"dur":17946237,"name":"Total LTO","args":{"count":1,"avg ms":17946}},{"pid":1,"tid":185415,"ph":"X","ts":0,"dur":1441864,"name":"Total Parse input files","args":{"count":1,"avg ms":1441}},{"pid":1,"tid":185416,"ph":"X","ts":0,"dur":1241569,"name":"Total Write output file","args":{"count":1,"avg ms":1241}},{"pid":1,"tid":185417,"ph":"X","ts":0,"dur":541704,"name":"Total OptModule","args":{"count":2,"avg ms":270}},{"pid":1,"tid":185418,"ph":"X","ts":0,"dur":15274,"name":"Total GC","args":{"count":1,"avg ms":15}},{"cat":"","pid":1,"tid":0,"ts":0,"ph":"M","name":"process_name","args":{"name":"ld.lld"}}]}

This file seems much smaller than yours. What am I missing? (I couldn't download your file because the server times out perhaps due to the file size.)

ruiu added inline comments.Thu, Oct 17, 10:50 PM
lld/ELF/Options.td
361

In many cases command line options are slightly different among drivers. so currently we have a completely separated option file for each driver. It looks like maintaining each file separately makes things much easier, so I wouldn't create a new common file.

I applied this patch and built clang with ThinLTO. Here is the generated file:
This file seems much smaller than yours. What am I missing?

I have seen some very empty looking traces when ThinLTO doesn't have much to do. Is it possible that the ThinLTO cache is doing a very good job?

(I couldn't download your file because the server times out perhaps due to the file size.)

That's odd. I can download it okay from here.

(I couldn't download your file because the server times out perhaps due to the file size.)

That's odd. I can download it okay from here.

It probably was a temporary issue. I was unable to download it ~2h ago too, but now it works fine for me.