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.

Sign up for GitHub

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

Jump to bottom

verifyFunction spends too much time validating !dbg metadata in +asserts builds #47056

Open
rnk opened this issue Oct 2, 2020 · 4 comments
Open

verifyFunction spends too much time validating !dbg metadata in +asserts builds #47056

rnk opened this issue Oct 2, 2020 · 4 comments
Labels
bugzilla Issues migrated from bugzilla llvm:core

Comments

@rnk
Copy link
Collaborator

rnk commented Oct 2, 2020

Bugzilla Link 47712
Version trunk
OS Windows NT
CC @adrian-prantl,@fhahn,@zmodem,@nico,@rotateright,@vedantk

Extended Description

I was profiling LLVM for other reasons and accidentally used a build with assertions enabled. What I discovered is that, if you compile PassBuilder.cpp with assertions, most of the time is spent in the verifier, mostly due to asserts in SLPVectorizer and LoopVectorizer. There are 187,486 samples overall, and 131,698 of them (70.2%) are inside calls to verifyFunction.

If you drill into what verifyFunction is doing, all the time is spent in recursive calls to visitMDNode. These calls are rooted in visitInstruction calls to visitMDNode:
https://github.com/llvm/llvm-project/blob/master/llvm/lib/IR/Verifier.cpp#L4431

visitMDNode in turn validates each of its operands. This is undesirable when validating a function: location metadata points upwards, so validating one location will ultimately validate the entire metadata graph rooted in the compile unit. See the tree of calls in this screenshot:
https://reviews.llvm.org/file/data/u5ms43qqwl3aahxopjql/PHID-FILE-ysoomivlg3fixz52f4ny/visitmdnode-profile.png

The code I linked was added in http://github.com/llvm/llvm-project/commit/8dfe819bcd23, but I'm not sure when this regressed. We used to ship clang with assertions enabled, so we saw these non-linear assert compile time issues in the field as they arose. Now that we are no longer watching carefully, it seems like these issues can slip in.

Should we try to establish the invariant that llvm::verifyFunction runs in O(#instructions), or should we move all calls to verifyFunction to EXPENSIVE_CHECKS?
@fhahn
Copy link
Contributor

fhahn commented Jan 9, 2021

Should we try to establish the invariant that llvm::verifyFunction runs in
O(#instructions), or should we move all calls to verifyFunction to
EXPENSIVE_CHECKS?

I think verifyFunction is too valuable for builds with assertions to put it behind EXPENSIVE_CHECKS.

Limiting assertions outside EXPENSIVE_CHECKS to be O(#instructions) seems very reasonable and a natural cut-off for non-expensive checks. (I think plenty of the current uses of EXPENSIVE_CHECKS already follow a similar reasoning). Might be good to spell it out somewhere. We probably should limit it to #instruction the pass operates on, e.g. a loop pass should not verify the whole function for each loop in a function.

As for the issue at hand in verifyFunction, I think we could limit the expensive MD verification to EXPENSIVE_CHECKS to start with.

@fhahn
Copy link
Contributor

fhahn commented Jan 13, 2021

A potentially related issue motivated another patch: https://reviews.llvm.org/D94576

Reid, do you happen to still have the file & flags to reproduce this? I tried with a recent Clang build & current main, but couldn't reproduce it by building PassBuilder.cpp

@fhahn
Copy link
Contributor

fhahn commented Jan 13, 2021

Reid, do you happen to still have the file & flags to reproduce this? I
tried with a recent Clang build & current main, but couldn't reproduce it by
building PassBuilder.cpp

Nevermind, this can be reproduced by building PassBuilder.cpp with -O3 and -g. Time spent in verifyFunction goes from >0.5% of total compile-time to ~11% total compile-time. Here's the trace, with total time spent & percentage of total compile-time.

8.91 s 12.7% 3.00 ms (anonymous namespace)::LoopVectorize::runOnFunction(llvm::Function&)
8.90 s 12.7% 0 s llvm::LoopVectorizePass::runImpl(llvm::Function&, llvm::ScalarEvolution&, llvm::LoopInfo&, llvm::TargetTransformInfo&, llvm::DominatorTree&, llvm::BlockFrequencyInfo&, llvm::TargetLibraryInfo*, llvm::DemandedBits&, llvm::AAResults&, llvm::AssumptionCache&, std::__1::function<llvm::LoopAccessInfo const& (llvm::Loop&)>&, llvm::OptimizationRemarkEmitter&, llvm::ProfileSummaryInfo*)
8.89 s 12.7% 2.00 ms llvm::LoopVectorizePass::processLoop(llvm::Loop*)
8.61 s 12.3% 0 s llvm::verifyFunction(llvm::Function const&, llvm::raw_ostream*)
8.54 s 12.2% 66.00 ms (anonymous namespace)::Verifier::verify(llvm::Function const&)
7.97 s 11.4% 0 s (anonymous namespace)::Verifier::visitMDNode(llvm::MDNode const&)
7.97 s 11.4% 12.00 ms (anonymous namespace)::Verifier::visitMDNode(llvm::MDNode const&)
7.96 s 11.4% 30.00 ms (anonymous namespace)::Verifier::visitMDNode(llvm::MDNode const&)
7.93 s 11.3% 71.00 ms (anonymous namespace)::Verifier::visitMDNode(llvm::MDNode const&)
1.00 ms 0.0% 0 s ml_set_interrupts_enabled
1.00 ms 0.0% 0 s (anonymous namespace)::Verifier::verifySourceDebugInfo(llvm::DICompileUnit const&, llvm::DIFile const&)
347.00 ms 0.4% 2.00 ms (anonymous namespace)::Verifier::visitCallInst(llvm::CallInst&)

I also get similar results with http://github.com/llvm/llvm-project/commit/8dfe819bcd23 reverted.

@rnk
Copy link
Collaborator Author

rnk commented Nov 27, 2021

mentioned in issue llvm/llvm-bugzilla-archive#48689

@llvmbot llvmbot transferred this issue from llvm/llvm-bugzilla-archive Dec 10, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bugzilla Issues migrated from bugzilla llvm:core
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rnk @fhahn