[Remarks] Add callsite locations to inline remarks

[wenlei]

Summary

Add call site location info into inline remarks so we can differentiate inline sites.
This can be useful for inliner tuning. We can also reconstruct full hierarchical inline
tree from parsing such remarks. The messege of inline remark is also tweaked so we can
differentiate SampleProfileLoader inline from CGSCC inline.

[thegameg]

This sounds useful indeed. @fhahn, @anemet might want to take a look.

[davidxl]

Can you add a test case where there is more than one level of inline contexts for the callsite?

llvm/lib/Analysis/InlineAdvisor.cpp

391

is this necessary? User should know if their build has profile or not.

What is more useful is when PGO is on, but some callsite does not have profile data, then it is worth reporting.

[wenlei]

llvm/lib/Analysis/InlineAdvisor.cpp

391

is this necessary? User should know if their build has profile or not.

This was used to differentiate between SampleProfileLoader inline vs CGSCC inline. Maybe the message by profile guided inliner isn't great, but can't think of a better and concise way..

With the differentiation in the message, the inlinee tree recovered through some parsing is what I'm looking for ([P] for SampleProfileLoader inline, [C] for CGSCC inline):

Inlinees for main
[P]  _ZN15largesolidarrayIP6regobjEixEi @ 369
[P]  _Z7random1i @ 363
[C]    _Z8myrandomv @ 2
[P]  _Z7random1i @ 364
[C]    _Z8myrandomv @ 2
[P]  _ZN15largesolidarrayIP6regobjEixEi @ 366
[P]  _ZN6wayobj9createwayEiiiiRP8point16tRi @ 327
[P]    _ZN6wayobj11createwayarEiiRP8point16tRi @ 37.1
[P]      _ZN6wayobj5indexEii @ 143
[P]      _ZN6wayobj5indexEii @ 130
[P]      _ZN6wayobj6indexxEi @ 31
[P]      _ZN6wayobj6indexyEi @ 32
[C]      _ZN8point16tC2Ess @ 2
[C]      _ZN8point16tC2Ess @ 2.1

What is more useful is when PGO is on, but some callsite does not have profile data, then it is worth reporting.

That can be useful. I was also looking for a way to get call site count printed (if we have a count), but looks like it's not available from InlineCost. I'm going to defer that for now if that's ok.

[wenlei]

Address David's comments, add test for nested inlinining.

[davidxl]

llvm/lib/Analysis/InlineAdvisor.cpp

392

Perhaps reword it to " to match profiling context" ..

[wenlei]

llvm/lib/Analysis/InlineAdvisor.cpp

392

Sounds good, updated.

[wenlei]

Update remark message.

[davidxl]

lgtm

llvm/lib/Analysis/InlineAdvisor.cpp

383

ProfileGuidedInline --> ForProfileContext

[fhahn]

That's interesting. We are also using something similar for the matrix lowering remarks [1]: we traverse the inlining chain bottom up and emit a remark at each step which contains the expression available at that level. I think those approaches could be useful in general to surface remarks at the right level and it might be worth moving them somewhere so they can be shared. What do you think?

[1] https://github.com/llvm/llvm-project/blob/master/llvm/lib/Transforms/Scalar/LowerMatrixIntrinsics.cpp#L1783

[wenlei]

In D82213#2110941, @fhahn wrote:

That's interesting. We are also using something similar for the matrix lowering remarks [1]: we traverse the inlining chain bottom up and emit a remark at each step which contains the expression available at that level. I think those approaches could be useful in general to surface remarks at the right level and it might be worth moving them somewhere so they can be shared. What do you think?

[1] https://github.com/llvm/llvm-project/blob/master/llvm/lib/Transforms/Scalar/LowerMatrixIntrinsics.cpp#L1783

That's indeed similar, though it seems like what you're doing is more than just showing the full inline stack as location. Agreed that if we start to do these in more places for optimization remarks, it'd make sense to build it into remarks infra. But we may not always want full inline stack names as location (considering deep inlining with long template instantiation names that can "pollute" the remark messages), so I'm guessing what we could do is move that into remarks infra, but still use a separate switch to control whether we show inline locations (just like how -fdiagnostics-show-hotness controls whether we show hotness for remarks)?

clang/test/Frontend/optimization-remark-with-hotness-new-pm.c

 
 void bar(int x) {
   // HOTNESS_OFF: foo inlined into bar
   // HOTNESS_OFF-NOT: hotness:
   // THRESHOLD-NOT: inlined
   // THRESHOLD-NOT: hotness
   // NO_PGO: '-fdiagnostics-show-hotness' requires profile-guided optimization information
   // NO_PGO: '-fdiagnostics-hotness-threshold=' requires profile-guided optimization information
-  // expected-remark@+1 {{foo inlined into bar with (cost=always): always inline attribute (hotness:}}
+  // expected-remark@+1 {{foo inlined into bar with (cost=always): always inline attribute at callsite bar:8 (hotness:}}
   sum += foo(x, x - 2);
 }
 
 int main(int argc, const char *argv[]) {
   for (int i = 0; i < 30; i++)
     // expected-remark@+1 {{bar inlined into main with}}
     bar(argc);
   return sum;
 }

clang/test/Frontend/optimization-remark-with-hotness.c

 
 void bar(int x) {
   // HOTNESS_OFF: foo inlined into bar
   // HOTNESS_OFF-NOT: hotness:
   // THRESHOLD-NOT: inlined
   // THRESHOLD-NOT: hotness
   // NO_PGO: '-fdiagnostics-show-hotness' requires profile-guided optimization information
   // NO_PGO: '-fdiagnostics-hotness-threshold=' requires profile-guided optimization information
-  // expected-remark@+1 {{foo inlined into bar with (cost=always): always inliner (hotness:}}
+  // expected-remark@+1 {{foo inlined into bar with (cost=always): always inliner at callsite bar:8 (hotness:}}
   sum += foo(x, x - 2);
 }
 
 int main(int argc, const char *argv[]) {
   for (int i = 0; i < 30; i++)
     // expected-remark@+1 {{bar not inlined into main because it should never be inlined (cost=never): no alwaysinline attribute (hotness:}}
     bar(argc);
   return sum;
 }

llvm/include/llvm/Analysis/InlineAdvisor.h

 /// inlining should not be attempted.
 Optional<InlineCost>
 shouldInline(CallBase &CB, function_ref<InlineCost(CallBase &CB)> GetInlineCost,
              OptimizationRemarkEmitter &ORE, bool EnableDeferral = true);
 
 /// Emit ORE message.
 void emitInlinedInto(OptimizationRemarkEmitter &ORE, DebugLoc DLoc,
                      const BasicBlock *Block, const Function &Callee,
-                     const Function &Caller, const InlineCost &IC);
+                     const Function &Caller, const InlineCost &IC,
+                     bool ForProfileContext = false,
+                     const char *PassName = nullptr);
+
+/// Add location info to ORE message.
+void addLocationToRemarks(OptimizationRemark &Remark, DebugLoc DLoc);
 
 /// Set the inline-remark attribute.
 void setInlineRemark(CallBase &CB, StringRef Message);
 
 /// Utility for extracting the inline cost message to a string.
 std::string inlineCostStr(const InlineCost &IC);
 } // namespace llvm
 #endif // LLVM_INLINEADVISOR_H_

llvm/lib/Analysis/InlineAdvisor.cpp

 
 #include "llvm/Analysis/InlineAdvisor.h"
 #include "llvm/ADT/Statistic.h"
 #include "llvm/Analysis/InlineCost.h"
 #include "llvm/Analysis/OptimizationRemarkEmitter.h"
 #include "llvm/Analysis/ProfileSummaryInfo.h"
 #include "llvm/Analysis/TargetLibraryInfo.h"
 #include "llvm/Analysis/TargetTransformInfo.h"
+#include "llvm/IR/DebugInfoMetadata.h"
 #include "llvm/IR/Instructions.h"
 #include "llvm/Support/raw_ostream.h"
 
 #include <sstream>
 
 using namespace llvm;
 #define DEBUG_TYPE "inline"
 
if (EnableDeferral &&
     return None;
   }
 
   LLVM_DEBUG(dbgs() << "    Inlining " << inlineCostStr(IC) << ", Call: " << CB
                     << '\n');
   return IC;
 }
 
+void llvm::addLocationToRemarks(OptimizationRemark &Remark, DebugLoc DLoc) {
+  if (!DLoc.get())
+    return;
+
+  bool First = true;
+  Remark << " at callsite ";
+  for (DILocation *DIL = DLoc.get(); DIL; DIL = DIL->getInlinedAt()) {
+    if (!First)
+      Remark << " @ ";
+    unsigned int Offset = DIL->getLine();
+    Offset -= DIL->getScope()->getSubprogram()->getLine();
+    unsigned int Discriminator = DIL->getBaseDiscriminator();
+    StringRef Name = DIL->getScope()->getSubprogram()->getLinkageName();
+    if (Name.empty())
+      Name = DIL->getScope()->getSubprogram()->getName();
+    Remark << Name << ":" << ore::NV("Line", Offset);
+    if (Discriminator)
+      Remark << "." << ore::NV("Disc", Discriminator);
+    First = false;
+  }
+}
+
 void llvm::emitInlinedInto(OptimizationRemarkEmitter &ORE, DebugLoc DLoc,
                            const BasicBlock *Block, const Function &Callee,
-                           const Function &Caller, const InlineCost &IC) {
+                           const Function &Caller, const InlineCost &IC,
+                           bool ForProfileContext, const char *PassName) {
   ORE.emit([&]() {
     bool AlwaysInline = IC.isAlways();
     StringRef RemarkName = AlwaysInline ? "AlwaysInline" : "Inlined";
-    return OptimizationRemark(DEBUG_TYPE, RemarkName, DLoc, Block)
-           << ore::NV("Callee", &Callee) << " inlined into "
-           << ore::NV("Caller", &Caller) << " with " << IC;
+    OptimizationRemark Remark(PassName ? PassName : DEBUG_TYPE, RemarkName,
+                              DLoc, Block);
+    Remark << ore::NV("Callee", &Callee) << " inlined into ";
+    Remark << ore::NV("Caller", &Caller);
+    if (ForProfileContext)
+      Remark << " to match profiling context";
+    Remark << " with " << IC;
+    addLocationToRemarks(Remark, DLoc);
+    return Remark;
   });
 }

llvm/lib/Transforms/IPO/SampleProfile.cpp

 #include "llvm/ADT/SmallVector.h"
 #include "llvm/ADT/Statistic.h"
 #include "llvm/ADT/StringMap.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/ADT/Twine.h"
 #include "llvm/Analysis/AssumptionCache.h"
 #include "llvm/Analysis/CallGraph.h"
 #include "llvm/Analysis/CallGraphSCCPass.h"
+#include "llvm/Analysis/InlineAdvisor.h"
 #include "llvm/Analysis/InlineCost.h"
 #include "llvm/Analysis/LoopInfo.h"
 #include "llvm/Analysis/OptimizationRemarkEmitter.h"
 #include "llvm/Analysis/PostDominators.h"
 #include "llvm/Analysis/ProfileSummaryInfo.h"
 #include "llvm/Analysis/TargetLibraryInfo.h"
 #include "llvm/Analysis/TargetTransformInfo.h"
 #include "llvm/IR/BasicBlock.h"
bool SampleProfileLoader::inlineCallInstruction(CallBase &CB) {
   if (Cost.isNever()) {
     ORE->emit(OptimizationRemarkAnalysis(CSINLINE_DEBUG, "InlineFail", DLoc, BB)
               << "incompatible inlining");
     return false;
   }
   InlineFunctionInfo IFI(nullptr, GetAC);
   if (InlineFunction(CB, IFI).isSuccess()) {
     // The call to InlineFunction erases I, so we can't pass it here.
-    ORE->emit(OptimizationRemark(CSINLINE_DEBUG, "InlineSuccess", DLoc, BB)
-              << "inlined callee '" << ore::NV("Callee", CalledFunction)
-              << "' into '" << ore::NV("Caller", BB->getParent()) << "'");
+    emitInlinedInto(*ORE, DLoc, BB, *CalledFunction, *BB->getParent(), Cost,
+                    true, CSINLINE_DEBUG);
     return true;
   }
   return false;
 }
 
 bool SampleProfileLoader::shouldInlineColdCallee(CallBase &CallInst) {
   if (!ProfileSizeInline)
     return false;

llvm/test/Transforms/Inline/optimization-remarks-passed-yaml.ll

 ; is the input:
 
 ;  1     int foo() { return 1; }
 ;  2
 ;  3     int bar() {
 ;  4       return foo();
 ;  5     }
 
-; CHECK: remark: /tmp/s.c:4:10: foo inlined into bar with (cost={{[0-9\-]+}}, threshold={{[0-9]+}}) (hotness: 30)
+; CHECK: remark: /tmp/s.c:4:10: foo inlined into bar with (cost={{[0-9\-]+}}, threshold={{[0-9]+}}) at callsite bar:1 (hotness: 30)
 
 ; YAML:      --- !Passed
 ; YAML-NEXT: Pass:            inline
 ; YAML-NEXT: Name:            Inlined
 ; YAML-NEXT: DebugLoc:        { File: '/tmp/s.c', Line: 4, Column: 10 }
 ; YAML-NEXT: Function:        bar
 ; YAML-NEXT: Hotness:         30
 ; YAML-NEXT: Args:
 ; YAML-NEXT:   - Callee: foo
 ; YAML-NEXT:     DebugLoc:        { File: '/tmp/s.c', Line: 1, Column: 0 }
 ; YAML-NEXT:   - String: ' inlined into '
 ; YAML-NEXT:   - Caller: bar
 ; YAML-NEXT:     DebugLoc:        { File: '/tmp/s.c', Line: 3, Column: 0 }
 ; YAML-NEXT:   - String: ' with '
 ; YAML-NEXT:   - String: '(cost='
 ; YAML-NEXT:   - Cost: '{{[0-9\-]+}}'
 ; YAML-NEXT:   - String: ', threshold='
 ; YAML-NEXT:   - Threshold: '{{[0-9]+}}'
 ; YAML-NEXT:   - String: ')'
+; YAML-NEXT:   - String:          ' at callsite '
+; YAML-NEXT:   - String:          bar
+; YAML-NEXT:   - String:          ':'
+; YAML-NEXT:   - Line:            '1'
 ; YAML-NEXT: ...
 
 ; ModuleID = '/tmp/s.c'
 source_filename = "/tmp/s.c"
 target datalayout = "e-m:o-i64:64-f80:128-n8:16:32:64-S128"
 target triple = "x86_64-apple-macosx10.11.0"
 
 ; Function Attrs: nounwind ssp uwtable

llvm/test/Transforms/SampleProfile/Inputs/remarks.prof

 main:623868:0
  0: 0
  0: _Z3foov:623868
   3: 18346
   4: 0
   6: 19475
+  6: rand:12093
+   0: 11203
   2: 18305

llvm/test/Transforms/SampleProfile/remarks.ll

 ;     9          sum += -i * rand();
 ;    10      return sum;
 ;    11    }
 ;    12
 ;    13    int main() { return foo() > 0; }
 
 ; We are expecting foo() to be inlined in main() (almost all the cycles are
 ; spent inside foo).
-; CHECK: remark: remarks.cc:13:21: inlined callee '_Z3foov' into 'main'
+; CHECK: remark: remarks.cc:13:21: _Z3foov inlined into main to match profiling context with (cost=130, threshold=225) at callsite main:0
+; CHECK: remark: remarks.cc:9:19: rand inlined into main to match profiling context with (cost=always): always inline attribute at callsite _Z3foov:6 @ main:0
 
 ; The back edge for the loop is the hottest edge in the loop subgraph.
 ; CHECK: remark: remarks.cc:6:9: most popular destination for conditional branches at remarks.cc:5:3
 
 ; The predicate almost always chooses the 'else' branch.
 ; CHECK: remark: remarks.cc:9:15: most popular destination for conditional branches at remarks.cc:6:9
 
 ; Checking to see if YAML file is generated and contains remarks
 ;YAML:       --- !Passed
 ;YAML-NEXT:  Pass:            sample-profile-inline
-;YAML-NEXT:  Name:            InlineSuccess
+;YAML-NEXT:  Name:            Inlined
 ;YAML-NEXT:  DebugLoc:        { File: remarks.cc, Line: 13, Column: 21 }
 ;YAML-NEXT:  Function:        main
 ;YAML-NEXT:  Args:
-;YAML-NEXT:    - String:          'inlined callee '''
 ;YAML-NEXT:    - Callee:          _Z3foov
 ;YAML-NEXT:      DebugLoc:        { File: remarks.cc, Line: 3, Column: 0 }
-;YAML-NEXT:    - String:          ''' into '''
+;YAML-NEXT:    - String:          ' inlined into '
 ;YAML-NEXT:    - Caller:          main
 ;YAML-NEXT:        DebugLoc:        { File: remarks.cc, Line: 13, Column: 0 }
-;YAML-NEXT:    - String:          ''''
+;YAML-NEXT:    - String:          ' to match profiling context'
+;YAML-NEXT:    - String:          ' with '
+;YAML-NEXT:    - String:          '(cost='
+;YAML-NEXT:    - Cost:            '130'
+;YAML-NEXT:    - String:          ', threshold='
+;YAML-NEXT:    - Threshold:       '225'
+;YAML-NEXT:    - String:          ')'
+;YAML-NEXT:    - String:          ' at callsite '
+;YAML-NEXT:    - String:          main
+;YAML-NEXT:    - String:          ':'
+;YAML-NEXT:    - Line:            '0'
 ;YAML-NEXT:  ...
+;YAML:       --- !Passed
+;YAML-NEXT:  Pass:            sample-profile-inline
+;YAML-NEXT:  Name:            AlwaysInline
+;YAML-NEXT:  DebugLoc:        { File: remarks.cc, Line: 9, Column: 19 }
+;YAML-NEXT:  Function:        main
+;YAML-NEXT:  Args:
+;YAML-NEXT:    - Callee:          rand
+;YAML-NEXT:      DebugLoc:        { File: remarks.cc, Line: 90, Column: 0 }
+;YAML-NEXT:    - String:          ' inlined into '
+;YAML-NEXT:    - Caller:          main
+;YAML-NEXT:      DebugLoc:        { File: remarks.cc, Line: 13, Column: 0 }
+;YAML-NEXT:    - String:          ' to match profiling context'
+;YAML-NEXT:    - String:          ' with '
+;YAML-NEXT:    - String:          '(cost=always)'
+;YAML-NEXT:    - String:          ': '
+;YAML-NEXT:    - Reason:          always inline attribute
+;YAML-NEXT:    - String:          ' at callsite '
+;YAML-NEXT:    - String:          _Z3foov
+;YAML-NEXT:    - String:          ':'
+;YAML-NEXT:    - Line:            '6'
+;YAML-NEXT:    - String:          ' @ '
+;YAML-NEXT:    - String:          main
+;YAML-NEXT:    - String:          ':'
+;YAML-NEXT:    - Line:            '0'
 ;YAML:  --- !Analysis
 ;YAML-NEXT:  Pass:            sample-profile
 ;YAML-NEXT:  Name:            AppliedSamples
 ;YAML-NEXT:  DebugLoc:        { File: remarks.cc, Line: 5, Column: 8 }
 ;YAML-NEXT:  Function:        main
 ;YAML-NEXT:  Args:
 ;YAML-NEXT:    - String:          'Applied '
 ;YAML-NEXT:    - NumSamples:      '18305'

 
 ; Function Attrs: nounwind argmemonly
 declare void @llvm.lifetime.start.p0i8(i64, i8* nocapture) #1
 
 ; Function Attrs: nounwind readnone
 declare void @llvm.dbg.declare(metadata, metadata, metadata) #2
 
 ; Function Attrs: nounwind
-declare i32 @rand() #3
+define i32 @rand() #3 !dbg !59 {
+  ret i32 1
+}
 
 ; Function Attrs: nounwind argmemonly
 declare void @llvm.lifetime.end.p0i8(i64, i8* nocapture) #1
 
 ; Function Attrs: nounwind uwtable
 define i32 @main() #0 !dbg !13 {
 entry:
   %retval = alloca i32, align 4
   store i32 0, i32* %retval, align 4
   %call = call i64 @_Z3foov(), !dbg !56
   %cmp = icmp sgt i64 %call, 0, !dbg !57
   %conv = zext i1 %cmp to i32, !dbg !56
   ret i32 %conv, !dbg !58
 }
 
 attributes #0 = { nounwind uwtable "disable-tail-calls"="false" "less-precise-fpmad"="false" "frame-pointer"="none" "no-infs-fp-math"="false" "no-nans-fp-math"="false" "stack-protector-buffer-size"="8" "target-cpu"="x86-64" "target-features"="+fxsr,+mmx,+sse,+sse2" "unsafe-fp-math"="false" "use-soft-float"="false" "use-sample-profile" }
 attributes #1 = { nounwind argmemonly }
 attributes #2 = { nounwind readnone }
-attributes #3 = { nounwind "disable-tail-calls"="false" "less-precise-fpmad"="false" "frame-pointer"="none" "no-infs-fp-math"="false" "no-nans-fp-math"="false" "stack-protector-buffer-size"="8" "target-cpu"="x86-64" "target-features"="+fxsr,+mmx,+sse,+sse2" "unsafe-fp-math"="false" "use-soft-float"="false" }
+attributes #3 = { nounwind alwaysinline "disable-tail-calls"="false" "less-precise-fpmad"="false" "frame-pointer"="none" "no-infs-fp-math"="false" "no-nans-fp-math"="false" "stack-protector-buffer-size"="8" "target-cpu"="x86-64" "target-features"="+fxsr,+mmx,+sse,+sse2" "unsafe-fp-math"="false" "use-soft-float"="false" }
 attributes #4 = { nounwind }
 
 !llvm.dbg.cu = !{!0}
 !llvm.module.flags = !{!16, !17}
 !llvm.ident = !{!18}
 
 !0 = distinct !DICompileUnit(language: DW_LANG_C_plus_plus, file: !1, producer: "clang version 3.8.0 (trunk 251041) (llvm/trunk 251053)", isOptimized: true, runtimeVersion: 0, emissionKind: NoDebug, enums: !2)
 !1 = !DIFile(filename: "remarks.cc", directory: ".")

 !51 = !DILocation(line: 5, column: 35, scope: !33)
 !52 = !DILocation(line: 5, column: 3, scope: !33)
 !53 = !DILocation(line: 10, column: 10, scope: !4)
 !54 = !DILocation(line: 11, column: 1, scope: !4)
 !55 = !DILocation(line: 10, column: 3, scope: !4)
 !56 = !DILocation(line: 13, column: 21, scope: !13)
 !57 = !DILocation(line: 13, column: 27, scope: !13)
 !58 = !DILocation(line: 13, column: 14, scope: !13)
+!59 = distinct !DISubprogram(name: "rand", linkageName: "rand", scope: !1, file: !1, line: 90, type: !5, isLocal: false, isDefinition: true, scopeLine: 90, flags: DIFlagPrototyped, isOptimized: true, unit: !0)