[NFC][SampleFDO] Add more debugging logic.

[hoy]

Summary

Adding more debugging logic to the sample profile loader inliner. Also
enchancing basic block name printing for blocks that don't come with a
name. Such blocks could come from prelink.

[wenlei]

llvm/include/llvm/Transforms/Utils/SampleProfileLoaderBaseImpl.h

217

This is useful, I wondering if this can be used to improve print block names in general, in addition to sample loader.

llvm/lib/Transforms/IPO/SampleProfile.cpp

889–890

Inside pgo::promoteIndirectCall, there is a remark covering this info already under pgo-icall-prom.

1178

This kind of message looks like the one that should be covered by remarks, and it's covered here. Is the remarks not enough? Looking at other place (Inliner/InlineCost, etc), we don't duplicate those messages between remarks and LLVM_DEBUG.

Same for the ones below.

1268

This seems a bit random/lack of structure. There's nothing marking the debugging message's start/end for a functions.

If we want, we can organize the messages so we know which function/inliner each message is about.

Also a general comment, adding all debug prints used when debugging smaller programs would make the debugging message hard to use for large programs. So I'd be a bit cautious about adding those.

1433

Unless the messages are structured, i.e there's a paired message saying which function we're currently processing, it'd be good to point out the function/inliner too.

[hoy]

llvm/include/llvm/Transforms/Utils/SampleProfileLoaderBaseImpl.h

217

Good point. We can make this a debug method of BasicBlock and MachineBasicBlock so that other passes can use it too.

llvm/lib/Transforms/IPO/SampleProfile.cpp

889–890

Yeah, but then you would need turn on two debug switches which may cause the debug log even longer. I've been using this to identify whether a missing inlining is due to missing ICP.

1178

I found that including this in the debug log is useful so that I could just focus on the debug log. Otherwise I had to cross look up and match the trace between debug log and remarks. LLVM_DEBUG is also used in inliner.cpp/inlineAdvisor.cpp (e.g, llvm::shouldInline) in addition to the remarks..

1268

There is a printing in the start SampleProfileLoader::runOnFunction I've been relying on to track the processing of a function. An example dump is like:

Processing Function _ZL26gen_send_ex_with_finish_yfP11PyGenObjectP7_objectiii.__uniq.47563953835103695458357092675948446368.llvm.8607294674879278747


Processing Function _ZL13call_functionP3_tsPPP7_objectlS2_m.__uniq.168935451908848054575265387003954625183.llvm.7825644747239789945
    3:  call void @llvm.pseudoprobe(i64 -4587497180907640548, i64 3, i32 0, i64 -1) #45, !dbg !22657 - weight: 171387 - factor: 1.00)
    8:  %48 = call %struct._object* %42(%struct._object* nonnull %10, %struct._object** %21, i64 %29, %struct._object* %3) #45, !dbg !22658, !prof !22660 - weight: 182417 - factor: 1.00)
    9:  %49 = call %struct._object* @_Py_CheckFunctionResult(%struct._object* nonnull %10, %struct._object* %48, i8* null) #45, !dbg !22661, !prof !22663 - weight: 171387 - factor: 1.00)
Inline Candidate:   %48 = call %struct._object* %42(%struct._object* nonnull %10, %struct._object** %21, i64 %29, %struct._object* %3) #45, !dbg !22658, !prof !22660
    3:  call void @llvm.pseudoprobe(i64 -4587497180907640548, i64 3, i32 0, i64 -1) #45, !dbg !22657 - weight: 171387 - factor: 1.00)
    8:  %48 = call %struct._object* %42(%struct._object* nonnull %10, %struct._object** %21, i64 %29, %struct._object* %3) #45, !dbg !22658, !prof !22660 - weight: 182417 - factor: 1.00)
    9:  %49 = call %struct._object* @_Py_CheckFunctionResult(%struct._object* nonnull %10, %struct._object* %48, i8* null) #45, !dbg !22661, !prof !22663 - weight: 171387 - factor: 1.00)
Inline Candidate:   %49 = call %struct._object* @_Py_CheckFunctionResult(%struct._object* nonnull %10, %struct._object* %48, i8* null) #45, !dbg !22661, !prof !22663
    5:  call void @llvm.pseudoprobe(i64 -7330008250765460926, i64 5, i32 0, i64 -1) #45, !dbg !22696 - weight: 21209 - factor: 1.00)
    7:  call void @_Py_Dealloc(%struct._object* nonnull %57) #45, !dbg !22698, !prof !22700 - weight: 21209 - factor: 1.00)
Inline Candidate:   call void @_Py_Dealloc(%struct._object* nonnull %57) #45, !dbg !22698, !prof !22700

Promoted indirect call   %53 = call %struct._object* %42(%struct._object* nonnull %10, %struct._object** %21, i64 %29, %struct._object* %3) #45, !dbg !22658, !prof !22661
 to   %51 = call %struct._object* @_ZL28_PyFunction_Vectorcall_NArgsP16PyFunctionObjectPP7_objectmS2_.__uniq.168935451908848054575265387003954625183.llvm.7825644747239789945(%struct.PyFunctionObject* nonnull %50, %struct._object** %21, i64 %29, %struct._object* %3) #45, !dbg !22658

Inlining _ZL28_PyFunction_Vectorcall_NArgsP16PyFunctionObjectPP7_objectmS2_.__uniq.168935451908848054575265387003954625183.llvm.7825644747239789945

Inlined _ZL28_PyFunction_Vectorcall_NArgsP16PyFunctionObjectPP7_objectmS2_.__uniq.168935451908848054575265387003954625183.llvm.7825644747239789945

llvm/include/llvm/Transforms/Utils/SampleProfileLoaderBaseImpl.h

void SampleProfileLoaderBaseImpl<BT>::clearFunctionData() {
   PDT = nullptr;
   LI = nullptr;
   Predecessors.clear();
   Successors.clear();
   CoverageTracker.clear();
 }
 
 #ifndef NDEBUG
+template <typename BT> static inline std::string getName(const BT *BB) {
+  if (BB->hasName())
+    return BB->getName().str();
+  std::string Str;
+  raw_string_ostream OS(Str);
+  BB->printAsOperand(OS, false);
+  return Str;
+}
+
 /// Print the weight of edge \p E on stream \p OS.
 ///
 /// \param OS  Stream to emit the output to.
 /// \param E  Edge to print.
 template <typename BT>
 void SampleProfileLoaderBaseImpl<BT>::printEdgeWeight(raw_ostream &OS, Edge E) {
-  OS << "weight[" << E.first->getName() << "->" << E.second->getName()
+  OS << "weight[" << getName(E.first) << "->" << getName(E.second)
      << "]: " << EdgeWeights[E] << "\n";
 }
 
 /// Print the equivalence class of block \p BB on stream \p OS.
 ///
 /// \param OS  Stream to emit the output to.
 /// \param BB  Block to print.
 template <typename BT>
 void SampleProfileLoaderBaseImpl<BT>::printBlockEquivalence(
     raw_ostream &OS, const BasicBlockT *BB) {
   const BasicBlockT *Equiv = EquivalenceClass[BB];
-  OS << "equivalence[" << BB->getName()
-     << "]: " << ((Equiv) ? EquivalenceClass[BB]->getName() : "NONE") << "\n";
+  OS << "equivalence[" << getName(BB)
+     << "]: " << ((Equiv) ? getName(EquivalenceClass[BB]) : "NONE") << "\n";
 }
 
 /// Print the weight of block \p BB on stream \p OS.
 ///
 /// \param OS  Stream to emit the output to.
 /// \param BB  Block to print.
 template <typename BT>
 void SampleProfileLoaderBaseImpl<BT>::printBlockWeight(
     raw_ostream &OS, const BasicBlockT *BB) const {
   const auto &I = BlockWeights.find(BB);
   uint64_t W = (I == BlockWeights.end() ? 0 : I->second);
-  OS << "weight[" << BB->getName() << "]: " << W << "\n";
+  OS << "weight[" << getName(BB) << "]: " << W << "\n";
 }
 #endif
 
 /// Get the weight for an instruction.
 ///
 /// The "weight" of an instruction \p Inst is the number of samples
 /// collected on that instruction at runtime. To retrieve it, we
 /// need to compute the line number of \p Inst relative to the start of its

llvm/lib/Transforms/IPO/SampleProfile.cpp

if (!R->getValue()->isDeclaration() && R->getValue()->getSubprogram() &&
     // in the value profile metadata so the target won't be promoted again.
     SmallVector<InstrProfValueData, 1> SortedCallTargets = {InstrProfValueData{
         Function::getGUID(R->getValue()->getName()), NOMORE_ICP_MAGICNUM}};
     updateIDTMetaData(CI, SortedCallTargets, 0);
 
     auto *DI = &pgo::promoteIndirectCall(
         CI, R->getValue(), Candidate.CallsiteCount, Sum, false, ORE);
     if (DI) {
+      LLVM_DEBUG(dbgs() << "Promoted indirect call " << CI << "\n"
+                        << " to " << *DI << "\n");
       Sum -= Candidate.CallsiteCount;
       // Do not prorate the indirect callsite distribution since the original
       // distribution will be used to scale down non-promoted profile target
       // counts later. By doing this we lose track of the real callsite count
       // for the leftover indirect callsite as a trade off for accurate call
       // target counts.
       // TODO: Ideally we would have two separate factors, one for call site
       // counts and one is used to prorate call target counts.
bool SampleProfileLoader::tryInlineCandidate(
   assert(CalledFunction && "Expect a callee with definition");
   DebugLoc DLoc = CB.getDebugLoc();
   BasicBlock *BB = CB.getParent();
 
   InlineCost Cost = shouldInlineCandidate(Candidate);
   if (Cost.isNever()) {
     ORE->emit(OptimizationRemarkAnalysis(CSINLINE_DEBUG, "InlineFail", DLoc, BB)
               << "incompatible inlining");
+    LLVM_DEBUG(dbgs() << "Failed to inline call " << CB
+                      << "\n because of incompatible inlining\n");
     return false;
   }
 
-  if (!Cost)
+  if (!Cost) {
+    LLVM_DEBUG(dbgs() << "Failed to inline call " << CB
+                      << "\n with CallsiteCount " << Candidate.CallsiteCount
+                      << " HotCountThreshold " << PSI->getHotCountThreshold()
+                      << " Cost " << Cost.getCost() << " CostThreshold "
+                      << Cost.getThreshold() << "\n");
     return false;
+  }
 
   InlineFunctionInfo IFI(nullptr, GetAC);
   IFI.UpdateProfile = false;
-  if (InlineFunction(CB, IFI).isSuccess()) {
+  InlineResult IR = InlineFunction(CB, IFI);
+  if (IR.isSuccess()) {
     // The call to InlineFunction erases I, so we can't pass it here.
     emitInlinedInto(*ORE, DLoc, BB, *CalledFunction, *BB->getParent(), Cost,
                     true, CSINLINE_DEBUG);
 
     // Now populate the list of newly exposed call sites.
     if (InlinedCallSites) {
       InlinedCallSites->clear();
       for (auto &I : IFI.InlinedCallSites)
if (Candidate.CallsiteDistribution < 1) {
       for (auto &I : IFI.InlinedCallSites) {
         if (Optional<PseudoProbe> Probe = extractProbe(*I))
           setProbeDistributionFactor(*I, Probe->Factor *
                                              Candidate.CallsiteDistribution);
       }
       NumDuplicatedInlinesite++;
     }
 
+    LLVM_DEBUG(dbgs() << "Inlined " << CalledFunction->getName() << "\n");
     return true;
+  } else {
+    ORE->emit([&]() {
+      return OptimizationRemarkMissed(CSINLINE_DEBUG, "NotInlined", DLoc, BB)
+             << ore::NV("Callee", CalledFunction)
+             << " will not be inlined into "
+             << ore::NV("Caller", BB->getParent()) << ": "
+             << ore::NV("Reason", IR.getFailureReason());
+    });
+    LLVM_DEBUG(dbgs() << "Failed to inline call " << CB << "\n because of "
+                      << IR.getFailureReason() << "\n");
   }
   return false;
 }
 
 bool SampleProfileLoader::getInlineCandidate(InlineCandidate *NewCandidate,
                                              CallBase *CB) {
   assert(CB && "Expect non-null call instruction");
 
bool SampleProfileLoader::getInlineCandidate(InlineCandidate *NewCandidate,
   ErrorOr<uint64_t> Weight = getBlockWeight(CB->getParent());
   if (Weight)
     CallsiteCount = Weight.get();
   if (CalleeSamples)
     CallsiteCount = std::max(
         CallsiteCount, uint64_t(CalleeSamples->getEntrySamples() * Factor));
 
   *NewCandidate = {CB, CalleeSamples, CallsiteCount, Factor};
+  LLVM_DEBUG(dbgs() << "Inline Candidate: " << *CB << "\n");
   return true;
 }
 
 InlineCost
 SampleProfileLoader::shouldInlineCandidate(InlineCandidate &Candidate) {
   std::unique_ptr<InlineAdvice> Advice = nullptr;
   if (ExternalInlineAdvisor) {
     Advice = ExternalInlineAdvisor->getAdvice(*Candidate.CallInstr);
SampleProfileLoader::shouldInlineCandidate(InlineCandidate &Candidate) {
 
   // Otherwise only use the cost from call analyzer, but overwite threshold with
   // Sample PGO threshold.
   return InlineCost::get(Cost.getCost(), SampleThreshold);
 }
 
 bool SampleProfileLoader::inlineHotFunctionsWithPriority(
     Function &F, DenseSet<GlobalValue::GUID> &InlinedGUIDs) {
-  assert(ProfileIsCS && "Prioritiy based inliner only works with CSSPGO now");
+  assert(ProfileIsCS && "Priority based inliner only works with CSSPGO now");
 
   // ProfAccForSymsInList is used in callsiteIsHot. The assertion makes sure
   // Profile symbol list is ignored when profile-sample-accurate is on.
   assert((!ProfAccForSymsInList ||
           (!ProfileSampleAccurate &&
            !F.hasFnAttribute("profile-sample-accurate"))) &&
          "ProfAccForSymsInList should be false when profile-sample-accurate "
          "is enabled");
if (I->isIndirectCall()) {
       }
     } else if (LTOPhase == ThinOrFullLTOPhase::ThinLTOPreLink) {
       findExternalInlineCandidate(Candidate.CalleeSamples, InlinedGUIDs,
                                   SymbolMap, PSI->getOrCompHotCountThreshold());
     }
   }
 
   if (!CQueue.empty()) {
+    LLVM_DEBUG(dbgs() << "Inlining stopped, out of budget\n");
     if (SizeLimit == (unsigned)ProfileInlineLimitMax)
       ++NumCSInlinedHitMaxLimit;
     else if (SizeLimit == (unsigned)ProfileInlineLimitMin)
       ++NumCSInlinedHitMinLimit;
     else
       ++NumCSInlinedHitGrowthLimit;
   }