Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
gottesmm opened this issue Jun 16, 2016 · 8 comments
Closed

Comments

@gottesmm
Copy link
Member

gottesmm commented Jun 16, 2016

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
Copy link
Contributor

belkadan commented Jun 20, 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.

@modocache
Copy link
Mannequin

modocache mannequin commented Aug 17, 2016

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

@modocache
Copy link
Mannequin

modocache mannequin commented Aug 17, 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.

@belkadan
Copy link
Contributor

belkadan commented Aug 18, 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.)

@modocache
Copy link
Mannequin

modocache mannequin commented Aug 18, 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

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

@modocache
Copy link
Mannequin

modocache mannequin commented Aug 18, 2016

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

@modocache
Copy link
Mannequin

modocache mannequin commented Aug 24, 2016

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

@gottesmm
Copy link
Member Author

gottesmm commented Aug 26, 2016

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

@swift-ci swift-ci transferred this issue from apple/swift-issues Apr 25, 2022
This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants