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

[gottesmm]

Previous ID	SR-1788
Radar	None
Original Reporter	@gottesmm
Type	Bug
Status	Resolved
Resolution	Done

Additional Detail from JIRA

Votes	0
Component/s	Compiler
Labels	Bug, Driver, StarterBug
Assignee	@gottesmm
Priority	Medium

md5: a76b7f7e31ee3a0f55d7942278040933

Issue 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.

[belkadan]

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.

[modocache]

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

[modocache]

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.

[belkadan]

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.)

[modocache]

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

@belkadan, is this the sort of output you had in mind?

[modocache]

I submitted #4367 as a first attempt. Let me know how it looks!

[modocache]

I think this task is resolved, now that #4367 is merged. Please confirm and close, @gottesmm.

[gottesmm]

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