[SR-1788] Add -driver-time-compilation option #4367

modocache · 2016-08-18T05:27:24Z

What's in this pull request?

Add an option to print the time it takes each driver task to complete.

Here's an example of the output:

$ swiftc -driver-time-compilation \
         -emit-library -module-name Crispix \
         Crispix/A.swift Crispix/B.swift Crispix/C.swift
===-------------------------------------------------------------------------===
                            Driver Time Compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0000 seconds (0.0892 wall clock)

   ---Wall Time---  --- Name ---
   0.0242 ( 27.1%)  /path/to/bin/swift -frontend -c -primary-file /path/to/Crispix/A.swift /path/to/Crispix/B.swift /path/to/Crispix/C.swift -target x86_64-unknown-linux-gnu -disable-objc-interop -color-diagnostics -parse-as-library -module-name Crispix -o /tmp/A-216874.o

   0.0239 ( 26.7%)  /usr/bin/clang++ -shared -fuse-ld=gold -target x86_64-unknown-linux-gnu -Xlinker -rpath -Xlinker /path/to/lib/swift/linux /path/to/lib/swift/linux/x86_64/swift_begin.o /tmp/A-216874.o /tmp/B-243ab4.o /tmp/C-5af361.o -L /path/to/lib/swift/linux --target=x86_64-unknown-linux-gnu -lswiftCore @/tmp/A-864579.autolink /path/to/lib/swift/linux/x86_64/swift_end.o -o libCrispix.so

   0.0205 ( 23.0%)  /path/to/bin/swift -frontend -c /path/to/Crispix/A.swift -primary-file /path/to/Crispix/B.swift /path/to/Crispix/C.swift -target x86_64-unknown-linux-gnu -disable-objc-interop -color-diagnostics -parse-as-library -module-name Crispix -o /tmp/B-243ab4.o

   0.0174 ( 19.6%)  /path/to/bin/swift -frontend -c /path/to/Crispix/A.swift /path/to/Crispix/B.swift -primary-file /path/to/Crispix/C.swift -target x86_64-unknown-linux-gnu -disable-objc-interop -color-diagnostics -parse-as-library -module-name Crispix -o /tmp/C-5af361.o

   0.0032 (  3.6%)  /path/to/bin/swift-autolink-extract /tmp/A-216874.o /tmp/B-243ab4.o /tmp/C-5af361.o -o /tmp/A-864579.autolink

   0.0892 (100.0%)  Total

I don't write C++ very often, and this is probably one of the larger changes I've made to lib/Driver, so I wouldn't be surprised if there's some wacky code in here. 😅 Any and all feedback welcome!

/cc @jrose-apple @gottesmm

Resolved bug number: (SR-1788)

Before merging this pull request to apple/swift repository:

Test pull request on Swift continuous integration.

Triggering Swift CI

The swift-ci is triggered by writing a comment on this PR addressed to the GitHub user @swift-ci. Different tests will run depending on the specific comment that you use. The currently available comments are:

Smoke Testing

Platform	Comment
All supported platforms	@swift-ci Please smoke test
All supported platforms	@swift-ci Please smoke test and merge
OS X platform	@swift-ci Please smoke test OS X platform
Linux platform	@swift-ci Please smoke test Linux platform

A smoke test on macOS does the following:

Builds the compiler incrementally.
Builds the standard library only for macOS. Simulator standard libraries and
device standard libraries are not built.
lldb is not built.
The test and validation-test targets are run only for macOS. The optimized
version of these tests are not run.

A smoke test on Linux does the following:

Builds the compiler incrementally.
Builds the standard library incrementally.
lldb is built incrementally.
The swift test and validation-test targets are run. The optimized version of these
tests are not run.
lldb is tested.

Validation Testing

Platform	Comment
All supported platforms	@swift-ci Please test
All supported platforms	@swift-ci Please test and merge
OS X platform	@swift-ci Please test OS X platform
OS X platform	@swift-ci Please benchmark
Linux platform	@swift-ci Please test Linux platform

Lint Testing

Language	Comment
Python	@swift-ci Please Python lint

Note: Only members of the Apple organization can trigger swift-ci.

modocache · 2016-08-18T05:29:40Z

@swift-ci please test

modocache · 2016-08-18T06:18:29Z

The Linux failures are occurring when compiling swift-corelibs-foundation, and appear to be unrelated.

gottesmm · 2016-08-18T07:24:42Z

@jrose-apple is really the person to review this, but taking a quick look I have some comments.

gottesmm · 2016-08-18T07:43:00Z

lib/Driver/Compilation.cpp

@@ -421,14 +424,26 @@ int Compilation::performJobsImpl() {
  }

  int Result = EXIT_SUCCESS;
+  llvm::TimerGroup DriverTimerGroup("Driver Time Compilation");
+  std::map<std::string, std::unique_ptr<llvm::Timer>> DriverTimers;


Given how the code is written, couldn't use an RAII type to hide all of this? I am imagining an API like:

// We want to make sure map is not allocating memory here unless we have ShowDriverTimeCompilation actually enabled. So I imagine you want something like SharedTimer has. SimpleTimerGroup Group; llvm::SmallString<128> CmdLine; auto taskBegin = ... { if (ShowDriverTimeCompilation) { BeginCmd->printCommandLine(CmdLine); Group.startTimer(CmdLine) } } ...

I think this is a perfectly good approach, except the map should be from Job * to timer instead of command-line-string to timer. (At which point I suggest using an llvm::DenseMap, which is a hash map. See the LLVM Programmer's Manual for more nifty data structures.)

jrose-apple · 2016-08-18T18:39:11Z

This is looking great. I wonder how it interacts with -parseable-output, though. I do want to make sure that if someone puts this in their OTHER_SWIFT_FLAGS in Xcode that it shows up in the build log and doesn't mess up printing warnings from individual files.

(That's not something that necessarily makes sense to put in a regression test, but it's worth seeing what the behavior is before we commit. I think it'll be fine because I think I've used -driver-show-incremental in an Xcode project before.)

modocache · 2016-08-19T12:27:20Z

When using both -parseable-output and -driver-time-compilation, the timer output appears after the parseable output: https://gist.github.com/modocache/588a47488e0c1c0d7dc793e71d1ff57c -- is that OK?

modocache · 2016-08-19T14:30:01Z

Thanks for all the great feedback! I think I addressed everything I can.

@swift-ci please test

jrose-apple · 2016-08-19T17:08:48Z

lib/Driver/Compilation.cpp

+      DriverTimers.insert({
+        BeganCmd,
+        std::unique_ptr<llvm::Timer>(
+          new llvm::Timer(CmdLine.str(), DriverTimerGroup))


Bonus tip: if you call str() on the raw_svector_ostream instead of the SmallString, you don't have to force its destructor to be called.

gottesmm · 2016-08-19T18:23:29Z

@swift-ci Please test

gottesmm · 2016-08-19T18:24:03Z

@modocache I don't think you actually triggered swift-ci. I pushed the button again.

modocache · 2016-08-19T22:00:43Z

Thanks for the follow-ups @jrose-apple. I think I've responded to them all. Now let's see if Swift CI still listens to me...

@swift-ci Please test

jrose-apple · 2016-08-19T22:49:02Z

Sort of. OS X tests here

jrose-apple · 2016-08-19T22:54:50Z

test/Driver/driver-time-compilation.swift

+// CHECK: ---Wall Time---
+// CHECK: --- Name ---
+// CHECK: driver-time-compilation.swift
+// CHECK: {{[0-9]+}}.{{[0-9]+}} (100.0%)  Total


Looks good! I think it's worth having a multi-file test too. You could just add an extra RUN line that uses %S/../Inputs/empty.swift, a standard empty .swift file, as well as %s. (Both tests are useful.)

modocache · 2016-08-20T03:38:31Z

@swift-ci please test

jrose-apple · 2016-08-22T15:40:46Z

Mostly looks good to me! I still feel weird about printing the whole command line, though—those can get pretty long with every input file appearing in the list.

modocache · 2016-08-22T16:08:20Z

(Rebased onto #4437.)

Ah, yeah, I guess for most actual inputs these timer names would be much, much longer. I liked the idea of seeing the exactly which jobs took up what amount of time, but that information is also available by using -driver-print-jobs.

I'll look into printing a summary of the job instead. Maybe I can reuse some of the logic from -driver-print-actions here.

modocache · 2016-08-22T16:24:01Z

The following change:

diff --git a/lib/Driver/Compilation.cpp b/lib/Driver/Compilation.cpp
index beabfd5..b86706c 100644
--- a/lib/Driver/Compilation.cpp
+++ b/lib/Driver/Compilation.cpp
@@ -436,13 +436,11 @@ int Compilation::performJobsImpl() {
     const Job *BeganCmd = (const Job *)Context;

     if (ShowDriverTimeCompilation) {
-      llvm::SmallString<128> CmdLine;
-      llvm::raw_svector_ostream OS(CmdLine);
-      BeganCmd->printCommandLine(OS);
+      auto JobName = BeganCmd->getSource().getClassName();
       DriverTimers.insert({
         BeganCmd,
         std::unique_ptr<llvm::Timer>(
-          new llvm::Timer(OS.str(), DriverTimerGroup))
+          new llvm::Timer(JobName, DriverTimerGroup))
       });
       DriverTimers[BeganCmd]->startTimer();
     }

Results in the following output:

modocache@ubuntu:~$ swiftc -driver-time-compilation test/Driver/driver-time-compilation.swift
===-------------------------------------------------------------------------===
                            Driver Time Compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0000 seconds (0.0467 wall clock)

   ---Wall Time---  --- Name ---
   0.0238 ( 50.9%)  link
   0.0196 ( 42.0%)  compile
   0.0033 (  7.1%)  swift-autolink-extract
   0.0467 (100.0%)  Total

You mention above displaying something like "Compile x.swift". I think I can do that by printing a Job's InputActions when available -- although, if there are a lot of input files, the name may get pretty long.

jrose-apple · 2016-08-22T17:27:49Z

Yeah, now that I think about it printing like -driver-print-actions is probably the way to go, even though in theory one Action can have multiple Jobs. (We don't use that today.) getSource is the way to jump from Job to Action.

modocache · 2016-08-22T19:33:36Z

OK, I have something like this at the moment:

===-------------------------------------------------------------------------===
                            Driver Time Compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0000 seconds (0.0875 wall clock)

   ---Wall Time---  --- Name ---
   0.0245 ( 28.0%)  link /home/modocache/GitHub/tmp/Crispix/A.swift /home/modocache/GitHub/tmp/Crispix/B.swift /home/modocache/GitHub/tmp/Crispix/C.swift
   0.0211 ( 24.1%)  compile /home/modocache/GitHub/tmp/Crispix/A.swift
   0.0209 ( 23.9%)  compile /home/modocache/GitHub/tmp/Crispix/B.swift
   0.0176 ( 20.1%)  compile /home/modocache/GitHub/tmp/Crispix/C.swift
   0.0035 (  4.0%)  swift-autolink-extract /home/modocache/GitHub/tmp/Crispix/A.swift /home/modocache/GitHub/tmp/Crispix/B.swift /home/modocache/GitHub/tmp/Crispix/C.swift
   0.0875 (100.0%)  Total

Does this look good? I'll update the pull request with this soon.

jrose-apple · 2016-08-22T19:57:55Z

Seems reasonable, and we can always tweak it later. Thanks, Brian!

Add an option to print the time it takes each driver task to complete. Here's an example of the output: ``` $ swiftc -driver-time-compilation \ -emit-library -module-name Crispix \ Crispix/A.swift Crispix/B.swift Crispix/C.swift ===-------------------------------------------------------------------------=== Driver Time Compilation ===-------------------------------------------------------------------------=== Total Execution Time: 0.0000 seconds (0.0875 wall clock) ---Wall Time--- --- Name --- 0.0245 ( 28.0%) link /path/to/Crispix/A.swift /path/to/Crispix/B.swift /path/to/Crispix/C.swift 0.0211 ( 24.1%) compile /path/to/Crispix/A.swift 0.0209 ( 23.9%) compile /path/to/Crispix/B.swift 0.0176 ( 20.1%) compile /path/to/Crispix/C.swift 0.0035 ( 4.0%) swift-autolink-extract /path/to/Crispix/A.swift /path/to/Crispix/B.swift /path/to/Crispix/C.swift 0.0875 (100.0%) Total ```

modocache · 2016-08-22T23:00:30Z

I'm betting some of the C++ could be nicer, but this now produces the output I described above.

@swift-ci please test

swift-ci · 2016-08-22T23:03:58Z

Build failed
Jenkins build - Swift Test Linux Platform
Git Commit - 6c92c78
Test requested by - @modocache

swift-ci · 2016-08-23T00:33:49Z

Build failed
Jenkins build - Swift Test OS X Platform
Git Commit - 6afc93481c4242639ad48d8f4daf050a46cc95e7
Test requested by - @modocache

modocache · 2016-08-23T01:11:21Z

Both failures appear to be in the CI infrastructure, not the contents of the pull request.

jrose-apple · 2016-08-23T17:41:23Z

Something weird happened there. Let's just try again.

@swift-ci Please test

modocache · 2016-08-23T19:40:43Z

Looks like it's all green this time! :)

jrose-apple · 2016-08-23T20:35:57Z

Thanks for the new feature, Brian!

modocache · 2016-08-23T20:41:08Z

You're quite welcome! I'd love to work on more of lib/Driver. Did you happen to see my email? https://lists.swift.org/pipermail/swift-dev/Week-of-Mon-20160815/002739.html

modocache assigned jrose-apple and gottesmm Aug 18, 2016

gottesmm reviewed Aug 18, 2016
View reviewed changes

modocache force-pushed the driver-time-compilation branch from fbf7638 to 4375b9b Compare August 19, 2016 12:21

modocache force-pushed the driver-time-compilation branch from 4375b9b to 642a32f Compare August 19, 2016 14:28

jrose-apple reviewed Aug 19, 2016
View reviewed changes

modocache force-pushed the driver-time-compilation branch from 642a32f to 6639184 Compare August 19, 2016 21:59

jrose-apple reviewed Aug 19, 2016
View reviewed changes

modocache force-pushed the driver-time-compilation branch from 6639184 to 6afc934 Compare August 20, 2016 03:37

modocache force-pushed the driver-time-compilation branch from 6afc934 to 1529d6e Compare August 22, 2016 16:02

modocache force-pushed the driver-time-compilation branch from 1529d6e to 6c92c78 Compare August 22, 2016 22:59

jrose-apple merged commit ba8009b into swiftlang:master Aug 23, 2016

modocache deleted the driver-time-compilation branch August 23, 2016 20:40

a-vlad mentioned this pull request Aug 30, 2016

Not reflect true compile time per file RobertGummesson/BuildTimeAnalyzer-for-Xcode#43

Open

modocache mannequin mentioned this pull request Aug 18, 2016

[SR-1788] Add driver support to print out the total time for compilation tasks #44397

Closed

[SR-1788] Add -driver-time-compilation option #4367

[SR-1788] Add -driver-time-compilation option #4367

Uh oh!

Conversation

modocache commented Aug 18, 2016

What's in this pull request?

Resolved bug number: (SR-1788)

Uh oh!

modocache commented Aug 18, 2016

Uh oh!

modocache commented Aug 18, 2016

Uh oh!

gottesmm commented Aug 18, 2016

Uh oh!

gottesmm Aug 18, 2016 • edited by modocache Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jrose-apple Aug 18, 2016

Choose a reason for hiding this comment

Uh oh!

jrose-apple commented Aug 18, 2016

Uh oh!

modocache commented Aug 19, 2016

Uh oh!

modocache commented Aug 19, 2016

Uh oh!

jrose-apple Aug 19, 2016

Choose a reason for hiding this comment

Uh oh!

gottesmm commented Aug 19, 2016

Uh oh!

gottesmm commented Aug 19, 2016

Uh oh!

modocache commented Aug 19, 2016

Uh oh!

jrose-apple commented Aug 19, 2016

Uh oh!

jrose-apple Aug 19, 2016 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

modocache Aug 20, 2016

Choose a reason for hiding this comment

Uh oh!

modocache commented Aug 20, 2016

Uh oh!

jrose-apple commented Aug 22, 2016

Uh oh!

modocache commented Aug 22, 2016

Uh oh!

modocache commented Aug 22, 2016

Uh oh!

jrose-apple commented Aug 22, 2016

Uh oh!

modocache commented Aug 22, 2016

Uh oh!

jrose-apple commented Aug 22, 2016

Uh oh!

modocache commented Aug 22, 2016

Uh oh!

swift-ci commented Aug 22, 2016

Uh oh!

swift-ci commented Aug 23, 2016

Uh oh!

modocache commented Aug 23, 2016

Uh oh!

jrose-apple commented Aug 23, 2016

Uh oh!

modocache commented Aug 23, 2016

Uh oh!

jrose-apple commented Aug 23, 2016

Uh oh!

modocache commented Aug 23, 2016

Uh oh!

Uh oh!

gottesmm Aug 18, 2016 •

edited by modocache

Loading

jrose-apple Aug 19, 2016 •

edited

Loading