[Reproducers] Add more logging capabilities to reproducer instrumentation

[JDevlieghere]

Summary

Debugging issues with instrumentation capture and replay can be particularly tricky, especially because part of the process takes places even before the debugger is initialized. This patch adds more logging capabilities to these classes, hidden behind a macro define.

[aprantl]

lldb/include/lldb/Utility/ReproducerInstrumentation.h

591 ↗

(On Diff #188017)

Who defines this macro? I'm asking because it's unusual for LLDB to emit anything on stderr.

[labath]

The overall idea seems fine to me, though I think it would be better to keep the macros simpler by moving all of the logic into the single Register call. I.e. the Register function would take extra StringRef arguments, which the macros would fill out. Then you could store the computed signature in the (possibly renamed) m_ids map, instead of having two maps with the same set of keys. That should save some space too.

lldb/include/lldb/Utility/ReproducerInstrumentation.h

591 ↗

(On Diff #188017)

I'm guessing it's the kind of thing you define by editing the source/cmake config, when you're really desperate to figure out what's going wrong.

[JDevlieghere]

Simplify record function

[JDevlieghere]

lldb/include/lldb/Utility/ReproducerInstrumentation.h

591 ↗

(On Diff #188017)

Correct, see the #define on line 24. I'll comment it out before landing of course.

include/lldb/Utility/ReproducerInstrumentation.h

 #include "lldb/Utility/Logging.h"
 
 #include "llvm/ADT/DenseMap.h"
 #include "llvm/ADT/StringRef.h"
 #include "llvm/Support/ErrorHandling.h"
 
 #include <map>
 
+// Define LLDB_REPRO_INSTR_TRACE to trace to stderr instead of LLDB's log
+// infrastructure. This is useful when you need to see traces before the logger
+// is initialized or enabled.
+#define LLDB_REPRO_INSTR_TRACE
+
 #define LLDB_REGISTER_CONSTRUCTOR(Class, Signature)                            \
-  Register<Class * Signature>(&construct<Class Signature>::doit)
+  Register<Class * Signature>(&construct<Class Signature>::doit, "", #Class,   \
+                              #Class, #Signature)
 #define LLDB_REGISTER_METHOD(Result, Class, Method, Signature)                 \
-  Register(&invoke<Result(Class::*) Signature>::method<&Class::Method>::doit)
+  Register(&invoke<Result(Class::*) Signature>::method<&Class::Method>::doit,  \
+           #Result, #Class, #Method, #Signature)
 #define LLDB_REGISTER_METHOD_CONST(Result, Class, Method, Signature)           \
   Register(&invoke<Result(Class::*)                                            \
-                       Signature const>::method_const<&Class::Method>::doit)
+                       Signature const>::method_const<&Class::Method>::doit,   \
+           #Result, #Class, #Method, #Signature)
 #define LLDB_REGISTER_STATIC_METHOD(Result, Class, Method, Signature)          \
-  Register<Result Signature>(static_cast<Result(*) Signature>(&Class::Method))
+  Register<Result Signature>(static_cast<Result(*) Signature>(&Class::Method), \
+                             #Result, #Class, #Method, #Signature)
 
 #define LLDB_RECORD_CONSTRUCTOR(Class, Signature, ...)                         \
   LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0}",                   \
            LLVM_PRETTY_FUNCTION);                                              \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
     lldb_private::repro::Recorder sb_recorder(                                 \
         data.GetSerializer(), data.GetRegistry(), LLVM_PRETTY_FUNCTION);       \

 public:
   Deserializer(llvm::StringRef buffer) : m_buffer(buffer) {}
 
   /// Returns true when the buffer has unread data.
   bool HasData(unsigned size) { return size <= m_buffer.size(); }
 
   /// Deserialize and interpret value as T.
   template <typename T> T Deserialize() {
+#ifdef LLDB_REPRO_INSTR_TRACE
+    llvm::errs() << "Deserializing with " << LLVM_PRETTY_FUNCTION << "\n";
+#endif
     return Read<T>(typename serializer_tag<T>::type());
   }
 
   /// Store the returned value in the index-to-object mapping.
   template <typename T> void HandleReplayResult(const T &t) {
     unsigned result = Deserialize<unsigned>();
     if (std::is_fundamental<T>::value)
       return;
struct DefaultReplayer<void(Args...)> : public Replayer {
 
   void (*f)(Args...);
 };
 
 /// The registry contains a unique mapping between functions and their ID. The
 /// IDs can be serialized and deserialized to replay a function. Functions need
 /// to be registered with the registry for this to work.
 class Registry {
+private:
+  struct SignatureStr {
+    SignatureStr(llvm::StringRef result = {}, llvm::StringRef scope = {},
+                 llvm::StringRef name = {}, llvm::StringRef args = {})
+        : result(result), scope(scope), name(name), args(args) {}
+
+    std::string ToString() const;
+
+    llvm::StringRef result;
+    llvm::StringRef scope;
+    llvm::StringRef name;
+    llvm::StringRef args;
+  };
+
 public:
   Registry() = default;
   virtual ~Registry() = default;
 
   /// Register a default replayer for a function.
-  template <typename Signature> void Register(Signature *f) {
-    DoRegister(uintptr_t(f), llvm::make_unique<DefaultReplayer<Signature>>(f));
+  template <typename Signature>
+  void Register(Signature *f, llvm::StringRef result = {},
+                llvm::StringRef scope = {}, llvm::StringRef name = {},
+                llvm::StringRef args = {}) {
+    DoRegister(uintptr_t(f), llvm::make_unique<DefaultReplayer<Signature>>(f),
+               SignatureStr(result, scope, name, args));
   }
 
   /// Register a replayer that invokes a custom function with the same
   /// signature as the replayed function.
-  template <typename Signature> void Register(Signature *f, Signature *g) {
-    DoRegister(uintptr_t(f), llvm::make_unique<DefaultReplayer<Signature>>(g));
+  template <typename Signature>
+  void Register(Signature *f, Signature *g, llvm::StringRef result = {},
+                llvm::StringRef scope = {}, llvm::StringRef name = {},
+                llvm::StringRef args = {}) {
+    DoRegister(uintptr_t(f), llvm::make_unique<DefaultReplayer<Signature>>(g),
+               SignatureStr(result, scope, name, args));
   }
 
   /// Replay functions from a file.
   bool Replay(const FileSpec &file);
 
   /// Replay functions from a buffer.
   bool Replay(llvm::StringRef buffer);
 
   /// Returns the ID for a given function address.
   unsigned GetID(uintptr_t addr);
 
 protected:
   /// Register the given replayer for a function (and the ID mapping).
-  void DoRegister(uintptr_t RunID, std::unique_ptr<Replayer> replayer);
+  void DoRegister(uintptr_t RunID, std::unique_ptr<Replayer> replayer,
+                  SignatureStr signature);
 
 private:
+  std::string GetSignature(unsigned id);
+  Replayer *GetReplayer(unsigned id);
+
   /// Mapping of function addresses to replayers and their ID.
   std::map<uintptr_t, std::pair<std::unique_ptr<Replayer>, unsigned>>
       m_replayers;
 
   /// Mapping of IDs to replayer instances.
-  std::map<unsigned, Replayer *> m_ids;
+  std::map<unsigned, std::pair<Replayer *, SignatureStr>> m_ids;
 };
 
 /// To be used as the "Runtime ID" of a constructor. It also invokes the
 /// constructor when called.
 template <typename Signature> struct construct;
 template <typename Class, typename... Args> struct construct<Class(Args...)> {
   static Class *doit(Args... args) { return new Class(args...); }
 };
public:
   /// Records a single function call.
   template <typename Result, typename... FArgs, typename... RArgs>
   void Record(Result (*f)(FArgs...), const RArgs &... args) {
     if (!ShouldCapture())
       return;
 
     unsigned id = m_registry.GetID(uintptr_t(f));
 
-    LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "Recording ({0}) '{1}'",
+#ifndef LLDB_REPRO_INSTR_TRACE
+    LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "Recording {0}: {1}",
              id, m_pretty_func);
+#else
+    llvm::errs() << "Recording " << id << ": " << m_pretty_func << "\n";
+#endif
 
     m_serializer.SerializeAll(id);
     m_serializer.SerializeAll(args...);
 
     if (std::is_class<typename std::remove_pointer<
             typename std::remove_reference<Result>::type>::type>::value) {
       m_result_recorded = false;
     } else {
       m_serializer.SerializeAll(0);
       m_result_recorded = true;
     }
   }
 
   /// Records a single function call.
   template <typename... Args>
   void Record(void (*f)(Args...), const Args &... args) {
     if (!ShouldCapture())
       return;
 
     unsigned id = m_registry.GetID(uintptr_t(f));
 
-    LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "Recording ({0}) '{1}'",
+#ifndef LLDB_REPRO_INSTR_TRACE
+    LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "Recording {0}: {1}",
              id, m_pretty_func);
+#else
+    llvm::errs() << "Recording " << id << ": " << m_pretty_func << "\n";
+#endif
 
     m_serializer.SerializeAll(id);
     m_serializer.SerializeAll(args...);
 
     // Record result.
     m_serializer.SerializeAll(0);
     m_result_recorded = true;
   }

source/Utility/ReproducerInstrumentation.cpp

bool Registry::Replay(const FileSpec &file) {
   auto error_or_file = llvm::MemoryBuffer::getFile(file.GetPath());
   if (auto err = error_or_file.getError())
     return false;
 
   return Replay((*error_or_file)->getBuffer());
 }
 
 bool Registry::Replay(llvm::StringRef buffer) {
+#ifndef LLDB_REPRO_INSTR_TRACE
   Log *log = GetLogIfAllCategoriesSet(LIBLLDB_LOG_API);
+#endif
 
   Deserializer deserializer(buffer);
   while (deserializer.HasData(1)) {
     unsigned id = deserializer.Deserialize<unsigned>();
-    LLDB_LOG(log, "Replaying function #{0}", id);
-    m_ids[id]->operator()(deserializer);
+
+#ifndef LLDB_REPRO_INSTR_TRACE
+    LLDB_LOG(log, "Replaying {0}: {1}", id, GetSignature(id));
+#else
+    llvm::errs() << "Replaying " << id << ": " << GetSignature(id) << "\n";
+#endif
+
+    GetReplayer(id)->operator()(deserializer);
   }
 
   return true;
 }
 
-void Registry::DoRegister(uintptr_t RunID, std::unique_ptr<Replayer> replayer) {
+void Registry::DoRegister(uintptr_t RunID, std::unique_ptr<Replayer> replayer,
+                          SignatureStr signature) {
   const unsigned id = m_replayers.size() + 1;
   assert(m_replayers.find(RunID) == m_replayers.end());
   m_replayers[RunID] = std::make_pair(std::move(replayer), id);
-  m_ids[id] = m_replayers[RunID].first.get();
+  m_ids[id] =
+      std::make_pair(m_replayers[RunID].first.get(), std::move(signature));
 }
 
 unsigned Registry::GetID(uintptr_t addr) {
   unsigned id = m_replayers[addr].second;
   assert(id != 0 && "Forgot to add function to registry?");
   return id;
 }
 
+std::string Registry::GetSignature(unsigned id) {
+  assert(m_ids.count(id) != 0 && "ID not in registry");
+  return m_ids[id].second.ToString();
+}
+
+Replayer *Registry::GetReplayer(unsigned id) {
+  assert(m_ids.count(id) != 0 && "ID not in registry");
+  return m_ids[id].first;
+}
+
+std::string Registry::SignatureStr::ToString() const {
+  return (result + (result.empty() ? "" : " ") + scope + "::" + name + args)
+      .str();
+}
+
 unsigned ObjectToIndex::GetIndexForObjectImpl(const void *object) {
   unsigned index = m_mapping.size() + 1;
   auto it = m_mapping.find(object);
   if (it == m_mapping.end())
     m_mapping[object] = index;
   return m_mapping[object];
 }