[Reproducers] Limit logging to calls that cross the API boundary.

[JDevlieghere]

Summary

We recently moved API logging into the instrumentation macros. This made that logging is now consistent and abstracted behind a macro for every API functions, independent of the reproducers. It also means we have a lot more output. While this is a good thing, it also meant a lot more noise in the log, from things that aren't always equally interesting, such as the copy constructor for example.

To improve usability, we should increase the signal-to-noise ratio. I propose to achieve this by only logging API functions that cross the API boundary. This is a divergence of what we had before, where a select number of functions were logged, irregardless of the API boundary, a concept that was introduced for the reproducers. However, I believe this is in line with the purpose of the API log.

[labath]

Logging only external calls makes sense to me. The one thing I was not sure about is the name of the Recorder class, since it's responsibility was now extended to include logging (and that has affected its design). However, I couldn't come up with a better name, and I suppose logging could be considered a form of recording, so maybe that's fine as it is. It might be good to mention the new role in the class description too...

lldb/source/Utility/ReproducerInstrumentation.cpp

106 ↗

(On Diff #196139)

std::move(pretty_args)

include/lldb/Utility/ReproducerInstrumentation.h

 #include "llvm/Support/ErrorHandling.h"
 
 #include <iostream>
 #include <map>
 #include <type_traits>
 
 template <typename T,
           typename std::enable_if<std::is_fundamental<T>::value, int>::type = 0>
-inline void log_append(llvm::raw_string_ostream &ss, const T &t) {
+inline void stringify_append(llvm::raw_string_ostream &ss, const T &t) {
   ss << t;
 }
 
 template <typename T, typename std::enable_if<!std::is_fundamental<T>::value,
                                               int>::type = 0>
-inline void log_append(llvm::raw_string_ostream &ss, const T &t) {
+inline void stringify_append(llvm::raw_string_ostream &ss, const T &t) {
   ss << &t;
 }
 
 template <typename T>
-inline void log_append(llvm::raw_string_ostream &ss, const T *t) {
+inline void stringify_append(llvm::raw_string_ostream &ss, const T *t) {
   ss << reinterpret_cast<const void *>(t);
 }
 
 template <>
-inline void log_append<char>(llvm::raw_string_ostream &ss, const char *t) {
+inline void stringify_append<char>(llvm::raw_string_ostream &ss,
+                                   const char *t) {
   ss << t;
 }
 
 template <typename Head>
-inline void log_helper(llvm::raw_string_ostream &ss, const Head &head) {
-  log_append(ss, head);
+inline void stringify_helper(llvm::raw_string_ostream &ss, const Head &head) {
+  stringify_append(ss, head);
 }
 
 template <typename Head, typename... Tail>
-inline void log_helper(llvm::raw_string_ostream &ss, const Head &head,
+inline void stringify_helper(llvm::raw_string_ostream &ss, const Head &head,
                              const Tail &... tail) {
-  log_append(ss, head);
+  stringify_append(ss, head);
   ss << ", ";
-  log_helper(ss, tail...);
+  stringify_helper(ss, tail...);
 }
 
-template <typename... Ts> inline std::string log_args(const Ts &... ts) {
+template <typename... Ts> inline std::string stringify_args(const Ts &... ts) {
   std::string buffer;
   llvm::raw_string_ostream ss(buffer);
-  log_helper(ss, ts...);
+  stringify_helper(ss, ts...);
   return ss.str();
 }
 
 // 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)                            \
   R.Register<Class * Signature>(&construct<Class Signature>::doit, "", #Class, \
                                 #Class, #Signature)
 #define LLDB_REGISTER_METHOD(Result, Class, Method, Signature)                 \
   R.Register(                                                                  \
       &invoke<Result(Class::*) Signature>::method<(&Class::Method)>::doit,     \
       #Result, #Class, #Method, #Signature)
 #define LLDB_REGISTER_METHOD_CONST(Result, Class, Method, Signature)           \
-  R.Register(&invoke<Result(Class::*)                                          \
-                       Signature const>::method_const<(&Class::Method)>::doit, \
+  R.Register(&invoke<Result(Class::*) Signature const>::method_const<(         \
+                 &Class::Method)>::doit,                                       \
              #Result, #Class, #Method, #Signature)
 #define LLDB_REGISTER_STATIC_METHOD(Result, Class, Method, Signature)          \
   R.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} ({1})",             \
-           LLVM_PRETTY_FUNCTION, log_args(__VA_ARGS__));                       \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION,              \
+                                            stringify_args(__VA_ARGS__));      \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    lldb_private::repro::Recorder sb_recorder(                                 \
-        data.GetSerializer(), data.GetRegistry(), LLVM_PRETTY_FUNCTION);       \
-    sb_recorder.Record(&lldb_private::repro::construct<Class Signature>::doit, \
+    sb_recorder.Record(data.GetSerializer(), data.GetRegistry(),               \
+                       &lldb_private::repro::construct<Class Signature>::doit, \
                        __VA_ARGS__);                                           \
     sb_recorder.RecordResult(this);                                            \
   }
 
 #define LLDB_RECORD_CONSTRUCTOR_NO_ARGS(Class)                                 \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0}",                   \
-           LLVM_PRETTY_FUNCTION);                                              \
+  lldb_private::repro::Recorder sb_recorder(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);       \
-    sb_recorder.Record(&lldb_private::repro::construct<Class()>::doit);        \
+    sb_recorder.Record(data.GetSerializer(), data.GetRegistry(),               \
+                       &lldb_private::repro::construct<Class()>::doit);        \
     sb_recorder.RecordResult(this);                                            \
   }
 
 #define LLDB_RECORD_METHOD(Result, Class, Method, Signature, ...)              \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0} ({1})",             \
-           LLVM_PRETTY_FUNCTION, log_args(__VA_ARGS__));                       \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;                   \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION,              \
+                                            stringify_args(__VA_ARGS__));      \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    sb_recorder.emplace(data.GetSerializer(), data.GetRegistry(),              \
-                        LLVM_PRETTY_FUNCTION);                                 \
-    sb_recorder->Record(                                                       \
+    sb_recorder.Record(                                                        \
+        data.GetSerializer(), data.GetRegistry(),                              \
         &lldb_private::repro::invoke<Result(Class::*) Signature>::method<(     \
             &Class::Method)>::doit,                                            \
         this, __VA_ARGS__);                                                    \
   }
 
 #define LLDB_RECORD_METHOD_CONST(Result, Class, Method, Signature, ...)        \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0} ({1})",             \
-           LLVM_PRETTY_FUNCTION, log_args(__VA_ARGS__));                       \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;                   \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION,              \
+                                            stringify_args(__VA_ARGS__));      \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    sb_recorder.emplace(data.GetSerializer(), data.GetRegistry(),              \
-                        LLVM_PRETTY_FUNCTION);                                 \
-    sb_recorder->Record(                                                       \
+    sb_recorder.Record(                                                        \
+        data.GetSerializer(), data.GetRegistry(),                              \
         &lldb_private::repro::invoke<Result(                                   \
             Class::*) Signature const>::method_const<(&Class::Method)>::doit,  \
         this, __VA_ARGS__);                                                    \
   }
 
 #define LLDB_RECORD_METHOD_NO_ARGS(Result, Class, Method)                      \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0}",                   \
-           LLVM_PRETTY_FUNCTION);                                              \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;                   \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION);             \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    sb_recorder.emplace(data.GetSerializer(), data.GetRegistry(),              \
-                        LLVM_PRETTY_FUNCTION);                                 \
-    sb_recorder->Record(&lldb_private::repro::invoke<Result (                  \
-                            Class::*)()>::method<(&Class::Method)>::doit,      \
-                        this);                                                 \
+    sb_recorder.Record(data.GetSerializer(), data.GetRegistry(),               \
+                       &lldb_private::repro::invoke<Result (                   \
+                           Class::*)()>::method<(&Class::Method)>::doit,       \
+                       this);                                                  \
   }
 
 #define LLDB_RECORD_METHOD_CONST_NO_ARGS(Result, Class, Method)                \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0}",                   \
-           LLVM_PRETTY_FUNCTION);                                              \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;                   \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION);             \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    sb_recorder.emplace(data.GetSerializer(), data.GetRegistry(),              \
-                        LLVM_PRETTY_FUNCTION);                                 \
-    sb_recorder->Record(                                                       \
+    sb_recorder.Record(                                                        \
+        data.GetSerializer(), data.GetRegistry(),                              \
         &lldb_private::repro::invoke<Result (                                  \
             Class::*)() const>::method_const<(&Class::Method)>::doit,          \
         this);                                                                 \
   }
 
 #define LLDB_RECORD_STATIC_METHOD(Result, Class, Method, Signature, ...)       \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0} ({1})",             \
-           LLVM_PRETTY_FUNCTION, log_args(__VA_ARGS__));                       \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;                   \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION,              \
+                                            stringify_args(__VA_ARGS__));      \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    sb_recorder.emplace(data.GetSerializer(), data.GetRegistry(),              \
-                        LLVM_PRETTY_FUNCTION);                                 \
-    sb_recorder->Record(static_cast<Result(*) Signature>(&Class::Method),      \
-                        __VA_ARGS__);                                          \
+    sb_recorder.Record(data.GetSerializer(), data.GetRegistry(),               \
+                       static_cast<Result(*) Signature>(&Class::Method),       \
+                       __VA_ARGS__);                                           \
   }
 
 #define LLDB_RECORD_STATIC_METHOD_NO_ARGS(Result, Class, Method)               \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0}",                   \
-           LLVM_PRETTY_FUNCTION);                                              \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;                   \
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION);             \
   if (lldb_private::repro::InstrumentationData data =                          \
           LLDB_GET_INSTRUMENTATION_DATA()) {                                   \
-    sb_recorder.emplace(data.GetSerializer(), data.GetRegistry(),              \
-                        LLVM_PRETTY_FUNCTION);                                 \
-    sb_recorder->Record(static_cast<Result (*)()>(&Class::Method));            \
+    sb_recorder.Record(data.GetSerializer(), data.GetRegistry(),               \
+                       static_cast<Result (*)()>(&Class::Method));             \
   }
 
-#define LLDB_RECORD_RESULT(Result)                                             \
-  sb_recorder ? sb_recorder->RecordResult(Result) : (Result);
+#define LLDB_RECORD_RESULT(Result) sb_recorder.RecordResult(Result);
 
 /// The LLDB_RECORD_DUMMY macro is special because it doesn't actually record
 /// anything. It's used to track API boundaries when we cannot record for
 /// technical reasons.
 #define LLDB_RECORD_DUMMY(Result, Class, Method, Signature, ...)               \
-  LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0} ({1})",             \
-           LLVM_PRETTY_FUNCTION, log_args(__VA_ARGS__));                       \
-  llvm::Optional<lldb_private::repro::Recorder> sb_recorder;
+  lldb_private::repro::Recorder sb_recorder(LLVM_PRETTY_FUNCTION,              \
+                                            stringify_args(__VA_ARGS__));
 
 namespace lldb_private {
 namespace repro {
 
 /// Mapping between serialized indices and their corresponding objects.
 ///
 /// This class is used during replay to map indices back to in-memory objects.
 ///
public:
 
   operator bool() { return m_serializer != nullptr && m_registry != nullptr; }
 
 private:
   Serializer *m_serializer;
   Registry *m_registry;
 };
 
-/// RAII object that tracks the function invocations and their return value.
+/// RAII object that records function invocations and their return value.
 ///
 /// API calls are only captured when the API boundary is crossed. Once we're in
 /// the API layer, and another API function is called, it doesn't need to be
 /// recorded.
 ///
 /// When a call is recored, its result is always recorded as well, even if the
 /// function returns a void. For functions that return by value, RecordResult
 /// should be used. Otherwise a sentinel value (0) will be serialized.
+///
+/// Because of the functional overlap between logging and recording API calls,
+/// this class is also used for logging.
 class Recorder {
 public:
-  Recorder(Serializer &serializer, Registry &registry,
-           llvm::StringRef pretty_func = {});
+  Recorder(llvm::StringRef pretty_func = {}, std::string &&pretty_args = {});
   ~Recorder();
 
   /// Records a single function call.
   template <typename Result, typename... FArgs, typename... RArgs>
-  void Record(Result (*f)(FArgs...), const RArgs &... args) {
+  void Record(Serializer &serializer, Registry &registry, Result (*f)(FArgs...),
+              const RArgs &... args) {
+    m_serializer = &serializer;
     if (!ShouldCapture())
       return;
 
-    unsigned id = m_registry.GetID(uintptr_t(f));
+    unsigned id = registry.GetID(uintptr_t(f));
+
+#ifdef LLDB_REPRO_INSTR_TRACE
     Log(id);
+#endif
 
-    m_serializer.SerializeAll(id);
-    m_serializer.SerializeAll(args...);
+    serializer.SerializeAll(id);
+    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);
+      serializer.SerializeAll(0);
       m_result_recorded = true;
     }
   }
 
   /// Records a single function call.
   template <typename... Args>
-  void Record(void (*f)(Args...), const Args &... args) {
+  void Record(Serializer &serializer, Registry &registry, void (*f)(Args...),
+              const Args &... args) {
+    m_serializer = &serializer;
     if (!ShouldCapture())
       return;
 
-    unsigned id = m_registry.GetID(uintptr_t(f));
+    unsigned id = registry.GetID(uintptr_t(f));
+
+#ifdef LLDB_REPRO_INSTR_TRACE
     Log(id);
+#endif
 
-    m_serializer.SerializeAll(id);
-    m_serializer.SerializeAll(args...);
+    serializer.SerializeAll(id);
+    serializer.SerializeAll(args...);
 
     // Record result.
-    m_serializer.SerializeAll(0);
+    serializer.SerializeAll(0);
     m_result_recorded = true;
   }
 
   /// Record the result of a function call.
   template <typename Result> Result RecordResult(Result &&r) {
     UpdateBoundary();
-    if (ShouldCapture()) {
+    if (m_serializer && ShouldCapture()) {
       assert(!m_result_recorded);
-      m_serializer.SerializeAll(r);
+      m_serializer->SerializeAll(r);
       m_result_recorded = true;
     }
     return std::forward<Result>(r);
   }
 
 private:
   void UpdateBoundary() {
     if (m_local_boundary)
       g_global_boundary = false;
   }
 
   bool ShouldCapture() { return m_local_boundary; }
-  void Log(unsigned id);
 
-  Serializer &m_serializer;
-  Registry &m_registry;
+#ifdef LLDB_REPRO_INSTR_TRACE
+  void Log(unsigned id) {
+    llvm::errs() << "Recording " << id << ": " << m_pretty_func << " ("
+                 << m_pretty_args << ")\n";
+  }
+#endif
+
+  Serializer *m_serializer;
 
   /// Pretty function for logging.
   llvm::StringRef m_pretty_func;
+  std::string m_pretty_args;
 
   /// Whether this function call was the one crossing the API boundary.
   bool m_local_boundary;
 
   /// Whether the return value was recorded explicitly.
   bool m_result_recorded;
 
   /// Whether we're currently across the API boundary.
   static bool g_global_boundary;
 };
 
 } // namespace repro
 } // namespace lldb_private
 
 #endif // LLDB_UTILITY_REPRODUCER_INSTRUMENTATION_H

source/Utility/ReproducerInstrumentation.cpp

 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];
 }
 
-Recorder::Recorder(Serializer &serializer, Registry &registry,
-                   llvm::StringRef pretty_func)
-    : m_serializer(serializer), m_registry(registry),
-      m_pretty_func(pretty_func), m_local_boundary(false),
+Recorder::Recorder(llvm::StringRef pretty_func, std::string &&pretty_args)
+    : m_serializer(nullptr), m_pretty_func(pretty_func),
+      m_pretty_args(pretty_args), m_local_boundary(false),
       m_result_recorded(true) {
   if (!g_global_boundary) {
     g_global_boundary = true;
     m_local_boundary = true;
+
+    LLDB_LOG(GetLogIfAllCategoriesSet(LIBLLDB_LOG_API), "{0} ({1})",
+             m_pretty_func, m_pretty_args);
   }
 }
 
 Recorder::~Recorder() {
   assert(m_result_recorded && "Did you forget LLDB_RECORD_RESULT?");
   UpdateBoundary();
 }
 
-void Recorder::Log(unsigned id) {
-#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
-}
-
 bool lldb_private::repro::Recorder::g_global_boundary;