[SR-1788] Add driver support to print out the total time for compilation tasks Created: 15 Jun 2016  Updated: 26 Aug 2016  Resolved: 23 Aug 2016

Status: Resolved
Project: Swift
Component/s: Compiler

Type: Bug Priority: Medium
Reporter: Michael Gottesman Assignee: Michael Gottesman
Resolution: Done Votes: 0
Labels: Driver, StarterBug


 Description   

We have currently debug-time-function-bodies, but that only times the type checker.

We should also have an option to just time the entire compilation.

This would be an easy starter bug.



 Comments   
Comment by Jordan Rose [ 20 Jun 2016 ]

We do have -debug-time-compilation, but that's on a per-file basis. What this bug refers to is something like -driver-time-compilation, which would print out compilation times for every file, and then a total at the end.

Comment by Brian Ivan Gesiak [ 16 Aug 2016 ]

I'm trying to learn more about lib/Driver. I'd like to try my hand at this task.

Comment by Brian Ivan Gesiak [ 17 Aug 2016 ]

I've learned a lot about lib/Driver thanks to looking into this – thanks for the StarterBug! Below are just my notes having worked on it for an hour or so.

I can confirm that -debug-time-function-bodies and -debug-time-compilation work as explained above. -debug-time-function-bodies uses a swift::FunctionBodyTimer to dump the time it takes the swift::TypeChecker to typecheck each function:

modocache@ubuntu:~/GitHub/apple/swift$ ../build/Ninja-ReleaseAssert/swift-linux-x86_64/bin/swiftc -emit-library -module-name Crispix -Xfrontend -debug-time-function-bodies ~/GitHub/tmp/Crispix/A.swift ~/GitHub/tmp/Crispix/B.swift ~/GitHub/tmp/Crispix/C.swift
4.0ms	/home/modocache/GitHub/tmp/Crispix/A.swift:2:7	final get {}
0.0ms	/home/modocache/GitHub/tmp/Crispix/A.swift:1:7	@objc deinit
0.0ms	/home/modocache/GitHub/tmp/Crispix/A.swift:1:7	init()
0.0ms	/home/modocache/GitHub/tmp/Crispix/B.swift:1:8	init()
0.0ms	/home/modocache/GitHub/tmp/Crispix/A.swift:2:7	final get {}

And -debug-time-compilation uses swift::SharedTimer, a wrapper for llvm::NamedRegionTimer, to dump compilation times on a per-file basis:

modocache@ubuntu:~/GitHub/apple/swift$ ../build/Ninja-ReleaseAssert/swift-linux-x86_64/bin/swiftc -emit-library -module-name Crispix -Xfrontend -debug-time-compilation ~/GitHub/tmp/Crispix/A.swift ~/GitHub/tmp/Crispix/B.swift ~/GitHub/tmp/Crispix/C.swift
===-------------------------------------------------------------------------===
                               Swift compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0080 seconds (0.0062 wall clock)

   ---User Time---   --User+System--   ---Wall Time---  --- Name ---
   0.0040 ( 50.0%)   0.0040 ( 50.0%)   0.0030 ( 49.0%)  LLVM output
   0.0040 ( 50.0%)   0.0040 ( 50.0%)   0.0010 ( 17.0%)  SILGen
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0008 ( 13.4%)  Type checking / Semantic analysis
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0006 (  9.1%)  IRGen
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0003 (  5.5%)  LLVM optimization
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0002 (  2.7%)  AST verification
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0001 (  1.2%)  SIL verification (pre-optimization)
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0001 (  1.1%)  Parsing
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.6%)  SIL verification (post-optimization)
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.5%)  SIL optimization
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.0%)  Name binding
   0.0080 (100.0%)   0.0080 (100.0%)   0.0062 (100.0%)  Total

===-------------------------------------------------------------------------===
                               Swift compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0000 seconds (0.0031 wall clock)

   ---Wall Time---  --- Name ---
   0.0021 ( 67.6%)  LLVM output
   0.0003 (  9.1%)  IRGen
   0.0003 (  8.4%)  LLVM optimization
   0.0001 (  4.2%)  SILGen
   0.0001 (  3.6%)  Type checking / Semantic analysis
   0.0001 (  3.0%)  AST verification
   0.0001 (  2.6%)  Parsing
   0.0000 (  0.7%)  SIL optimization
   0.0000 (  0.7%)  SIL verification (pre-optimization)
   0.0000 (  0.1%)  SIL verification (post-optimization)
   0.0000 (  0.0%)  Name binding
   0.0031 (100.0%)  Total

===-------------------------------------------------------------------------===
                               Swift compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0040 seconds (0.0008 wall clock)

   --System Time--   --User+System--   ---Wall Time---  --- Name ---
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0003 ( 36.0%)  Type checking / Semantic analysis
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0002 ( 20.4%)  LLVM output
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0001 ( 12.9%)  IRGen
   0.0040 (100.0%)   0.0040 (100.0%)   0.0001 ( 12.5%)  LLVM optimization
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0001 (  7.7%)  AST verification
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0001 (  7.2%)  Parsing
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  1.7%)  SILGen
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  1.5%)  SIL optimization
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.3%)  SIL verification (pre-optimization)
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.0%)  SIL verification (post-optimization)
   0.0000 (  0.0%)   0.0000 (  0.0%)   0.0000 (  0.0%)  Name binding
   0.0040 (100.0%)   0.0040 (100.0%)   0.0008 (100.0%)  Total

As I understand, the objective here is to add a new option, named -driver-time-compilation. Just adding the option is pretty easy:

diff --git a/include/swift/Frontend/FrontendOptions.h b/include/swift/Frontend/FrontendOptions.h
index 04a6660..d6ff48e 100644
--- a/include/swift/Frontend/FrontendOptions.h
+++ b/include/swift/Frontend/FrontendOptions.h
@@ -181,6 +181,12 @@ public:
   /// \sa swift::SharedTimer
   bool DebugTimeCompilation = false;
 
+  /// If set, prints the time taken in all compilation phases to llvm:errs(),
+  /// followed by the total time at the end.
+  ///
+  /// \sa swift::SharedTimer
+  bool DriverTimeCompilaton = false;
+
   /// Indicates whether function body parsing should be delayed
   /// until the end of all files.
   bool DelayedFunctionBodyParsing = false;
diff --git a/include/swift/Option/FrontendOptions.td b/include/swift/Option/FrontendOptions.td
index 878e6a8..4ecfe47 100644
--- a/include/swift/Option/FrontendOptions.td
+++ b/include/swift/Option/FrontendOptions.td
@@ -139,6 +139,8 @@ def debug_forbid_typecheck_prefix : Separate<["-"], "debug-forbid-typecheck-pref
   HelpText<"Triggers llvm fatal_error if typechecker tries to typecheck a decl "
            "with the provided prefix name">;
 
+def driver_time_compilation : Flag<["-"], "driver-time-compilation">,
+  HelpText<"Prints the total time taken by all compilation phases">;
 def debug_time_compilation : Flag<["-"], "debug-time-compilation">,
   HelpText<"Prints the time taken by each compilation phase">;
 def debug_time_function_bodies : Flag<["-"], "debug-time-function-bodies">,
diff --git a/lib/Frontend/CompilerInvocation.cpp b/lib/Frontend/CompilerInvocation.cpp
index f8883f2..08e2317 100644
--- a/lib/Frontend/CompilerInvocation.cpp
+++ b/lib/Frontend/CompilerInvocation.cpp
@@ -174,6 +174,7 @@ static bool ParseFrontendArgs(FrontendOptions &Opts, ArgList &Args,
   Opts.PrintClangStats |= Args.hasArg(OPT_print_clang_stats);
   Opts.DebugTimeFunctionBodies |= Args.hasArg(OPT_debug_time_function_bodies);
   Opts.DebugTimeCompilation |= Args.hasArg(OPT_debug_time_compilation);
+  Opts.DriverTimeCompilaton |= Args.hasArg(OPT_driver_time_compilation);
 
   if (const Arg *A = Args.getLastArg(OPT_warn_long_function_bodies)) {
     unsigned attempt;

I'm still looking into how to implement this, though. The next few questions I'll try to answer are:

1. Can I reuse swift::SharedTimer to implement the desired behavior? Or is that somehow coupled to measuring one file at a time?
2. What's the ideal output? Is it the output from -debug-time-compilation, followed by total times? I assume not, since it's pretty redundant that big "Swift compilation" header printed out for each file.

I'll keep working on this over the next few days. Feedback welcome.

Comment by Jordan Rose [ 17 Aug 2016 ]

I think the plain-and-simple thing would not touch the frontend at all—it would just have the driver time each task's total execution time, possibly collating them at the end. I feel like aggregating a breakdown of time spent in each phase of compilation across multiple files is less interesting; we can just dump all that to stderr with -Xfrontend -debug-time-compilation and parse it out later. I think the most interesting thing for users in general is to find out which files are taking a long time, and it's less interesting to find out which compilation phase is at fault. (Though perhaps not which function.)

Comment by Brian Ivan Gesiak [ 17 Aug 2016 ]

OK, so I hacked some code together that outputs the following:

modocache@ubuntu:~/GitHub/apple/swift$ /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/bin/swiftc -Xfrontend -driver-time-compilation -emit-library -module-name Crispix ~/GitHub/tmp/Crispix/A.swift ~/GitHub/tmp/Crispix/B.swift ~/GitHub/tmp/Crispix/C.swift
===-------------------------------------------------------------------------===
                            Driver Time Compilation
===-------------------------------------------------------------------------===
  Total Execution Time: 0.0000 seconds (0.0892 wall clock)

   ---Wall Time---  --- Name ---
   0.0242 ( 27.1%)  /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/bin/swift -frontend -c -primary-file /home/modocache/GitHub/tmp/Crispix/A.swift /home/modocache/GitHub/tmp/Crispix/B.swift /home/modocache/GitHub/tmp/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 /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/lib/swift/linux /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/lib/swift/linux/x86_64/swift_begin.o /tmp/A-216874.o /tmp/B-243ab4.o /tmp/C-5af361.o -L /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/lib/swift/linux --target=x86_64-unknown-linux-gnu -lswiftCore @/tmp/A-864579.autolink /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/lib/swift/linux/x86_64/swift_end.o -o libCrispix.so

   0.0205 ( 23.0%)  /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/bin/swift -frontend -c /home/modocache/GitHub/tmp/Crispix/A.swift -primary-file /home/modocache/GitHub/tmp/Crispix/B.swift /home/modocache/GitHub/tmp/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%)  /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/bin/swift -frontend -c /home/modocache/GitHub/tmp/Crispix/A.swift /home/modocache/GitHub/tmp/Crispix/B.swift -primary-file /home/modocache/GitHub/tmp/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%)  /home/modocache/GitHub/apple/build/Ninja-ReleaseAssert/swift-linux-x86_64/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

Jordan Rose, is this the sort of output you had in mind?

Comment by Brian Ivan Gesiak [ 18 Aug 2016 ]

I submitted https://github.com/apple/swift/pull/4367 as a first attempt. Let me know how it looks!

Comment by Brian Ivan Gesiak [ 23 Aug 2016 ]

I think this task is resolved, now that https://github.com/apple/swift/pull/4367 is merged. Please confirm and close, Michael Gottesman.

Comment by Michael Gottesman [ 26 Aug 2016 ]

I am still on the east coast. I am going to assign this to me and look at this when I get back.

Generated at Wed Jun 20 14:12:37 CDT 2018 using JIRA 7.3.4#73015-sha1:a262b3457b3605f12635df4b0a0c3dc71d631a1e.