[PATCH] D102808: [NFC][SampleFDO] Add more debugging logic.

[Hongtao Yu via Phabricator via llvm-commits]

hoy added inline comments.


================
Comment at: llvm/include/llvm/Transforms/Utils/SampleProfileLoaderBaseImpl.h:217
 #ifndef NDEBUG
+template <typename BT> static inline std::string getName(const BT *BB) {
+  if (BB->hasName())
----------------
wenlei wrote:
> This is useful, I wondering if this can be used to improve print block names in general, in addition to sample loader.
Good point. We can make this a debug method of BasicBlock and MachineBasicBlock so that other passes can use it too.


================
Comment at: llvm/lib/Transforms/IPO/SampleProfile.cpp:889-890
     if (DI) {
+      LLVM_DEBUG(dbgs() << "Promoted indirect call " << CI << "\n"
+                        << " to " << *DI << "\n");
       Sum -= Candidate.CallsiteCount;
----------------
wenlei wrote:
> Inside `pgo::promoteIndirectCall`, there is a remark covering this info already under `pgo-icall-prom`.
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.


================
Comment at: llvm/lib/Transforms/IPO/SampleProfile.cpp:1178
               << "incompatible inlining");
+    LLVM_DEBUG(dbgs() << "Failed to inline call " << CB
+                      << "\n because of incompatible inlining\n");
----------------
wenlei wrote:
> 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.
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.. 


================
Comment at: llvm/lib/Transforms/IPO/SampleProfile.cpp:1268
   *NewCandidate = {CB, CalleeSamples, CallsiteCount, Factor};
+  LLVM_DEBUG(dbgs() << "Inline Candidate: " << *CB << "\n");
   return true;
----------------
wenlei wrote:
> 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. 
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

```


Repository:
  rG LLVM Github Monorepo

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D102808/new/

https://reviews.llvm.org/D102808