-debug-time-function-bodies: dump time spent type-checking each funct…

…ion.

This is a hidden frontend-only option intended for debugging purposes,
mainly for identifying where in a file the type checker is spending most
of its time. Use with "sort -g" to get the top problem functions.

Swift SVN r23789

include/swift/Frontend/FrontendOptions.h

@@ -134,6 +134,9 @@ class FrontendOptions {
   /// Indicates that the input(s) should be parsed as the Swift stdlib.
   bool ParseStdlib = false;
 
+  /// If set, dumps wall time taken to check each function body to llvm::errs().
+  bool DebugTimeFunctionBodies = false;
+
   /// Indicates whether function body parsing should be delayed
   /// until the end of all files.
   bool DelayedFunctionBodyParsing = false;

include/swift/Option/FrontendOptions.td

@@ -98,6 +98,9 @@ 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 debug_time_function_bodies : Flag<["-"], "debug-time-function-bodies">,
+  HelpText<"Dumps the time it takes to type-check each function body">;
+
 def debug_assert_immediately : Flag<["-"], "debug-assert-immediately">,
   DebugCrashOpt, HelpText<"Force an assertion failure immediately">;
 def debug_assert_after_parse : Flag<["-"], "debug-assert-after-parse">,

include/swift/Subsystems.h

@@ -133,7 +133,11 @@ namespace swift {
   enum class TypeCheckingFlags : unsigned {
     /// Whether to delay checking that benefits from having the entire
     /// module parsed, e.g., Objective-C method override checking.
-    DelayWholeModuleChecking = 0x01
+    DelayWholeModuleChecking = 1 << 0,
+
+    /// If set, dumps wall time taken to check each function body to
+    /// llvm::errs().
+    DebugTimeFunctionBodies = 1 << 1
   };
 
   /// Once parsing and name-binding are complete, this walks the AST to resolve

lib/Frontend/CompilerInvocation.cpp

@@ -140,14 +140,13 @@ static bool ParseFrontendArgs(FrontendOptions &Opts, ArgList &Args,
   }
 
   Opts.EmitVerboseSIL |= Args.hasArg(OPT_emit_verbose_sil);
-
   Opts.EmitSortedSIL |= Args.hasArg(OPT_emit_sorted_sil);
 
   Opts.DelayedFunctionBodyParsing |= Args.hasArg(OPT_delayed_function_body_parsing);
 
   Opts.PrintStats |= Args.hasArg(OPT_print_stats);
-
   Opts.PrintClangStats |= Args.hasArg(OPT_print_clang_stats);
+  Opts.DebugTimeFunctionBodies |= Args.hasArg(OPT_debug_time_function_bodies);
 
   Opts.PlaygroundTransform |= Args.hasArg(OPT_playground);
   if (Args.hasArg(OPT_disable_playground_transform))

lib/Frontend/Frontend.cpp

@@ -382,6 +382,9 @@ void CompilerInstance::performSema() {
   if (PrimaryBufferID == NO_SUCH_BUFFER) {
     TypeCheckOptions |= TypeCheckingFlags::DelayWholeModuleChecking;
   }
+  if (Invocation.getFrontendOptions().DebugTimeFunctionBodies) {
+    TypeCheckOptions |= TypeCheckingFlags::DebugTimeFunctionBodies;
+  }
 
   // Parse the main file last.
   if (MainBufferID != NO_SUCH_BUFFER) {

lib/Sema/TypeCheckStmt.cpp

@@ -35,6 +35,8 @@
 #include "llvm/ADT/TinyPtrVector.h"
 #include "llvm/ADT/Twine.h"
 #include "llvm/Support/Debug.h"
+#include "llvm/Support/Format.h"
+#include "llvm/Support/Timer.h"
 
 using namespace swift;
 
@@ -117,6 +119,32 @@ namespace {
       return isa<PatternBindingDecl>(D);
     }
   };
+
+  class FunctionBodyTimer {
+    PointerUnion<const AbstractFunctionDecl *,
+                 const AbstractClosureExpr *> Function;
+    llvm::TimeRecord StartTime = llvm::TimeRecord::getCurrentTime();
+
+  public:
+    FunctionBodyTimer(decltype(Function) Fn) : Function(Fn) {}
+    ~FunctionBodyTimer() {
+      llvm::TimeRecord endTime = llvm::TimeRecord::getCurrentTime(false);
+
+      auto elapsed = endTime.getProcessTime() - StartTime.getProcessTime();
+      llvm::errs() << llvm::format("%0.1f", elapsed * 1000) << "ms\t";
+
+      if (auto *AFD = Function.dyn_cast<const AbstractFunctionDecl *>()) {
+        AFD->getLoc().print(llvm::errs(), AFD->getASTContext().SourceMgr);
+        llvm::errs() << "\t";
+        AFD->print(llvm::errs(), PrintOptions());
+      } else {
+        auto *ACE = Function.get<const AbstractClosureExpr *>();
+        ACE->getLoc().print(llvm::errs(), ACE->getASTContext().SourceMgr);
+        llvm::errs() << "\t(closure)";
+      }
+      llvm::errs() << "\n";
+    }
+  };
 }
 
 static void setAutoClosureDiscriminators(DeclContext *DC, Stmt *S) {
@@ -836,6 +864,11 @@ bool TypeChecker::typeCheckAbstractFunctionBodyUntil(AbstractFunctionDecl *AFD,
 bool TypeChecker::typeCheckAbstractFunctionBody(AbstractFunctionDecl *AFD) {
   if (!AFD->getBody())
     return false;
+
+  Optional<FunctionBodyTimer> timer;
+  if (DebugTimeFunctionBodies)
+    timer.emplace(AFD);
+
   return typeCheckAbstractFunctionBodyUntil(AFD, SourceLoc());
 }
 
@@ -1048,6 +1081,11 @@ bool TypeChecker::typeCheckDestructorBodyUntil(DestructorDecl *DD,
 
 void TypeChecker::typeCheckClosureBody(ClosureExpr *closure) {
   BraceStmt *body = closure->getBody();
+
+  Optional<FunctionBodyTimer> timer;
+  if (DebugTimeFunctionBodies)
+    timer.emplace(closure);
+
   StmtChecker(*this, closure).typeCheckBody(body);
   if (body) {
     closure->setBody(body, closure->hasSingleExpressionBody());

lib/Sema/TypeChecker.cpp

@@ -460,6 +460,8 @@ void swift::performTypeChecking(SourceFile &SF, TopLevelContext &TLC,
   auto &Ctx = SF.getASTContext();
   TypeChecker TC(Ctx);
   auto &DefinedFunctions = TC.definedFunctions;
+  if (Options.contains(TypeCheckingFlags::DebugTimeFunctionBodies))
+    TC.enableDebugTimeFunctionBodies();
 
   // Lookup the swift module.  This ensures that we record all known protocols
   // in the AST.

lib/Sema/TypeChecker.h

@@ -337,6 +337,10 @@ class TypeChecker final : public LazyResolver {
   /// The index of the next response metavariable to bind to a REPL result.
   unsigned NextResponseVariableIndex = 0;
 
+  /// If true, the time it takes to type-check each function will be dumped
+  /// to llvm::errs().
+  bool DebugTimeFunctionBodies = false;
+
   /// A helper to construct and typecheck call to super.init().
   ///
   /// \returns NULL if the constructed expression does not typecheck.
@@ -348,6 +352,11 @@ class TypeChecker final : public LazyResolver {
   ~TypeChecker();
 
   LangOptions &getLangOpts() const { return Context.LangOpts; }
+
+  /// Dump the time it takes to type-check each function to llvm::errs().
+  void enableDebugTimeFunctionBodies() {
+    DebugTimeFunctionBodies = true;
+  }
 
   template<typename ...ArgTypes>
   InFlightDiagnostic diagnose(ArgTypes &&...Args) {