Skip to content

Commit af99ac5

Browse files
slavapestovslavapestov
committed
RequirementMachine: Add -debug-requirement-machine=timers
1 parent 7c226dd commit af99ac5

File tree

4 files changed

+132
-6
lines changed

4 files changed

+132
-6
lines changed

‎lib/AST/RequirementMachine/Debug.h

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -69,6 +69,9 @@ enum class DebugFlags : unsigned {
6969
/// Print debug output from propagating explicit requirement
7070
/// IDs from redundant rules.
7171
PropagateRequirementIDs = (1<<15),
72+
73+
/// Print a trace of requirement machines constructed and how long each took.
74+
Timers = (1<<16),
7275
};
7376

7477
using DebugOptions = OptionSet<DebugFlags>;

‎lib/AST/RequirementMachine/RequirementMachineRequests.cpp

Lines changed: 56 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -237,6 +237,24 @@ RequirementSignatureRequestRQM::evaluate(Evaluator &evaluator,
237237
requirements.push_back({req, SourceLoc(), /*inferred=*/false});
238238
}
239239

240+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
241+
rewriteCtx.beginTimer("RequirementSignatureRequest");
242+
llvm::dbgs() << "[";
243+
for (auto *proto : component)
244+
llvm::dbgs() << " " << proto->getName();
245+
llvm::dbgs() << " ]\n";
246+
}
247+
248+
SWIFT_DEFER {
249+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
250+
rewriteCtx.endTimer("RequirementSignatureRequest");
251+
llvm::dbgs() << "[";
252+
for (auto *proto : component)
253+
llvm::dbgs() << " " << proto->getName();
254+
llvm::dbgs() << " ]\n";
255+
}
256+
};
257+
240258
unsigned attempt = 0;
241259
for (;;) {
242260
// Heap-allocate the requirement machine to save stack space.
@@ -501,12 +519,19 @@ AbstractGenericSignatureRequestRQM::evaluate(
501519
requirements.push_back({req, SourceLoc(), /*wasInferred=*/false});
502520
}
503521

522+
auto &rewriteCtx = ctx.getRewriteContext();
523+
524+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
525+
rewriteCtx.beginTimer("AbstractGenericSignatureRequest");
526+
llvm::dbgs() << "\n";
527+
}
528+
504529
// Preprocess requirements to eliminate conformances on generic parameters
505530
// which are made concrete.
506531
if (ctx.LangOpts.EnableRequirementMachineConcreteContraction) {
507532
SmallVector<StructuralRequirement, 4> contractedRequirements;
508533
if (performConcreteContraction(requirements, contractedRequirements,
509-
ctx.getRewriteContext().getDebugOptions()
534+
rewriteCtx.getDebugOptions()
510535
.contains(DebugFlags::ConcreteContraction))) {
511536
std::swap(contractedRequirements, requirements);
512537
}
@@ -516,7 +541,7 @@ AbstractGenericSignatureRequestRQM::evaluate(
516541
for (;;) {
517542
// Heap-allocate the requirement machine to save stack space.
518543
std::unique_ptr<RequirementMachine> machine(new RequirementMachine(
519-
ctx.getRewriteContext()));
544+
rewriteCtx));
520545

521546
auto status =
522547
machine->initWithWrittenRequirements(genericParams, requirements);
@@ -547,6 +572,11 @@ AbstractGenericSignatureRequestRQM::evaluate(
547572
result.verify();
548573
}
549574

575+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
576+
rewriteCtx.endTimer("AbstractGenericSignatureRequest");
577+
llvm::dbgs() << result << "\n";
578+
}
579+
550580
return GenericSignatureWithError(result, errorFlags);
551581
}
552582
}
@@ -648,12 +678,23 @@ InferredGenericSignatureRequestRQM::evaluate(
648678
for (const auto &req : addedRequirements)
649679
requirements.push_back({req, SourceLoc(), /*wasInferred=*/true});
650680

681+
auto &rewriteCtx = ctx.getRewriteContext();
682+
683+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
684+
rewriteCtx.beginTimer("InferredGenericSignatureRequest");
685+
686+
llvm::dbgs() << "@ ";
687+
auto &sourceMgr = ctx.SourceMgr;
688+
loc.print(llvm::dbgs(), sourceMgr);
689+
llvm::dbgs() << "\n";
690+
}
691+
651692
// Preprocess requirements to eliminate conformances on generic parameters
652693
// which are made concrete.
653694
if (ctx.LangOpts.EnableRequirementMachineConcreteContraction) {
654695
SmallVector<StructuralRequirement, 4> contractedRequirements;
655696
if (performConcreteContraction(requirements, contractedRequirements,
656-
ctx.getRewriteContext().getDebugOptions()
697+
rewriteCtx.getDebugOptions()
657698
.contains(DebugFlags::ConcreteContraction))) {
658699
std::swap(contractedRequirements, requirements);
659700
}
@@ -663,7 +704,7 @@ InferredGenericSignatureRequestRQM::evaluate(
663704
for (;;) {
664705
// Heap-allocate the requirement machine to save stack space.
665706
std::unique_ptr<RequirementMachine> machine(new RequirementMachine(
666-
ctx.getRewriteContext()));
707+
rewriteCtx));
667708

668709
auto status =
669710
machine->initWithWrittenRequirements(genericParams, requirements);
@@ -680,6 +721,12 @@ InferredGenericSignatureRequestRQM::evaluate(
680721

681722
auto result = GenericSignature::get(genericParams,
682723
parentSig.getRequirements());
724+
725+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
726+
rewriteCtx.endTimer("InferredGenericSignatureRequest");
727+
llvm::dbgs() << result << "\n";
728+
}
729+
683730
return GenericSignatureWithError(
684731
result, GenericSignatureErrorFlags::CompletionFailed);
685732
}
@@ -717,6 +764,11 @@ InferredGenericSignatureRequestRQM::evaluate(
717764
result.verify();
718765
}
719766

767+
if (rewriteCtx.getDebugOptions().contains(DebugFlags::Timers)) {
768+
rewriteCtx.endTimer("InferredGenericSignatureRequest");
769+
llvm::dbgs() << result << "\n";
770+
}
771+
720772
return GenericSignatureWithError(result, errorFlags);
721773
}
722774
}

‎lib/AST/RequirementMachine/RewriteContext.cpp

Lines changed: 65 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,7 @@ static DebugOptions parseDebugFlags(StringRef debugFlags) {
4343
.Case("redundant-rules-detail", DebugFlags::RedundantRulesDetail)
4444
.Case("concrete-contraction", DebugFlags::ConcreteContraction)
4545
.Case("propagate-requirement-ids", DebugFlags::PropagateRequirementIDs)
46+
.Case("timers", DebugFlags::Timers)
4647
.Default(None);
4748
if (!flag) {
4849
llvm::errs() << "Unknown debug flag in -debug-requirement-machine "
@@ -72,6 +73,41 @@ RewriteContext::RewriteContext(ASTContext &ctx)
7273
Debug = parseDebugFlags(debugFlags);
7374
}
7475

76+
void RewriteContext::beginTimer(StringRef name) {
77+
auto now = std::chrono::system_clock::now();
78+
auto dur = now.time_since_epoch();
79+
80+
for (unsigned i = 0; i < Timers.size(); ++i)
81+
llvm::dbgs() << "| ";
82+
llvm::dbgs() << "+ started " << name << " ";
83+
84+
Timers.push_back(std::chrono::duration_cast<std::chrono::microseconds>(dur).count());
85+
}
86+
87+
void RewriteContext::endTimer(StringRef name) {
88+
auto now = std::chrono::system_clock::now();
89+
auto dur = now.time_since_epoch();
90+
auto time = (std::chrono::duration_cast<std::chrono::microseconds>(dur).count()
91+
- Timers.back());
92+
Timers.pop_back();
93+
94+
// If we're nested inside of another timer, don't charge our time to the parent.
95+
if (!Timers.empty()) {
96+
Timers.back() += time;
97+
}
98+
99+
for (unsigned i = 0; i < Timers.size(); ++i)
100+
llvm::dbgs() << "| ";
101+
102+
llvm::dbgs() << "+ ";
103+
104+
if (time > 100000)
105+
llvm::dbgs() << "**** SLOW **** ";
106+
107+
llvm::dbgs() << "finished " << name << " in " << time << "us: ";
108+
109+
}
110+
75111
const llvm::TinyPtrVector<const ProtocolDecl *> &
76112
RewriteContext::getInheritedProtocols(const ProtocolDecl *proto) {
77113
auto found = AllInherited.find(proto);
@@ -127,6 +163,11 @@ RequirementMachine *RewriteContext::getRequirementMachine(
127163
return machine;
128164
}
129165

166+
if (Debug.contains(DebugFlags::Timers)) {
167+
beginTimer("getRequirementMachine()");
168+
llvm::dbgs() << sig << "\n";
169+
}
170+
130171
// Store this requirement machine before adding the signature,
131172
// to catch re-entrant construction via initWithGenericSignature()
132173
// below.
@@ -137,6 +178,11 @@ RequirementMachine *RewriteContext::getRequirementMachine(
137178
auto status = newMachine->initWithGenericSignature(sig);
138179
newMachine->checkCompletionResult(status.first);
139180

181+
if (Debug.contains(DebugFlags::Timers)) {
182+
endTimer("getRequirementMachine()");
183+
llvm::dbgs() << sig << "\n";
184+
}
185+
140186
return newMachine;
141187
}
142188

@@ -338,17 +384,34 @@ RequirementMachine *RewriteContext::getRequirementMachine(
338384
return component.Machine;
339385
}
340386

387+
auto protos = component.Protos;
388+
389+
if (Debug.contains(DebugFlags::Timers)) {
390+
beginTimer("getRequirementMachine()");
391+
llvm::dbgs() << "[";
392+
for (auto *proto : protos)
393+
llvm::dbgs() << " " << proto->getName();
394+
llvm::dbgs() << " ]\n";
395+
}
396+
341397
// Store this requirement machine before adding the protocols, to catch
342398
// re-entrant construction via initWithProtocolSignatureRequirements()
343399
// below.
344400
auto *newMachine = new rewriting::RequirementMachine(*this);
345401
component.Machine = newMachine;
346402

347403
// This might re-entrantly invalidate 'component.Machine'.
348-
auto status = newMachine->initWithProtocolSignatureRequirements(
349-
component.Protos);
404+
auto status = newMachine->initWithProtocolSignatureRequirements(protos);
350405
newMachine->checkCompletionResult(status.first);
351406

407+
if (Debug.contains(DebugFlags::Timers)) {
408+
endTimer("getRequirementMachine()");
409+
llvm::dbgs() << "[";
410+
for (auto *proto : protos)
411+
llvm::dbgs() << " " << proto->getName();
412+
llvm::dbgs() << " ]\n";
413+
}
414+
352415
return newMachine;
353416
}
354417

‎lib/AST/RequirementMachine/RewriteContext.h

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -116,6 +116,10 @@ class RewriteContext final {
116116
/// ProtocolNode.
117117
llvm::DenseMap<unsigned, ProtocolComponent> Components;
118118

119+
/// The stack of timers for performance analysis. See beginTimer() and
120+
/// endTimer().
121+
llvm::SmallVector<uint64_t, 2> Timers;
122+
119123
ASTContext &Context;
120124

121125
DebugOptions Debug;
@@ -149,6 +153,10 @@ class RewriteContext final {
149153

150154
ASTContext &getASTContext() const { return Context; }
151155

156+
void beginTimer(StringRef name);
157+
158+
void endTimer(StringRef name);
159+
152160
//////////////////////////////////////////////////////////////////////////////
153161
///
154162
/// Reduction order on protocols.

0 commit comments

Comments
 (0)