[Lldb-commits] [lldb] r292360 - Add a more succinct logging syntax

Pavel Labath via lldb-commits lldb-commits at lists.llvm.org
Wed Jan 18 03:00:27 PST 2017


Author: labath
Date: Wed Jan 18 05:00:26 2017
New Revision: 292360

URL: http://llvm.org/viewvc/llvm-project?rev=292360&view=rev
Log:
Add a more succinct logging syntax

This adds the LLDB_LOG macro, which enables one to write more succinct log
statements.
if (log)
  log->Printf("log something: %d", var);
becomes
LLDB_LOG(log, "log something: {0}, var);

The macro still internally does the "if(log)" dance, so the arguments are only
evaluated if logging is enabled, meaning it has the same overhead as the
previous syntax.

Additionally, the log statements will be automatically prefixed with the file
and function generating the log (if the corresponding new argument to the "log
enable" command is enabled), so one does not need to manually specify this in
the log statement.

It also uses the new llvm formatv syntax, which means we don't have to worry
about PRIx64 macros and similar, and we can log complex object (llvm::StringRef,
lldb_private::Error, ...) more easily.

Differential Revision: https://reviews.llvm.org/D27459

Added:
    lldb/trunk/unittests/Core/LogTest.cpp
Modified:
    lldb/trunk/include/lldb/Core/Log.h
    lldb/trunk/source/Commands/CommandObjectLog.cpp
    lldb/trunk/source/Core/Log.cpp
    lldb/trunk/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp
    lldb/trunk/tools/lldb-server/lldb-gdbserver.cpp
    lldb/trunk/unittests/Core/CMakeLists.txt

Modified: lldb/trunk/include/lldb/Core/Log.h
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/include/lldb/Core/Log.h?rev=292360&r1=292359&r2=292360&view=diff
==============================================================================
--- lldb/trunk/include/lldb/Core/Log.h (original)
+++ lldb/trunk/include/lldb/Core/Log.h Wed Jan 18 05:00:26 2017
@@ -10,14 +10,6 @@
 #ifndef liblldb_Log_h_
 #define liblldb_Log_h_
 
-// C Includes
-#include <signal.h>
-#include <stdarg.h>
-#include <stdint.h>
-#include <stdio.h>
-
-// C++ Includes
-// Other libraries and framework includes
 // Project includes
 #include "lldb/Core/ConstString.h"
 #include "lldb/Core/Flags.h"
@@ -25,7 +17,12 @@
 #include "lldb/Core/PluginInterface.h"
 #include "lldb/lldb-private.h"
 
+// Other libraries and framework includes
 #include "llvm/Support/FormatVariadic.h"
+// C++ Includes
+#include <cstdarg>
+#include <cstdint>
+// C Includes
 
 //----------------------------------------------------------------------
 // Logging Options
@@ -39,6 +36,7 @@
 #define LLDB_LOG_OPTION_PREPEND_THREAD_NAME (1U << 6)
 #define LLDB_LOG_OPTION_BACKTRACE (1U << 7)
 #define LLDB_LOG_OPTION_APPEND (1U << 8)
+#define LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION (1U << 9)
 
 //----------------------------------------------------------------------
 // Logging Functions
@@ -109,8 +107,10 @@ public:
   void PutCString(const char *cstr);
   void PutString(llvm::StringRef str);
 
-  template <typename... Args> void Format(const char *fmt, Args &&... args) {
-    PutString(llvm::formatv(fmt, std::forward<Args>(args)...).str());
+  template <typename... Args>
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const char *format, Args &&... args) {
+    Format(file, function, llvm::formatv(format, std::forward<Args>(args)...));
   }
 
   // CLEANUP: Add llvm::raw_ostream &Stream() function.
@@ -155,6 +155,13 @@ protected:
 
 private:
   DISALLOW_COPY_AND_ASSIGN(Log);
+
+  void WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                   llvm::StringRef function);
+  void WriteMessage(const std::string &message);
+
+  void Format(llvm::StringRef file, llvm::StringRef function,
+              const llvm::formatv_object_base &payload);
 };
 
 class LogChannel : public PluginInterface {
@@ -186,4 +193,11 @@ private:
 
 } // namespace lldb_private
 
+#define LLDB_LOG(log, ...)                                                     \
+  do {                                                                         \
+    ::lldb_private::Log *log_private = (log);                                  \
+    if (log_private)                                                           \
+      log_private->Format(__FILE__, __FUNCTION__, __VA_ARGS__);                \
+  } while (0)
+
 #endif // liblldb_Log_h_

Modified: lldb/trunk/source/Commands/CommandObjectLog.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Commands/CommandObjectLog.cpp?rev=292360&r1=292359&r2=292360&view=diff
==============================================================================
--- lldb/trunk/source/Commands/CommandObjectLog.cpp (original)
+++ lldb/trunk/source/Commands/CommandObjectLog.cpp Wed Jan 18 05:00:26 2017
@@ -48,6 +48,7 @@ static OptionDefinition g_log_options[]
   { LLDB_OPT_SET_1, false, "thread-name",'n', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Prepend all log lines with the thread name for the thread that generates the log line." },
   { LLDB_OPT_SET_1, false, "stack",      'S', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Append a stack backtrace to each log line." },
   { LLDB_OPT_SET_1, false, "append",     'a', OptionParser::eNoArgument,       nullptr, nullptr, 0, eArgTypeNone,     "Append to the log file instead of overwriting." },
+  { LLDB_OPT_SET_1, false, "file-function",'F',OptionParser::eNoArgument,      nullptr, nullptr, 0, eArgTypeNone,     "Prepend the names of files and function that generate the logs." },
     // clang-format on
 };
 
@@ -130,6 +131,8 @@ public:
       case 'a':
         log_options |= LLDB_LOG_OPTION_APPEND;
         break;
+      case 'F':
+        log_options |= LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION;
       default:
         error.SetErrorStringWithFormat("unrecognized option '%c'",
                                        short_option);

Modified: lldb/trunk/source/Core/Log.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Core/Log.cpp?rev=292360&r1=292359&r2=292360&view=diff
==============================================================================
--- lldb/trunk/source/Core/Log.cpp (original)
+++ lldb/trunk/source/Core/Log.cpp Wed Jan 18 05:00:26 2017
@@ -20,6 +20,7 @@
 // Other libraries and framework includes
 #include "llvm/ADT/SmallString.h"
 #include "llvm/Support/Chrono.h"
+#include "llvm/Support/Path.h"
 #include "llvm/Support/Signals.h"
 #include "llvm/Support/raw_ostream.h"
 
@@ -69,58 +70,18 @@ void Log::Printf(const char *format, ...
 // a valid file handle, we also log to the file.
 //----------------------------------------------------------------------
 void Log::VAPrintf(const char *format, va_list args) {
-  // Make a copy of our stream shared pointer in case someone disables our
-  // log while we are logging and releases the stream
-  StreamSP stream_sp(m_stream_sp);
-  if (stream_sp) {
-    static uint32_t g_sequence_id = 0;
-    StreamString header;
-
-    // Add a sequence ID if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
-      header.Printf("%u ", ++g_sequence_id);
-
-    // Timestamp if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
-      auto now = std::chrono::duration<double>(
-          std::chrono::system_clock::now().time_since_epoch());
-      header.Printf("%.9f ", now.count());
-    }
+  std::string message_string;
+  llvm::raw_string_ostream message(message_string);
+  WriteHeader(message, "", "");
+
+  char *text;
+  vasprintf(&text, format, args);
+  message << text;
+  free(text);
 
-    // Add the process and thread if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
-      header.Printf("[%4.4x/%4.4" PRIx64 "]: ", getpid(),
-                    Host::GetCurrentThreadID());
-
-    // Add the thread name if requested
-    if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
-      llvm::SmallString<32> thread_name;
-      ThisThread::GetName(thread_name);
-      if (!thread_name.empty())
-        header.Printf("%s ", thread_name.c_str());
-    }
-
-    header.PrintfVarArg(format, args);
-    header.PutCString("\n");
-
-    if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE)) {
-      std::string back_trace;
-      llvm::raw_string_ostream stream(back_trace);
-      llvm::sys::PrintStackTrace(stream);
-      stream.flush();
-      header.PutCString(back_trace);
-    }
+  message << "\n";
 
-    if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
-      static std::recursive_mutex g_LogThreadedMutex;
-      std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
-      stream_sp->PutCString(header.GetString());
-      stream_sp->Flush();
-    } else {
-      stream_sp->PutCString(header.GetString());
-      stream_sp->Flush();
-    }
-  }
+  WriteMessage(message.str());
 }
 
 //----------------------------------------------------------------------
@@ -353,6 +314,71 @@ bool Log::GetDebug() const {
   return false;
 }
 
+void Log::WriteHeader(llvm::raw_ostream &OS, llvm::StringRef file,
+                      llvm::StringRef function) {
+  static uint32_t g_sequence_id = 0;
+  // Add a sequence ID if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_SEQUENCE))
+    OS << ++g_sequence_id << " ";
+
+  // Timestamp if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_TIMESTAMP)) {
+    auto now = std::chrono::duration<double>(
+        std::chrono::system_clock::now().time_since_epoch());
+    OS << llvm::formatv("{0:f9} ", now.count());
+  }
+
+  // Add the process and thread if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD))
+    OS << llvm::formatv("[{0,0+4}/{1,0+4}] ", getpid(),
+                        Host::GetCurrentThreadID());
+
+  // Add the thread name if requested
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_THREAD_NAME)) {
+    llvm::SmallString<32> thread_name;
+    ThisThread::GetName(thread_name);
+    if (!thread_name.empty())
+      OS << thread_name;
+  }
+
+  if (m_options.Test(LLDB_LOG_OPTION_BACKTRACE))
+    llvm::sys::PrintStackTrace(OS);
+
+  if (m_options.Test(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION) &&
+      (!file.empty() || !function.empty())) {
+    file = llvm::sys::path::filename(file).take_front(40);
+    function = function.take_front(40);
+    OS << llvm::formatv("{0,-60:60} ", (file + ":" + function).str());
+  }
+}
+
+void Log::WriteMessage(const std::string &message) {
+  // Make a copy of our stream shared pointer in case someone disables our
+  // log while we are logging and releases the stream
+  StreamSP stream_sp(m_stream_sp);
+  if (!stream_sp)
+    return;
+
+  if (m_options.Test(LLDB_LOG_OPTION_THREADSAFE)) {
+    static std::recursive_mutex g_LogThreadedMutex;
+    std::lock_guard<std::recursive_mutex> guard(g_LogThreadedMutex);
+    stream_sp->PutCString(message.c_str());
+    stream_sp->Flush();
+  } else {
+    stream_sp->PutCString(message.c_str());
+    stream_sp->Flush();
+  }
+}
+
+void Log::Format(llvm::StringRef file, llvm::StringRef function,
+                 const llvm::formatv_object_base &payload) {
+  std::string message_string;
+  llvm::raw_string_ostream message(message_string);
+  WriteHeader(message, file, function);
+  message << payload << "\n";
+  WriteMessage(message.str());
+}
+
 LogChannelSP LogChannel::FindPlugin(const char *plugin_name) {
   LogChannelSP log_channel_sp;
   LogChannelMap &channel_map = GetChannelMap();

Modified: lldb/trunk/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp?rev=292360&r1=292359&r2=292360&view=diff
==============================================================================
--- lldb/trunk/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp (original)
+++ lldb/trunk/source/Plugins/ExpressionParser/Clang/IRForTarget.cpp Wed Jan 18 05:00:26 2017
@@ -512,11 +512,9 @@ bool IRForTarget::RewriteObjCConstString
    break;
  default:
    encoding_flags = 0x0600; /* fall back to 0x0600, kCFStringEncodingASCII */
-   if (log) {
-     log->Format("Encountered an Objective-C constant string with unusual "
+   LLDB_LOG(log, "Encountered an Objective-C constant string with unusual "
                  "element size {0}",
-                 string_array->getElementByteSize());
-   }
+            string_array->getElementByteSize());
  }
  Constant *encoding_arg = ConstantInt::get(i32_ty, encoding_flags, false);
  Constant *isExternal_arg =

Modified: lldb/trunk/tools/lldb-server/lldb-gdbserver.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/tools/lldb-server/lldb-gdbserver.cpp?rev=292360&r1=292359&r2=292360&view=diff
==============================================================================
--- lldb/trunk/tools/lldb-server/lldb-gdbserver.cpp (original)
+++ lldb/trunk/tools/lldb-server/lldb-gdbserver.cpp Wed Jan 18 05:00:26 2017
@@ -424,8 +424,10 @@ int main_gdbserver(int argc, char *argv[
     exit(option_error);
   }
 
-  if (!LLDBServerUtilities::SetupLogging(log_file, log_channels,
-                                         LLDB_LOG_OPTION_PREPEND_TIMESTAMP))
+  if (!LLDBServerUtilities::SetupLogging(
+          log_file, log_channels,
+          LLDB_LOG_OPTION_PREPEND_TIMESTAMP |
+              LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION))
     return -1;
 
   Log *log(lldb_private::GetLogIfAnyCategoriesSet(GDBR_LOG_VERBOSE));

Modified: lldb/trunk/unittests/Core/CMakeLists.txt
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Core/CMakeLists.txt?rev=292360&r1=292359&r2=292360&view=diff
==============================================================================
--- lldb/trunk/unittests/Core/CMakeLists.txt (original)
+++ lldb/trunk/unittests/Core/CMakeLists.txt Wed Jan 18 05:00:26 2017
@@ -4,6 +4,7 @@ add_lldb_unittest(LLDBCoreTests
   DataExtractorTest.cpp
   ErrorTest.cpp
   ListenerTest.cpp
+  LogTest.cpp
   ScalarTest.cpp
   StructuredDataTest.cpp
   TimerTest.cpp

Added: lldb/trunk/unittests/Core/LogTest.cpp
URL: http://llvm.org/viewvc/llvm-project/lldb/trunk/unittests/Core/LogTest.cpp?rev=292360&view=auto
==============================================================================
--- lldb/trunk/unittests/Core/LogTest.cpp (added)
+++ lldb/trunk/unittests/Core/LogTest.cpp Wed Jan 18 05:00:26 2017
@@ -0,0 +1,56 @@
+//===-- LogTest.cpp ---------------------------------------------*- C++ -*-===//
+//
+//                     The LLVM Compiler Infrastructure
+//
+// This file is distributed under the University of Illinois Open Source
+// License. See LICENSE.TXT for details.
+//
+//===----------------------------------------------------------------------===//
+
+#include "lldb/Core/Log.h"
+#include "lldb/Core/StreamString.h"
+#include "lldb/Host/Host.h"
+#include "gtest/gtest.h"
+
+using namespace lldb;
+using namespace lldb_private;
+
+static std::string GetLogString(uint32_t log_options, const char *format,
+                                int arg) {
+  std::shared_ptr<StreamString> stream_sp(new StreamString());
+  Log log_(stream_sp);
+  log_.GetOptions().Reset(log_options);
+  Log *log = &log_;
+  LLDB_LOG(log, format, arg);
+  return stream_sp->GetString();
+}
+
+TEST(LogTest, LLDB_LOG_nullptr) {
+  Log *log = nullptr;
+  LLDB_LOG(log, "{0}", 0); // Shouldn't crash
+}
+
+TEST(LogTest, log_options) {
+  EXPECT_EQ("Hello World 47\n", GetLogString(0, "Hello World {0}", 47));
+  EXPECT_EQ("Hello World 47\n",
+            GetLogString(LLDB_LOG_OPTION_THREADSAFE, "Hello World {0}", 47));
+
+  {
+    std::string msg =
+        GetLogString(LLDB_LOG_OPTION_PREPEND_SEQUENCE, "Hello World {0}", 47);
+    int seq_no;
+    EXPECT_EQ(1, sscanf(msg.c_str(), "%d Hello World 47", &seq_no));
+  }
+
+  EXPECT_EQ(
+      "LogTest.cpp:GetLogString                                     Hello "
+      "World 47\n",
+      GetLogString(LLDB_LOG_OPTION_PREPEND_FILE_FUNCTION, "Hello World {0}", 47));
+
+  EXPECT_EQ(llvm::formatv("[{0}/{1}] Hello World 47\n",
+                          Host::GetCurrentProcessID(),
+                          Host::GetCurrentThreadID())
+                .str(),
+            GetLogString(LLDB_LOG_OPTION_PREPEND_PROC_AND_THREAD,
+                         "Hello World {0}", 47));
+}




More information about the lldb-commits mailing list