Skip to content

Commit

Permalink
Browse files Browse the repository at this point in the history
Add frontend option "-warn-long-function-bodies=<N>".
This is a /slightly/ more user-friendly option than
-debug-time-function-bodies; pass it a limit in milliseconds and
the compiler will warn whenever a function or multi-statement closure
takes longer than that to type-check.

Since it's a frontend option (and thus usually passed with -Xfrontend),
I went with the "joined" syntax as the common case. The usual "separate"
syntax of "-warn-long-function-bodies <N>" is also available.

As a frontend option, this is UNSUPPORTED and may be removed without
notice at any future date.

Additional caveats:
- Other parts of type-checking not measured by this may also be slow.
- May include first-use penalties (i.e. "this is slow because it's
  the first function that references an imported type, which causes
  many things to be imported")
- Does not report anything whatsoever about other phases of compilation
  (SILGen, optimization, IRGen, assembly emission, whatever).
- Does not catch anything accidentally being type-checked multiple times
  (a known issue for initial value expressions on properties).
  • Loading branch information
jrose-apple committed May 11, 2016
1 parent ecd8821 commit 18c7592
Show file tree
Hide file tree
Showing 9 changed files with 107 additions and 25 deletions.
11 changes: 11 additions & 0 deletions include/swift/AST/DiagnosticsSema.def
Expand Up @@ -2911,6 +2911,17 @@ ERROR(circular_reference, none,
NOTE(circular_reference_through, none,
"through reference here", ())

//------------------------------------------------------------------------------
// Debug diagnostics
//------------------------------------------------------------------------------

WARNING(debug_long_function_body, none,
"%0 %1 took %2ms to type-check (limit: %3ms)",
(DescriptiveDeclKind, DeclName, unsigned, unsigned))
WARNING(debug_long_closure_body, none,
"closure took %0ms to type-check (limit: %1ms)",
(unsigned, unsigned))

#ifndef DIAG_NO_UNDEF
# if defined(DIAG)
# undef DIAG
Expand Down
6 changes: 6 additions & 0 deletions include/swift/Frontend/FrontendOptions.h
Expand Up @@ -128,6 +128,12 @@ class FrontendOptions {
/// The path to collect the group information for the compiled source files.
std::string GroupInfoPath;

/// If non-zero, warn when a function body takes longer than this many
/// milliseconds to type-check.
///
/// Intended for debugging purposes only.
unsigned WarnLongFunctionBodies = 0;

enum ActionType {
NoneAction, ///< No specific action
Parse, ///< Parse and type-check only
Expand Down
6 changes: 6 additions & 0 deletions include/swift/Option/FrontendOptions.td
Expand Up @@ -247,6 +247,12 @@ def swift3_migration :
Flag<["-"], "swift3-migration">,
HelpText<"Enable Fix-It based migration aids for Swift 3">;

def warn_long_function_bodies : Separate<["-"], "warn-long-function-bodies">,
MetaVarName<"<n>">,
HelpText<"Warns when type-checking a function takes longer than <n> ms">;
def warn_long_function_bodies_EQ : Joined<["-"], "warn-long-function-bodies=">,
Alias<warn_long_function_bodies>;

def warn_omit_needless_words :
Flag<["-"], "Womit-needless-words">,
HelpText<"Warn about needless words in names">;
Expand Down
8 changes: 6 additions & 2 deletions include/swift/Subsystems.h
Expand Up @@ -160,10 +160,14 @@ namespace swift {
/// types and diagnose problems therein.
///
/// \param StartElem Where to start for incremental type-checking in the main
/// source file.
/// source file.
///
/// \param WarnLongFunctionBodies If non-zero, warn when a function body takes
/// longer than this many milliseconds to type-check
void performTypeChecking(SourceFile &SF, TopLevelContext &TLC,
OptionSet<TypeCheckingFlags> Options,
unsigned StartElem = 0);
unsigned StartElem = 0,
unsigned WarnLongFunctionBodies = 0);

/// Once type checking is complete, this walks protocol requirements
/// to resolve default witnesses.
Expand Down
10 changes: 10 additions & 0 deletions lib/Frontend/CompilerInvocation.cpp
Expand Up @@ -175,6 +175,16 @@ static bool ParseFrontendArgs(FrontendOptions &Opts, ArgList &Args,
Opts.DebugTimeFunctionBodies |= Args.hasArg(OPT_debug_time_function_bodies);
Opts.DebugTimeCompilation |= Args.hasArg(OPT_debug_time_compilation);

if (const Arg *A = Args.getLastArg(OPT_warn_long_function_bodies)) {
unsigned attempt;
if (StringRef(A->getValue()).getAsInteger(10, attempt)) {
Diags.diagnose(SourceLoc(), diag::error_invalid_arg_value,
A->getAsString(Args), A->getValue());
} else {
Opts.WarnLongFunctionBodies = attempt;
}
}

Opts.PlaygroundTransform |= Args.hasArg(OPT_playground);
if (Args.hasArg(OPT_disable_playground_transform))
Opts.PlaygroundTransform = false;
Expand Down
10 changes: 6 additions & 4 deletions lib/Frontend/Frontend.cpp
Expand Up @@ -465,10 +465,10 @@ void CompilerInstance::performSema() {
if (PrimaryBufferID == NO_SUCH_BUFFER) {
TypeCheckOptions |= TypeCheckingFlags::DelayWholeModuleChecking;
}
if (Invocation.getFrontendOptions().DebugTimeFunctionBodies) {
if (options.DebugTimeFunctionBodies) {
TypeCheckOptions |= TypeCheckingFlags::DebugTimeFunctionBodies;
}
if (Invocation.getFrontendOptions().actionIsImmediate()) {
if (options.actionIsImmediate()) {
TypeCheckOptions |= TypeCheckingFlags::ForImmediateMode;
}

Expand Down Expand Up @@ -497,7 +497,8 @@ void CompilerInstance::performSema() {
&PersistentState, DelayedCB.get());
if (mainIsPrimary) {
performTypeChecking(MainFile, PersistentState.getTopLevelContext(),
TypeCheckOptions, CurTUElem);
TypeCheckOptions, CurTUElem,
options.WarnLongFunctionBodies);
}
CurTUElem = MainFile.Decls.size();
} while (!Done);
Expand All @@ -516,7 +517,8 @@ void CompilerInstance::performSema() {
if (auto SF = dyn_cast<SourceFile>(File))
if (PrimaryBufferID == NO_SUCH_BUFFER || SF == PrimarySourceFile)
performTypeChecking(*SF, PersistentState.getTopLevelContext(),
TypeCheckOptions);
TypeCheckOptions, /*curElem*/0,
options.WarnLongFunctionBodies);

// Even if there were no source files, we should still record known
// protocols.
Expand Down
63 changes: 45 additions & 18 deletions lib/Sema/TypeCheckStmt.cpp
Expand Up @@ -134,29 +134,56 @@ namespace {
}
};

/// Used for debugging which parts of the code are taking a long time to
/// compile.
class FunctionBodyTimer {
PointerUnion<const AbstractFunctionDecl *,
const AbstractClosureExpr *> Function;
AnyFunctionRef Function;
llvm::TimeRecord StartTime = llvm::TimeRecord::getCurrentTime();
unsigned WarnLimit;
bool ShouldDump;

public:
FunctionBodyTimer(decltype(Function) Fn) : Function(Fn) {}
FunctionBodyTimer(AnyFunctionRef Fn, bool shouldDump,
unsigned warnLimit)
: Function(Fn), WarnLimit(warnLimit), ShouldDump(shouldDump) {}

~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)";
unsigned elapsedMS = static_cast<unsigned>(elapsed * 1000);

ASTContext &ctx = Function.getAsDeclContext()->getASTContext();

if (ShouldDump) {
llvm::errs() << llvm::format("%0.1f", elapsed * 1000) << "ms\t";
Function.getLoc().print(llvm::errs(), ctx.SourceMgr);

if (auto *AFD = Function.getAbstractFunctionDecl()) {
llvm::errs() << "\t";
AFD->print(llvm::errs(), PrintOptions());
} else {
llvm::errs() << "\t(closure)";
}
llvm::errs() << "\n";
}

if (WarnLimit != 0 && elapsedMS >= WarnLimit) {
if (auto *AFD = Function.getAbstractFunctionDecl()) {
DeclName name = AFD->getFullName();
if (!name) {
if (auto *method = dyn_cast<FuncDecl>(AFD)) {
name = method->getAccessorStorageDecl()->getFullName();
}
}
ctx.Diags.diagnose(AFD, diag::debug_long_function_body,
AFD->getDescriptiveKind(), name,
elapsedMS, WarnLimit);
} else {
ctx.Diags.diagnose(Function.getLoc(), diag::debug_long_closure_body,
elapsedMS, WarnLimit);
}
}
llvm::errs() << "\n";
}
};
}
Expand Down Expand Up @@ -1191,8 +1218,8 @@ bool TypeChecker::typeCheckAbstractFunctionBody(AbstractFunctionDecl *AFD) {
return false;

Optional<FunctionBodyTimer> timer;
if (DebugTimeFunctionBodies)
timer.emplace(AFD);
if (DebugTimeFunctionBodies || WarnLongFunctionBodies)
timer.emplace(AFD, DebugTimeFunctionBodies, WarnLongFunctionBodies);

if (typeCheckAbstractFunctionBodyUntil(AFD, SourceLoc()))
return true;
Expand Down Expand Up @@ -1433,8 +1460,8 @@ void TypeChecker::typeCheckClosureBody(ClosureExpr *closure) {
BraceStmt *body = closure->getBody();

Optional<FunctionBodyTimer> timer;
if (DebugTimeFunctionBodies)
timer.emplace(closure);
if (DebugTimeFunctionBodies || WarnLongFunctionBodies)
timer.emplace(closure, DebugTimeFunctionBodies, WarnLongFunctionBodies);

StmtChecker(*this, closure).typeCheckBody(body);
if (body) {
Expand Down
4 changes: 3 additions & 1 deletion lib/Sema/TypeChecker.cpp
Expand Up @@ -498,7 +498,8 @@ void swift::typeCheckExternalDefinitions(SourceFile &SF) {

void swift::performTypeChecking(SourceFile &SF, TopLevelContext &TLC,
OptionSet<TypeCheckingFlags> Options,
unsigned StartElem) {
unsigned StartElem,
unsigned WarnLongFunctionBodies) {
if (SF.ASTStage == SourceFile::TypeChecked)
return;

Expand All @@ -516,6 +517,7 @@ void swift::performTypeChecking(SourceFile &SF, TopLevelContext &TLC,
TypeChecker TC(Ctx);
SharedTimer timer("Type checking / Semantic analysis");

TC.setWarnLongFunctionBodies(WarnLongFunctionBodies);
if (Options.contains(TypeCheckingFlags::DebugTimeFunctionBodies))
TC.enableDebugTimeFunctionBodies();

Expand Down
14 changes: 14 additions & 0 deletions lib/Sema/TypeChecker.h
Expand Up @@ -545,6 +545,12 @@ class TypeChecker final : public LazyResolver {
/// The index of the next response metavariable to bind to a REPL result.
unsigned NextResponseVariableIndex = 0;

/// If non-zero, warn when a function body takes longer than this many
/// milliseconds to type-check.
///
/// Intended for debugging purposes only.
unsigned WarnLongFunctionBodies = 0;

/// If true, the time it takes to type-check each function will be dumped
/// to llvm::errs().
bool DebugTimeFunctionBodies = false;
Expand All @@ -571,6 +577,14 @@ class TypeChecker final : public LazyResolver {
DebugTimeFunctionBodies = true;
}

/// If \p timeInMS is non-zero, warn when a function body takes longer than
/// this many milliseconds to type-check.
///
/// Intended for debugging purposes only.
void setWarnLongFunctionBodies(unsigned timeInMS) {
WarnLongFunctionBodies = timeInMS;
}

bool getInImmediateMode() {
return InImmediateMode;
}
Expand Down

0 comments on commit 18c7592

Please sign in to comment.