[Lldb-commits] [lldb] r359016 - [Reproducers] Limit logging to calls that cross the API boundary.

Jonas Devlieghere via lldb-commits lldb-commits at lists.llvm.org
Tue Apr 23 10:44:40 PDT 2019


Author: jdevlieghere
Date: Tue Apr 23 10:44:40 2019
New Revision: 359016

URL: http://llvm.org/viewvc/llvm-project?rev=359016&view=rev
Log:
[Reproducers] Limit logging to calls that cross the API boundary.

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.

Differential revision: https://reviews.llvm.org/D60984

Modified:
    lldb/trunk/include/lldb/Utility/ReproducerInstrumentation.h
    lldb/trunk/source/Utility/ReproducerInstrumentation.cpp

Modified: lldb/trunk/include/lldb/Utility/ReproducerInstrumentation.h
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/include/lldb/Utility/ReproducerInstrumentation.h?rev=359016&r1=359015&r2=359016&view=diff
==============================================================================
--- lldb/trunk/include/lldb/Utility/ReproducerInstrumentation.h (original)
+++ lldb/trunk/include/lldb/Utility/ReproducerInstrumentation.h Tue Apr 23 10:44:40 2019
@@ -22,43 +22,44 @@
 
 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,
-                       const Tail &... tail) {
-  log_append(ss, head);
+inline void stringify_helper(llvm::raw_string_ostream &ss, const Head &head,
+                             const Tail &... tail) {
+  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();
 }
 
@@ -69,131 +70,111 @@ template <typename... Ts> inline std::st
 
 #define LLDB_REGISTER_CONSTRUCTOR(Class, Signature)                            \
   R.Register<Class * Signature>(&construct<Class Signature>::doit, "", #Class, \
-                              #Class, #Signature)
+                                #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, \
-           #Result, #Class, #Method, #Signature)
+  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 {
@@ -621,7 +602,7 @@ private:
   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
@@ -630,56 +611,68 @@ private:
 /// 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);
@@ -692,13 +685,19 @@ private:
   }
 
   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;

Modified: lldb/trunk/source/Utility/ReproducerInstrumentation.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Utility/ReproducerInstrumentation.cpp?rev=359016&r1=359015&r2=359016&view=diff
==============================================================================
--- lldb/trunk/source/Utility/ReproducerInstrumentation.cpp (original)
+++ lldb/trunk/source/Utility/ReproducerInstrumentation.cpp Tue Apr 23 10:44:40 2019
@@ -101,14 +101,16 @@ unsigned ObjectToIndex::GetIndexForObjec
   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);
   }
 }
 
@@ -117,13 +119,4 @@ Recorder::~Recorder() {
   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;




More information about the lldb-commits mailing list