Page MenuHomePhabricator

[NFC][SampleFDO] Add more debugging logic.
Needs ReviewPublic

Authored by hoy on May 19 2021, 1:56 PM.

Details

Reviewers
wenlei
wmi
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.

Diff Detail

Event Timeline

hoy created this revision.May 19 2021, 1:56 PM
hoy requested review of this revision.May 19 2021, 1:56 PM
Herald added a project: Restricted Project. · View Herald TranscriptMay 19 2021, 1:56 PM
wenlei added inline comments.May 19 2021, 2:24 PM
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 added inline comments.May 19 2021, 2:42 PM
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