[BOLT] Add stale-related logging

[spupyrev]

Summary

Adding some logs related to stale profile matching. The new data can be helpful
to understand how "stale" the input profile is and how well the inference is
able to utilize the stale data.

Example of outputs on clang-10 built with LTO (profile collected on a year-old release):

BOLT-INFO: inferred profile for 2101 (18.52% of profiled, 100.00% of stale) functions responsible for 30.95% samples (14754697 out of 47670654)
BOLT-INFO: stale inference matched 89.42% of basic blocks (79052 out of 88402 stale) responsible for 76.99% samples (645737 out of 838719 stale)

LTO+AutoFDO:

BOLT-INFO: inferred profile for 6146 (57.57% of profiled, 100.00% of stale) functions responsible for 90.34% samples (50891403 out of 56330313)
BOLT-INFO: stale inference matched 74.55% of basic blocks (191295 out of 256589 stale) responsible for 57.30% samples (1288632 out of 2248799 stale)

[Amir]

LGTM.
@maksfb – please take a look if it's fine to add BF Inference stats and methods.

[maksfb]

bolt/include/bolt/Core/BinaryFunction.h

394–403

Let's move the stats out of the BinaryFunction. Once the input function list is populated, function addresses are fixed. You can use a map, e.g., to attach stats to BinaryFunction *. I'm also not sure you need per-function stats or having aggregated is enough.

[spupyrev]

bolt/include/bolt/Core/BinaryFunction.h

394–403

Yes that's what I was thinking on doing. Is there a good example of storing stats or some other info across different passes?

[maksfb]

bolt/include/bolt/Core/BinaryFunction.h

394–403

We don't have a good stats aggregator in BOLT. The easiest way is to create a new class and include its instance in the BC. Another way is to modify the pass manager, which is more involved. Also worth checking what LLVM has implemented.

[spupyrev]

bolt/include/bolt/Core/BinaryFunction.h

394–403

BC seems to already have something similar, e.g., BinaryContext::MissedMacroFusionPairs, although that's not a separate object.
LLVM has ADT/Statistic.h which looks similar but implemented via static variables so some changes would be needed to access the stats in different passes.

I guess the best would be to have a stat wrapper in BC and move existing fields (MissedMacroFusionPairs, MissedMacroFusionExecCount) there?

[spupyrev]

Moving stats from BinaryFunction to (aggregated) BinaryContext

[maksfb]

bolt/include/bolt/Core/BinaryFunction.h

394–403

Sounds reasonable to me.

[maksfb]

bolt/lib/Profile/StaleProfileMatching.cpp

401–402

Now you can pass just the BinaryContext.

[spupyrev]

• wrapping binary stats into a struct;
• printing matching stats based on strong hashes, where we have high confidence in correctness.

[spupyrev]

a typo

[spupyrev]

another typo

[Amir]

bolt/lib/Profile/StaleProfileMatching.cpp

449

But AllInstrHashes is not used in FlowBlock lookup above?

[spupyrev]

Updated the part computing matching metrics to make it more readable. Let me know if there is still confusion.

[maksfb]

LGTM with a couple of nits. Thanks!

bolt/include/bolt/Core/BinaryContext.h

650

654

[spupyrev]

nit

bolt/include/bolt/Core/BinaryContext.h

public:
   uint64_t NumStaleProfileFuncs{0};
 
   /// Number of objects in profile whose profile was ignored.
   uint64_t NumUnusedProfiledObjects{0};
 
   /// Total hotness score according to profiling data for this binary.
   uint64_t TotalScore{0};
 
-  /// Binary-wide stats for macro-fusion.
+  /// Binary-wide aggregated stats.
+  struct BinaryStats {
+    /// Stats for macro-fusion.
     uint64_t MissedMacroFusionPairs{0};
     uint64_t MissedMacroFusionExecCount{0};
 
+    /// Stats for stale profile matching:
+    ///   the total number of basic blocks in the profile
+    uint32_t NumStaleBlocks{0};
+    ///   the number matched basic blocks
+    uint32_t NumMatchedBlocks{0};
+    ///   the total count of samples in the profile
+    uint64_t StaleSampleCount{0};
+    ///   the count matched samples
+    uint64_t MatchedSampleCount{0};
+  } Stats;
+
   // Address of the first allocated segment.
   uint64_t FirstAllocAddress{std::numeric_limits<uint64_t>::max()};
 
   /// Track next available address for new allocatable sections. RewriteInstance
   /// sets this prior to running BOLT passes, so layout passes are aware of the
   /// final addresses functions will have.
   uint64_t LayoutStartAddress{0};
 

bolt/include/bolt/Core/BinaryFunction.h

private:
   SmallPtrSet<BinaryFunction *, 1> Fragments;
 
   /// The profile data for the number of times the function was executed.
   uint64_t ExecutionCount{COUNT_NO_PROFILE};
 
   /// Profile match ratio.
   float ProfileMatchRatio{0.0f};
 
-  /// Raw branch count for this function in the profile
+  /// Raw branch count for this function in the profile.
   uint64_t RawBranchCount{0};
 
   /// Indicates the type of profile the function is using.
   uint16_t ProfileFlags{PF_NONE};
 
   /// True if the function's input profile data has been inaccurate but has
   /// been adjusted by the profile inference algorithm.
   bool HasInferredProfile{false};
 
   /// For functions with mismatched profile we store all call profile
   /// information at a function level (as opposed to tying it to
   /// specific call sites).
   IndirectCallSiteProfile AllCallSites;
 
   /// Score of the function (estimated number of instructions executed,
   /// according to profile data). -1 if the score has not been calculated yet.
   mutable int64_t FunctionScore{-1};
 
   /// Original LSDA address for the function.
   uint64_t LSDAAddress{0};
 
   /// Original LSDA type encoding
   unsigned LSDATypeEncoding{dwarf::DW_EH_PE_omit};
 
   /// Containing compilation unit for the function.
   DWARFUnit *DwarfUnit{nullptr};
 

bolt/lib/Core/BinaryFunction.cpp

for (const BinaryBasicBlock &BB : blocks()) {
     const uint32_t Offset = BC.MIB->getOffsetWithDefault(*std::next(II), 0);
     if (!Offset || (getAddress() + Offset) % 64)
       continue;
 
     LLVM_DEBUG(dbgs() << "\nmissed macro-op fusion at address 0x"
                       << Twine::utohexstr(getAddress() + Offset)
                       << " in function " << *this << "; executed "
                       << BB.getKnownExecutionCount() << " times.\n");
-    ++BC.MissedMacroFusionPairs;
-    BC.MissedMacroFusionExecCount += BB.getKnownExecutionCount();
+    ++BC.Stats.MissedMacroFusionPairs;
+    BC.Stats.MissedMacroFusionExecCount += BB.getKnownExecutionCount();
   }
 }
 
 void BinaryFunction::removeTagsFromProfile() {
   for (BinaryBasicBlock *BB : BasicBlocks) {
     if (BB->ExecutionCount == BinaryBasicBlock::COUNT_NO_PROFILE)
       BB->ExecutionCount = 0;
     for (BinaryBasicBlock::BinaryBranchInfo &BI : BB->branch_info()) {

bolt/lib/Passes/BinaryPasses.cpp

if (NumInferredFunctions) {
     outs() << format("BOLT-INFO: inferred profile for %d (%.2f%% of profiled, "
                      "%.2f%% of stale) functions responsible for %.2f%% samples"
                      " (%zu out of %zu)\n",
                      NumInferredFunctions,
                      100.0 * NumInferredFunctions / NumAllProfiledFunctions,
                      100.0 * NumInferredFunctions / NumAllStaleFunctions,
                      100.0 * InferredSampleCount / TotalSampleCount,
                      InferredSampleCount, TotalSampleCount);
+    outs() << format(
+        "BOLT-INFO: stale inference matched %.2f%% of basic blocks"
+        " (%zu out of %zu stale) responsible for %.2f%% samples"
+        " (%zu out of %zu stale)\n",
+        100.0 * BC.Stats.NumMatchedBlocks / BC.Stats.NumStaleBlocks,
+        BC.Stats.NumMatchedBlocks, BC.Stats.NumStaleBlocks,
+        100.0 * BC.Stats.MatchedSampleCount / BC.Stats.StaleSampleCount,
+        BC.Stats.MatchedSampleCount, BC.Stats.StaleSampleCount);
   }
 
   if (const uint64_t NumUnusedObjects = BC.getNumUnusedProfiledObjects()) {
     outs() << "BOLT-INFO: profile for " << NumUnusedObjects
            << " objects was ignored\n";
   }
 
   if (ProfiledFunctions.size() > 10) {
if (opts::Verbosity >= 1 || BC.TrappedFunctions.size() <= 5) {
       for (const BinaryFunction *Function : BC.TrappedFunctions)
         errs() << "  " << *Function << '\n';
     } else {
       errs() << " Use -v=1 to see the list.\n";
     }
   }
 
   // Print information on missed macro-fusion opportunities seen on input.
-  if (BC.MissedMacroFusionPairs) {
-    outs() << "BOLT-INFO: the input contains " << BC.MissedMacroFusionPairs
-           << " (dynamic count : " << BC.MissedMacroFusionExecCount
-           << ") opportunities for macro-fusion optimization";
+  if (BC.Stats.MissedMacroFusionPairs) {
+    outs() << format("BOLT-INFO: the input contains %zu (dynamic count : %zu)"
+                     " opportunities for macro-fusion optimization",
+                     BC.Stats.MissedMacroFusionPairs,
+                     BC.Stats.MissedMacroFusionExecCount);
     switch (opts::AlignMacroOpFusion) {
     case MFT_NONE:
       outs() << ". Use -align-macro-fusion to fix.\n";
       break;
     case MFT_HOT:
       outs() << ". Will fix instances on a hot path.\n";
       break;
     case MFT_ALL:

bolt/lib/Profile/StaleProfileMatching.cpp

for (size_t I = 0; I < Blocks.size(); I++) {
       uint16_t OpHash = Hashes[I].OpcodeHash;
       OpHashToBlocks[OpHash].push_back(std::make_pair(Hashes[I], Block));
     }
   }
 
   /// Find the most similar block for a given hash.
   const FlowBlock *matchBlock(BlendedBlockHash BlendedHash) const {
     auto BlockIt = OpHashToBlocks.find(BlendedHash.OpcodeHash);
-    if (BlockIt == OpHashToBlocks.end()) {
+    if (BlockIt == OpHashToBlocks.end())
       return nullptr;
-    }
     FlowBlock *BestBlock = nullptr;
     uint64_t BestDist = std::numeric_limits<uint64_t>::max();
-    for (auto It : BlockIt->second) {
-      FlowBlock *Block = It.second;
-      BlendedBlockHash Hash = It.first;
+    for (const auto &[Hash, Block] : BlockIt->second) {
       uint64_t Dist = Hash.distance(BlendedHash);
       if (BestBlock == nullptr || Dist < BestDist) {
         BestDist = Dist;
         BestBlock = Block;
       }
     }
     return BestBlock;
   }
 
+  /// Returns true if the two basic blocks (in the binary and in the profile)
+  /// corresponding to the given hashes are matched to each other with a high
+  /// confidence.
+  static bool isHighConfidenceMatch(BlendedBlockHash Hash1,
+                                    BlendedBlockHash Hash2) {
+    return Hash1.InstrHash == Hash2.InstrHash;
+  }
+
 private:
   using HashBlockPairType = std::pair<BlendedBlockHash, FlowBlock *>;
   std::unordered_map<uint16_t, std::vector<HashBlockPairType>> OpHashToBlocks;
 };
 
 void BinaryFunction::computeBlockHashes() const {
   if (size() == 0)
     return;

 /// is to extract as much information from the stale profile as possible. Here
 /// we assume that each basic block is specified via a hash value computed from
 /// its content and the hashes of the unchanged basic blocks stay the same
 /// across different revisions of the binary.
 /// Whenever there is a count in the profile with the hash corresponding to one
 /// of the basic blocks in the binary, the count is "matched" to the block.
 /// Similarly, if both the source and the target of a count in the profile are
 /// matched to a jump in the binary, the count is recorded in CFG.
-void matchWeightsByHashes(const BinaryFunction::BasicBlockOrderType &BlockOrder,
+void matchWeightsByHashes(BinaryContext &BC,
+                          const BinaryFunction::BasicBlockOrderType &BlockOrder,
                           const yaml::bolt::BinaryFunctionProfile &YamlBF,
                           FlowFunction &Func) {
   assert(Func.Blocks.size() == BlockOrder.size() + 1);
 
   std::vector<FlowBlock *> Blocks;
   std::vector<BlendedBlockHash> BlendedHashes;
   for (uint64_t I = 0; I < BlockOrder.size(); I++) {
     const BinaryBasicBlock *BB = BlockOrder[I];
     assert(BB->getHash() != 0 && "empty hash of BinaryBasicBlock");
     Blocks.push_back(&Func.Blocks[I + 1]);
     BlendedBlockHash BlendedHash(BB->getHash());
     BlendedHashes.push_back(BlendedHash);
     LLVM_DEBUG(dbgs() << "BB with index " << I << " has hash = "
                       << Twine::utohexstr(BB->getHash()) << "\n");
   }
   StaleMatcher Matcher;
   Matcher.init(Blocks, BlendedHashes);
 
   // Index in yaml profile => corresponding (matched) block
   DenseMap<uint64_t, const FlowBlock *> MatchedBlocks;
   // Match blocks from the profile to the blocks in CFG
   for (const yaml::bolt::BinaryBasicBlockProfile &YamlBB : YamlBF.Blocks) {
     assert(YamlBB.Hash != 0 && "empty hash of BinaryBasicBlockProfile");
-    BlendedBlockHash BlendedHash(YamlBB.Hash);
-    const FlowBlock *MatchedBlock = Matcher.matchBlock(BlendedHash);
+    BlendedBlockHash YamlHash(YamlBB.Hash);
+    const FlowBlock *MatchedBlock = Matcher.matchBlock(YamlHash);
     if (MatchedBlock != nullptr) {
       MatchedBlocks[YamlBB.Index] = MatchedBlock;
       LLVM_DEBUG(dbgs() << "Matched yaml block with bid = " << YamlBB.Index
                         << " and hash = " << Twine::utohexstr(YamlBB.Hash)
                         << " to BB with index = " << MatchedBlock->Index - 1
                         << "\n");
+      // Update matching stats accounting for the matched block.
+      BlendedBlockHash BinHash = BlendedHashes[MatchedBlock->Index - 1];
+      if (Matcher.isHighConfidenceMatch(BinHash, YamlHash)) {
+        ++BC.Stats.NumMatchedBlocks;
+        BC.Stats.MatchedSampleCount += YamlBB.ExecCount;
+      }
     } else {
       LLVM_DEBUG(
           dbgs() << "Couldn't match yaml block with bid = " << YamlBB.Index
                  << " and hash = " << Twine::utohexstr(YamlBB.Hash) << "\n");
     }
+
+    // Update matching stats.
+    ++BC.Stats.NumStaleBlocks;
+    BC.Stats.StaleSampleCount += YamlBB.ExecCount;
   }
 
   // Match jumps from the profile to the jumps from CFG
   std::vector<uint64_t> OutWeight(Func.Blocks.size(), 0);
   std::vector<uint64_t> InWeight(Func.Blocks.size(), 0);
   for (const yaml::bolt::BinaryBasicBlockProfile &YamlBB : YamlBF.Blocks) {
     for (const yaml::bolt::SuccessorInfo &YamlSI : YamlBB.Successors) {
       if (YamlSI.Count == 0)
         continue;
for (const yaml::bolt::SuccessorInfo &YamlSI : YamlBB.Successors) {
       if (MatchedDstBlock != nullptr)
         InWeight[MatchedDstBlock->Index] += YamlSI.Count;
     }
   }
 
   // Assign block counts based on in-/out- jumps
   for (FlowBlock &Block : Func.Blocks) {
     if (OutWeight[Block.Index] == 0 && InWeight[Block.Index] == 0) {
-      assert(Block.HasUnknownWeight && "unmatched block with positive count");
+      assert(Block.HasUnknownWeight && "unmatched block with a positive count");
       continue;
     }
     Block.HasUnknownWeight = false;
     Block.Weight = std::max(OutWeight[Block.Index], InWeight[Block.Index]);
   }
 }
 
 /// The function finds all blocks that are (i) reachable from the Entry block
bool YAMLProfileReader::inferStaleProfile(
 
   const BinaryFunction::BasicBlockOrderType BlockOrder(
       BF.getLayout().block_begin(), BF.getLayout().block_end());
 
   // Create a wrapper flow function to use with the profile inference algorithm
   FlowFunction Func = createFlowFunction(BlockOrder);
 
   // Match as many block/jump counts from the stale profile as possible
-  matchWeightsByHashes(BlockOrder, YamlBF, Func);
+  matchWeightsByHashes(BF.getBinaryContext(), BlockOrder, YamlBF, Func);
 
   // Adjust the flow function by marking unreachable blocks Unlikely so that
   // they don't get any counts assigned
   preprocessUnreachableBlocks(Func);
 
   // Check if profile inference can be applied for the instance
   if (!canApplyInference(Func))
     return false;