[Debugify] Export per-pass debug info loss statistics

[vsk]

Summary

Add a -debugify-export option to opt. This exports per-pass debugify
loss statistics to a file in CSV format.

Here is sample output from running opt -O2 on the amalgamated sqlite3 sources, exported from Numbers:

sqlite3.diloss.pdf34 KBDownload

.

[aprantl]

This is definitely going to be very useful! It's not very large, but generally I wonder if llvm-developer-centric features like this should be made #ifndef NDEBUG-only to not weigh down clang releases' binary size?

[vsk]

In D49003#1153875, @aprantl wrote:

This is definitely going to be very useful! It's not very large, but generally I wonder if llvm-developer-centric features like this should be made #ifndef NDEBUG-only to not weigh down clang releases' binary size?

I think we'd get much more space savings per unit of effort by not shipping these 5 binaries (over 100 MB): http://lists.llvm.org/pipermail/llvm-dev/2018-May/123310.html. I'll get around to that one of these days .. :). I'd rather not pepper NDEBUG around opt for more marginal savings.

[gbedwell]

This is really nice. I agree it will be really useful, albeit with a minor concern about false positives in the stats themselves due to DCE transforms like what we ran into in https://llvm.org/PR37942 .

On some of the codebases I've tried, the warnings can be a bit noisy (and makes attempting to do any form of automatic testcase reduction based on their presence very difficult). For example, in my testing with this patch I can see that Dead Store Elimination is generating some missing values and locations in a few testcases. In every one I've looked at so far, these numbers relate to eliminated dead stores :). Similarly, we don't know how many of the large instcombine number in the above PDF is down to DCE and how much is down to genuine DI loss. We've seen cases of both, but I'm not sure of the ratio. Maybe a compelling argument for taking some approach along the lines of the suggested one of attaching undef dbg.values during DCE?

tools/opt/Debugify.cpp

402 ↗

(On Diff #154341)

prefix this with something like "could not open file: "?

[vsk]

At a high-level is it fine to use CSV here? I've found it really convenient because Google Sheets, Numbers, python scripts etc. can ingest the data easily.

In D49003#1154445, @gbedwell wrote:

This is really nice. I agree it will be really useful, albeit with a minor concern about false positives in the stats themselves due to DCE transforms like what we ran into in https://llvm.org/PR37942 .

Taken individually these reports won't be very useful. It gives us a sense of which mid-level passes drop the most debug info, but the results aren't particularly surprising. I think the real signal will come from monitoring loss stats over time on fixed inputs. That should tell us which areas of the compiler to focus on, and which areas are improving/regressing.

On some of the codebases I've tried, the warnings can be a bit noisy (and makes attempting to do any form of automatic testcase reduction based on their presence very difficult). For example, in my testing with this patch I can see that Dead Store Elimination is generating some missing values and locations in a few testcases. In every one I've looked at so far, these numbers relate to eliminated dead stores :). Similarly, we don't know how many of the large instcombine number in the above PDF is down to DCE and how much is down to genuine DI loss. We've seen cases of both, but I'm not sure of the ratio.

Right, each issue needs to be looked at individually. Even in cases where a pass is doing straight DCE, it's sometimes possible to preserve debug values by rewriting instruction effects as DIExpressions. The exported stats won't precisely signal how many bugs there are to fix.

Maybe a compelling argument for taking some approach along the lines of the suggested one of attaching undef dbg.values during DCE?

I'm not sure this is the right tradeoff between improved stats tracking and compile-time overhead.

tools/opt/Debugify.cpp

402 ↗

(On Diff #154341)

Right, will do.

[gbedwell]

In D49003#1154631, @vsk wrote:

At a high-level is it fine to use CSV here? I've found it really convenient because Google Sheets, Numbers, python scripts etc. can ingest the data easily.

It works for me personally as we have plenty of tools and scripts internally that can easily operate on CSVs for tracking and graphing. If the plan is to monitor loss stats over time, would we want to integrate it into LNT or similar for providing continuous results on an upstream bot? I'm not sure what works best for that use-case if that's the direction we want to go in.

Maybe a compelling argument for taking some approach along the lines of the suggested one of attaching undef dbg.values during DCE?

I'm not sure this is the right tradeoff between improved stats tracking and compile-time overhead.

I agree, although I am still concerned that we lose a lot of the value of debugify tracking through false positives. If anything, it would have to be on a flag, but that comes with its own set of tradeoffs in terms of the additional code-complexity that it would create and the fact we'd be testing different code paths compared to what our users are actually using, which is never ideal.

[vsk]

Ping.

[gbedwell]

Modulo my nit above about the error message text, this LGTM.

llvm/trunk/test/DebugInfo/debugify-export.ll

+; RUN: opt < %s -debugify-each -debugify-quiet -debugify-export - -o /dev/null | FileCheck %s
+
+; CHECK: Pass Name
+; CHECK-SAME: # of missing debug values
+; CHECK-SAME: # of missing locations
+; CHECK-SAME: Missing/Expected value ratio
+; CHECK-SAME: Missing/Expected location ratio
+
+; CHECK: Module Verifier
+; CHECK-SAME: 0,0,0.000000e+00,0.000000e+00
+
+define void @foo() {
+  ret void
+}

llvm/trunk/tools/opt/Debugify.h

 //===- Debugify.h - Attach synthetic debug info to everything -------------===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 ///
 /// \file Interface to the `debugify` synthetic debug info testing utility.
 ///
 //===----------------------------------------------------------------------===//
 
 #ifndef LLVM_TOOLS_OPT_DEBUGIFY_H
 #define LLVM_TOOLS_OPT_DEBUGIFY_H
 
+#include "llvm/ADT/StringRef.h"
+#include "llvm/ADT/MapVector.h"
 #include "llvm/IR/PassManager.h"
+#include "llvm/Support/raw_ostream.h"
 
 llvm::ModulePass *createDebugifyModulePass();
 llvm::FunctionPass *createDebugifyFunctionPass();
 
 struct NewPMDebugifyPass : public llvm::PassInfoMixin<NewPMDebugifyPass> {
   llvm::PreservedAnalyses run(llvm::Module &M, llvm::ModuleAnalysisManager &AM);
 };
 
+/// Track how much `debugify` information has been lost.
+struct DebugifyStatistics {
+  /// Number of missing dbg.values.
+  unsigned NumDbgValuesMissing = 0;
+
+  /// Number of dbg.values expected.
+  unsigned NumDbgValuesExpected = 0;
+
+  /// Number of instructions with empty debug locations.
+  unsigned NumDbgLocsMissing = 0;
+
+  /// Number of instructions expected to have debug locations.
+  unsigned NumDbgLocsExpected = 0;
+
+  /// Get the ratio of missing/expected dbg.values.
+  float getMissingValueRatio() const {
+    return float(NumDbgValuesMissing) / float(NumDbgLocsExpected);
+  }
+
+  /// Get the ratio of missing/expected instructions with locations.
+  float getEmptyLocationRatio() const {
+    return float(NumDbgLocsMissing) / float(NumDbgLocsExpected);
+  }
+};
+
+/// Map pass names to a per-pass DebugifyStatistics instance.
+using DebugifyStatsMap = llvm::MapVector<llvm::StringRef, DebugifyStatistics>;
+
+/// Export per-pass debugify statistics to the file specified by \p Path.
+void exportDebugifyStats(llvm::StringRef Path, const DebugifyStatsMap &Map);
+
 llvm::ModulePass *
 createCheckDebugifyModulePass(bool Strip = false,
-                              llvm::StringRef NameOfWrappedPass = "");
+                              llvm::StringRef NameOfWrappedPass = "",
+                              DebugifyStatsMap *StatsMap = nullptr);
 
 llvm::FunctionPass *
 createCheckDebugifyFunctionPass(bool Strip = false,
-                                llvm::StringRef NameOfWrappedPass = "");
+                                llvm::StringRef NameOfWrappedPass = "",
+                                DebugifyStatsMap *StatsMap = nullptr);
 
 struct NewPMCheckDebugifyPass
     : public llvm::PassInfoMixin<NewPMCheckDebugifyPass> {
   llvm::PreservedAnalyses run(llvm::Module &M, llvm::ModuleAnalysisManager &AM);
 };
 
 #endif // LLVM_TOOLS_OPT_DEBUGIFY_H

llvm/trunk/tools/opt/Debugify.cpp

if (HasBadSize) {
     dbg() << "\n";
   }
   return HasBadSize;
 }
 
 bool checkDebugifyMetadata(Module &M,
                            iterator_range<Module::iterator> Functions,
                            StringRef NameOfWrappedPass, StringRef Banner,
-                           bool Strip) {
+                           bool Strip, DebugifyStatsMap *StatsMap) {
   // Skip modules without debugify metadata.
   NamedMDNode *NMD = M.getNamedMetadata("llvm.debugify");
   if (!NMD) {
     dbg() << Banner << "Skipping module without debugify metadata\n";
     return false;
   }
 
   auto getDebugifyOperand = [&](unsigned Idx) -> unsigned {
     return mdconst::extract<ConstantInt>(NMD->getOperand(Idx)->getOperand(0))
         ->getZExtValue();
   };
   assert(NMD->getNumOperands() == 2 &&
          "llvm.debugify should have exactly 2 operands!");
   unsigned OriginalNumLines = getDebugifyOperand(0);
   unsigned OriginalNumVars = getDebugifyOperand(1);
   bool HasErrors = false;
 
+  // Track debug info loss statistics if able.
+  DebugifyStatistics *Stats = nullptr;
+  if (StatsMap && !NameOfWrappedPass.empty())
+    Stats = &StatsMap->operator[](NameOfWrappedPass);
+
   BitVector MissingLines{OriginalNumLines, true};
   BitVector MissingVars{OriginalNumVars, true};
   for (Function &F : Functions) {
     if (isFunctionSkipped(F))
       continue;
 
     // Find missing lines.
     for (Instruction &I : instructions(F)) {
bool checkDebugifyMetadata(Module &M,
 
   // Print the results.
   for (unsigned Idx : MissingLines.set_bits())
     dbg() << "WARNING: Missing line " << Idx + 1 << "\n";
 
   for (unsigned Idx : MissingVars.set_bits())
     dbg() << "WARNING: Missing variable " << Idx + 1 << "\n";
 
+  // Update DI loss statistics.
+  if (Stats) {
+    Stats->NumDbgLocsExpected += OriginalNumLines;
+    Stats->NumDbgLocsMissing += MissingLines.count();
+    Stats->NumDbgValuesExpected += OriginalNumVars;
+    Stats->NumDbgValuesMissing += MissingVars.count();
+  }
+
   dbg() << Banner;
   if (!NameOfWrappedPass.empty())
     dbg() << " [" << NameOfWrappedPass << "]";
   dbg() << ": " << (HasErrors ? "FAIL" : "PASS") << '\n';
 
   // Strip the Debugify Metadata if required.
   if (Strip) {
     StripDebugInfo(M);
struct DebugifyFunctionPass : public FunctionPass {
   static char ID; // Pass identification.
 };
 
 /// ModulePass for checking debug info inserted by -debugify, used with the
 /// legacy module pass manager.
 struct CheckDebugifyModulePass : public ModulePass {
   bool runOnModule(Module &M) override {
     return checkDebugifyMetadata(M, M.functions(), NameOfWrappedPass,
-                                 "CheckModuleDebugify", Strip);
+                                 "CheckModuleDebugify", Strip, StatsMap);
   }
 
-  CheckDebugifyModulePass(bool Strip = false, StringRef NameOfWrappedPass = "")
-      : ModulePass(ID), Strip(Strip), NameOfWrappedPass(NameOfWrappedPass) {}
+  CheckDebugifyModulePass(bool Strip = false, StringRef NameOfWrappedPass = "",
+                          DebugifyStatsMap *StatsMap = nullptr)
+      : ModulePass(ID), Strip(Strip), NameOfWrappedPass(NameOfWrappedPass),
+        StatsMap(StatsMap) {}
 
   void getAnalysisUsage(AnalysisUsage &AU) const override {
     AU.setPreservesAll();
   }
 
   static char ID; // Pass identification.
 
 private:
   bool Strip;
   StringRef NameOfWrappedPass;
+  DebugifyStatsMap *StatsMap;
 };
 
 /// FunctionPass for checking debug info inserted by -debugify-function, used
 /// with the legacy module pass manager.
 struct CheckDebugifyFunctionPass : public FunctionPass {
   bool runOnFunction(Function &F) override {
     Module &M = *F.getParent();
     auto FuncIt = F.getIterator();
     return checkDebugifyMetadata(M, make_range(FuncIt, std::next(FuncIt)),
                                  NameOfWrappedPass, "CheckFunctionDebugify",
-                                 Strip);
+                                 Strip, StatsMap);
   }
 
   CheckDebugifyFunctionPass(bool Strip = false,
-                            StringRef NameOfWrappedPass = "")
-      : FunctionPass(ID), Strip(Strip), NameOfWrappedPass(NameOfWrappedPass) {}
+                            StringRef NameOfWrappedPass = "",
+                            DebugifyStatsMap *StatsMap = nullptr)
+      : FunctionPass(ID), Strip(Strip), NameOfWrappedPass(NameOfWrappedPass),
+        StatsMap(StatsMap) {}
 
   void getAnalysisUsage(AnalysisUsage &AU) const override {
     AU.setPreservesAll();
   }
 
   static char ID; // Pass identification.
 
 private:
   bool Strip;
   StringRef NameOfWrappedPass;
+  DebugifyStatsMap *StatsMap;
 };
 
 } // end anonymous namespace
 
+void exportDebugifyStats(llvm::StringRef Path, const DebugifyStatsMap &Map) {
+  std::error_code EC;
+  raw_fd_ostream OS{Path, EC};
+  if (EC) {
+    errs() << "Could not open file: " << EC.message() << ", " << Path << '\n';
+    return;
+  }
+
+  OS << "Pass Name" << ',' << "# of missing debug values" << ','
+     << "# of missing locations" << ',' << "Missing/Expected value ratio" << ','
+     << "Missing/Expected location ratio" << '\n';
+  for (const auto &Entry : Map) {
+    StringRef Pass = Entry.first;
+    DebugifyStatistics Stats = Entry.second;
+
+    OS << Pass << ',' << Stats.NumDbgValuesMissing << ','
+       << Stats.NumDbgLocsMissing << ',' << Stats.getMissingValueRatio() << ','
+       << Stats.getEmptyLocationRatio() << '\n';
+  }
+}
+
 ModulePass *createDebugifyModulePass() { return new DebugifyModulePass(); }
 
 FunctionPass *createDebugifyFunctionPass() {
   return new DebugifyFunctionPass();
 }
 
 PreservedAnalyses NewPMDebugifyPass::run(Module &M, ModuleAnalysisManager &) {
   applyDebugifyMetadata(M, M.functions(), "ModuleDebugify: ");
   return PreservedAnalyses::all();
 }
 
 ModulePass *createCheckDebugifyModulePass(bool Strip,
-                                          StringRef NameOfWrappedPass) {
-  return new CheckDebugifyModulePass(Strip, NameOfWrappedPass);
+                                          StringRef NameOfWrappedPass,
+                                          DebugifyStatsMap *StatsMap) {
+  return new CheckDebugifyModulePass(Strip, NameOfWrappedPass, StatsMap);
 }
 
 FunctionPass *createCheckDebugifyFunctionPass(bool Strip,
-                                              StringRef NameOfWrappedPass) {
-  return new CheckDebugifyFunctionPass(Strip, NameOfWrappedPass);
+                                              StringRef NameOfWrappedPass,
+                                              DebugifyStatsMap *StatsMap) {
+  return new CheckDebugifyFunctionPass(Strip, NameOfWrappedPass, StatsMap);
 }
 
 PreservedAnalyses NewPMCheckDebugifyPass::run(Module &M,
                                               ModuleAnalysisManager &) {
-  checkDebugifyMetadata(M, M.functions(), "", "CheckModuleDebugify", false);
+  checkDebugifyMetadata(M, M.functions(), "", "CheckModuleDebugify", false,
+                        nullptr);
   return PreservedAnalyses::all();
 }
 
 char DebugifyModulePass::ID = 0;
 static RegisterPass<DebugifyModulePass> DM("debugify",
                                            "Attach debug info to everything");
 
 char CheckDebugifyModulePass::ID = 0;

llvm/trunk/tools/opt/opt.cpp

static cl::opt<bool> EnableDebugify(
     cl::desc(
         "Start the pipeline with debugify and end it with check-debugify"));
 
 static cl::opt<bool> DebugifyEach(
     "debugify-each",
     cl::desc(
         "Start each pass with debugify and end it with check-debugify"));
 
+static cl::opt<std::string>
+    DebugifyExport("debugify-export",
+                   cl::desc("Export per-pass debugify statistics to this file"),
+                   cl::value_desc("filename"), cl::init(""));
+
 static cl::opt<bool>
 PrintBreakpoints("print-breakpoints-for-testing",
                  cl::desc("Print select breakpoints location for testing"));
 
 static cl::opt<std::string> ClDataLayout("data-layout",
                                          cl::desc("data layout string to use"),
                                          cl::value_desc("layout-string"),
                                          cl::init(""));
static cl::opt<unsigned> PassRemarksHotnessThreshold(
     cl::Hidden);
 
 static cl::opt<std::string>
     RemarksFilename("pass-remarks-output",
                     cl::desc("YAML output filename for pass remarks"),
                     cl::value_desc("filename"));
 
 class OptCustomPassManager : public legacy::PassManager {
+  DebugifyStatsMap DIStatsMap;
+
 public:
   using super = legacy::PassManager;
 
   void add(Pass *P) override {
+    // Wrap each pass with (-check)-debugify passes if requested, making
+    // exceptions for passes which shouldn't see -debugify instrumentation.
     bool WrapWithDebugify = DebugifyEach && !P->getAsImmutablePass() &&
                             !isIRPrintingPass(P) && !isBitcodeWriterPass(P);
     if (!WrapWithDebugify) {
       super::add(P);
       return;
     }
+
+    // Apply -debugify/-check-debugify before/after each pass and collect
+    // debug info loss statistics.
     PassKind Kind = P->getPassKind();
+    StringRef Name = P->getPassName();
+
     // TODO: Implement Debugify for BasicBlockPass, LoopPass.
     switch (Kind) {
       case PT_Function:
         super::add(createDebugifyFunctionPass());
         super::add(P);
-        super::add(createCheckDebugifyFunctionPass(true, P->getPassName()));
+        super::add(createCheckDebugifyFunctionPass(true, Name, &DIStatsMap));
         break;
       case PT_Module:
         super::add(createDebugifyModulePass());
         super::add(P);
-        super::add(createCheckDebugifyModulePass(true, P->getPassName()));
+        super::add(createCheckDebugifyModulePass(true, Name, &DIStatsMap));
         break;
       default:
         super::add(P);
         break;
     }
   }
+
+  const DebugifyStatsMap &getDebugifyStatsMap() const { return DIStatsMap; }
 };
 
 static inline void addPass(legacy::PassManagerBase &PM, Pass *P) {
   // Add the pass to the pass manager...
   PM.add(P);
 
   // If we are verifying all of the intermediate steps, add the verifier...
   if (VerifyEach)
if (Buffer.size() != FirstRunBuffer.size() ||
       Out->keep();
       if (OptRemarkFile)
         OptRemarkFile->keep();
       return 1;
     }
     Out->os() << BOS->str();
   }
 
+  if (DebugifyEach && !DebugifyExport.empty())
+    exportDebugifyStats(DebugifyExport, Passes.getDebugifyStatsMap());
+
   // Declare success.
   if (!NoOutput || PrintBreakpoints)
     Out->keep();
 
   if (OptRemarkFile)
     OptRemarkFile->keep();
 
   if (ThinLinkOut)
     ThinLinkOut->keep();
 
   return 0;
 }