[lldb] Support a buffered logging mode

[JDevlieghere]

Summary

This patch adds a buffered logging mode to lldb. It can be enabled by passing -b <buffer size> to log enable.

[JDevlieghere]

Adding a test is trivial, but I'm holding off on spending time on that until there's consensus about the approach.

[clayborg]

I would vote to add new options to "log enable" and enable any such features on a per "log enable" invocation if possible? Otherwise each time you want to enable this you need to do two commands, and if someone already enables buffered mode, then you wouldn't be able to log anything else? Lets say Xcode always enables logging with something like:

(lldb) log buffered enable 1000000
(lldb) log enable lldb process state thread step

Then the user doesn't know this and they try to enable logging with:

(lldb) log enable lldb expr

Then they currently wouldn't get any logging to the screen? It would be buffered until we dump it with "log buffered dump"?

[clayborg]

Something like:

(lldb) log enable --buffered 100000 lldb process state thread step

If we do this, then we need to be able to specify which buffers to dump somehow. In case someone did:

(lldb) log enable --buffered 100000 lldb ...
(lldb) log enable --buffered 100000 dwarf ...

I the user types "log buffer dump" then all streams would be dumped, maybe with a prefix like:

"lldb" log messages:
...
"dwarf" log messages:
...

Or we might be able to specify one or more channels to get just the ones we want:

(lldb) log buffered dump lldb
(lldb) log buffered dump dwarf
(lldb) log buffered dump lldb dwarf

[clayborg]

I could also imagine having multiple options. For example

--buffered <count>

would specify to buffer the output and only flush if we go over <count> bytes. This could improve logging speeds.

--circular

would enable circular buffering where things are never flushed unless manually done with "log circular dump"

Then we need to manage these settings inside of each LogHandler instance since "--buffered" could work for StreamLogHandler and for CallbackLogHandler. I am just tossing out ideas here just in case any of them make sense as I am thinking about this patch.

[JDevlieghere]

Implement Greg's suggestion of integrating this with log enable.

[clayborg]

The main questions is if we want --buffered for any log channel (file, callback, or circular). If we add a --circular flag, then we just let things accumulate in the LogHandler class.

The idea would be to add more stuff to the LogHandler base class to support this:

class LogHandler {
  bool m_circular = false; // If true, never flush unless "log dump" is called.
  size_t m_buffer_size = 0;
  // If m_buffer_size > 0 then store messages in m_buffer until size is exceeded, then flush.
  std::string m_buffer; 
};

Then we don't need "RotatingLogHandler", and then "log dump" can dump to the callback or to the file. So when the buffer is full, we flush to the virtual Emit(...) call. Just adds some extra logic to the LogHandler class' Emit(...) method to take care of the buffering.

lldb/source/Commands/CommandObjectLog.cpp

161–164

Can't we build buffer size into a file based LogHandler? Have a std::string inside LogHandler and append to it until the bytes left + latest Emit() message go over the buffer size and then flush then?

[clayborg]

For this idea to work we would need to change the Emit() function to be DoEmit(...), then add logic to LogHandler:

void LogHandler::Emit(StringRef message) {
  if (m_circular) {
    // Fill buffer in circular fashion
    return;
  }
  if (m_buffer_size > 0) {
    if (m_buffer.size() + message.size() > m_buffer_size) {
      // If we exceed the buffer size, flush.
      DoEmit(m_buffer);
      DoEmit(message);
      m_buffer.clear();
    } else {
      // Buffer size not exceeded yet.
      m_buffer += message.str();
    }
  } else {
    DoEmit(message); 
  }
}

[JDevlieghere]

In D127986#3590157, @clayborg wrote:

The main questions is if we want --buffered for any log channel (file, callback, or circular). If we add a --circular flag, then we just let things accumulate in the LogHandler class.

That's wasn't a problem I was trying to solve personally, but if you think that would be useful I don't mind supporting it.

The idea would be to add more stuff to the LogHandler base class to support this:

I don't think this has to (or even should) go into the base class. The idea behind the different handlers was to serve as an extension point. I think general buffering is a perfect example of that. The way I would implement that is by wrapping it into its own handler (e.g. BufferedLogHandler) which wraps around another Handler. The delegate handler can then be any of the existing handlers. The implementation would be pretty similar to what you described:

class BufferedLogHandler : public LogHandler {
public:
  void Emit(StringRef message) {
  if (m_buffer_size > 0) {
    if (m_buffer.size() + message.size() > m_buffer_size) {
      // If we exceed the buffer size, flush.
      m_delegate.Emit(m_buffer);
      m_delegate.DoEmit(message);
      m_buffer.clear();
    } else {
      // Buffer size not exceeded yet.
      m_buffer += message.str();
    }
  } else {
    DoEmit(message); 
  }
}

private:
  size_t m_buffer_size = 0;
  std::string m_buffer; 
  LogHandler m_delegate;
};

[clayborg]

The delegate idea is fine too! No need to overload the base class with extra stuff if not needed. I would just like there to be no predispositions on the kinds of logs that can be used when buffering is enabled.

[JDevlieghere]

Generalize support for buffering. You can see it in action below:

(lldb) log enable -b 10 lldb default
(lldb) target create ./bin/count
Current executable set to '/Users/jonas/llvm/build-ra/bin/count' (arm64).
(lldb) b main
 Processing command: target create ./bin/count
 HandleCommand, cmd_obj : 'target create'
 HandleCommand, (revised) command_string: 'target create ./bin/count'
 HandleCommand, wants_raw_input:'False'
 HandleCommand, command line after removing command name(s): './bin/count'
 Target::Target created with architecture arm64 (arm64-apple-macosx12.4.0)
 HandleCommand, command succeeded
 Processing command: b main
 HandleCommand, cmd_obj : '_regexp-break'
 HandleCommand, (revised) command_string: '_regexp-break main'
 HandleCommand, wants_raw_input:'True'
 HandleCommand, command line after removing command name(s): 'main'
 Processing command: breakpoint set --name 'main'
 ...

[clayborg]

Looks good!

[JDevlieghere]

@labath let me know if this is what you had in mind

[labath]

In D127986#3600665, @JDevlieghere wrote:

@labath let me know if this is what you had in mind

Yes, that's pretty much it.

lldb/include/lldb/Core/Debugger.h

public:
 
   bool GetCloseInputOnEOF() const;
 
   void SetCloseInputOnEOF(bool b);
 
   bool EnableLog(llvm::StringRef channel,
                  llvm::ArrayRef<const char *> categories,
                  llvm::StringRef log_file, uint32_t log_options,
-                 llvm::raw_ostream &error_stream);
+                 size_t buffer_size, llvm::raw_ostream &error_stream);
 
   void SetLoggingCallback(lldb::LogOutputCallback log_callback, void *baton);
 
   // Properties Functions
   enum StopDisassemblyType {
     eStopDisassemblyTypeNever = 0,
     eStopDisassemblyTypeNoDebugInfo,
     eStopDisassemblyTypeNoSource,

lldb/include/lldb/Utility/Log.h

public:
   void EmitThreadSafe(llvm::StringRef message);
 
 private:
   std::mutex m_mutex;
 };
 
 class StreamLogHandler : public LogHandler {
 public:
-  StreamLogHandler(int fd, bool should_close, bool unbuffered = true);
+  StreamLogHandler(int fd, bool should_close, size_t buffer_size = 0);
+  ~StreamLogHandler() override;
 
   void Emit(llvm::StringRef message) override;
+  void Flush();
 
 private:
   llvm::raw_fd_ostream m_stream;
 };
 
 class CallbackLogHandler : public LogHandler {
 public:
   CallbackLogHandler(lldb::LogOutputCallback callback, void *baton);

lldb/source/API/SBDebugger.cpp

bool SBDebugger::EnableLog(const char *channel, const char **categories) {
   LLDB_INSTRUMENT_VA(this, channel, categories);
 
   if (m_opaque_sp) {
     uint32_t log_options =
         LLDB_LOG_OPTION_PREPEND_TIMESTAMP | LLDB_LOG_OPTION_PREPEND_THREAD_NAME;
     std::string error;
     llvm::raw_string_ostream error_stream(error);
     return m_opaque_sp->EnableLog(channel, GetCategoryArray(categories), "",
-                                  log_options, error_stream);
+                                  log_options, /*buffer_size=*/0, error_stream);
   } else
     return false;
 }
 
 void SBDebugger::SetLoggingCallback(lldb::LogOutputCallback log_callback,
                                     void *baton) {
   LLDB_INSTRUMENT_VA(this, log_callback, baton);
 

lldb/source/Commands/CommandObjectLog.cpp

 //===-- CommandObjectLog.cpp ----------------------------------------------===//
 //
 // Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
 // See https://llvm.org/LICENSE.txt for license information.
 // SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
 //
 //===----------------------------------------------------------------------===//
 
 #include "CommandObjectLog.h"
 #include "lldb/Core/Debugger.h"
 #include "lldb/Host/OptionParser.h"
 #include "lldb/Interpreter/CommandReturnObject.h"
 #include "lldb/Interpreter/OptionArgParser.h"
+#include "lldb/Interpreter/OptionValueUInt64.h"
 #include "lldb/Interpreter/Options.h"
 #include "lldb/Utility/Args.h"
 #include "lldb/Utility/FileSpec.h"
 #include "lldb/Utility/Log.h"
 #include "lldb/Utility/Stream.h"
 #include "lldb/Utility/Timer.h"
 
 using namespace lldb;
 using namespace lldb_private;
 
-#define LLDB_OPTIONS_log
+#define LLDB_OPTIONS_log_enable
 #include "CommandOptions.inc"
 
 /// Common completion logic for log enable/disable.
 static void CompleteEnableDisable(CompletionRequest &request) {
   size_t arg_index = request.GetCursorIndex();
   if (arg_index == 0) { // We got: log enable/disable x[tab]
     for (llvm::StringRef channel : Log::ListChannels())
       request.TryCompleteCurrentArg(channel);
Status SetOptionValue(uint32_t option_idx, llvm::StringRef option_arg,
       Status error;
       const int short_option = m_getopt_table[option_idx].val;
 
       switch (short_option) {
       case 'f':
         log_file.SetFile(option_arg, FileSpec::Style::native);
         FileSystem::Instance().Resolve(log_file);
         break;
+      case 'b':
+        error =
+            buffer_size.SetValueFromString(option_arg, eVarSetOperationAssign);
+        break;
       case 't':
         log_options |= LLDB_LOG_OPTION_THREADSAFE;
         break;
       case 'v':
         log_options |= LLDB_LOG_OPTION_VERBOSE;
         break;
       case 's':
         log_options |= LLDB_LOG_OPTION_PREPEND_SEQUENCE;
Status SetOptionValue(uint32_t option_idx, llvm::StringRef option_arg,
         llvm_unreachable("Unimplemented option");
       }
 
       return error;
     }
 
     void OptionParsingStarting(ExecutionContext *execution_context) override {
       log_file.Clear();
+      buffer_size.Clear();
       log_options = 0;
     }
 
     llvm::ArrayRef<OptionDefinition> GetDefinitions() override {
-      return llvm::makeArrayRef(g_log_options);
+      return llvm::makeArrayRef(g_log_enable_options);
     }
 
-    // Instance variables to hold the values for command options.
-
     FileSpec log_file;
+    OptionValueUInt64 buffer_size;
     uint32_t log_options = 0;
   };
 
   void
   HandleArgumentCompletion(CompletionRequest &request,
                            OptionElementVector &opt_element_vector) override {
     CompleteEnableDisable(request);
   }
 
 protected:
   bool DoExecute(Args &args, CommandReturnObject &result) override {
     if (args.GetArgumentCount() < 2) {
       result.AppendErrorWithFormat(
           "%s takes a log channel and one or more log types.\n",
           m_cmd_name.c_str());
       return false;
     }
 
     // Store into a std::string since we're about to shift the channel off.
     const std::string channel = std::string(args[0].ref());
     args.Shift(); // Shift off the channel
     char log_file[PATH_MAX];
     if (m_options.log_file)
       m_options.log_file.GetPath(log_file, sizeof(log_file));
     else
       log_file[0] = '\0';
 
     std::string error;
     llvm::raw_string_ostream error_stream(error);
-    bool success =
-        GetDebugger().EnableLog(channel, args.GetArgumentArrayRef(), log_file,
-                                m_options.log_options, error_stream);
+    bool success = GetDebugger().EnableLog(
+        channel, args.GetArgumentArrayRef(), log_file, m_options.log_options,
+        m_options.buffer_size.GetCurrentValue(), error_stream);
     result.GetErrorStream() << error_stream.str();
 
     if (success)
       result.SetStatus(eReturnStatusSuccessFinishNoResult);
     else
       result.SetStatus(eReturnStatusFailed);
     return result.Succeeded();
   }

lldb/source/Commands/Options.td

def history_start_index : Option<"start-index", "s">, Group<1>,
     "commands (or end to mean tail mode).">;
   def history_end_index : Option<"end-index", "e">, Group<1>,
     Arg<"UnsignedInteger">,
     Desc<"Index at which to stop printing history commands.">;
   def history_clear : Option<"clear", "C">, Group<2>,
     Desc<"Clears the current command history.">;
 }
 
-let Command = "log" in {
+let Command = "log enable" in {
   def log_file : Option<"file", "f">, Group<1>, Arg<"Filename">,
     Desc<"Set the destination file to log to.">;
+  def log_buffer_size : Option<"buffer", "b">, Group<1>, Arg<"UnsignedInteger">,
+    Desc<"Set the log to be buffered, using the specified buffer size.">;
   def log_threadsafe : Option<"threadsafe", "t">, Group<1>,
     Desc<"Enable thread safe logging to avoid interweaved log lines.">;
   def log_verbose : Option<"verbose", "v">, Group<1>,
     Desc<"Enable verbose logging.">;
   def log_sequence : Option<"sequence", "s">, Group<1>,
     Desc<"Prepend all log lines with an increasing integer sequence id.">;
   def log_timestamp : Option<"timestamp", "T">, Group<1>,
     Desc<"Prepend all log lines with a timestamp.">;

lldb/source/Core/Debugger.cpp

void Debugger::ReportError(std::string message,
 
   ReportDiagnosticImpl(DiagnosticEventData::Type::Error, std::move(message),
                        debugger_id, once);
 }
 
 bool Debugger::EnableLog(llvm::StringRef channel,
                          llvm::ArrayRef<const char *> categories,
                          llvm::StringRef log_file, uint32_t log_options,
-                         llvm::raw_ostream &error_stream) {
+                         size_t buffer_size, llvm::raw_ostream &error_stream) {
   const bool should_close = true;
 
   std::shared_ptr<LogHandler> log_handler_sp;
   if (m_callback_handler_sp) {
     log_handler_sp = m_callback_handler_sp;
     // For now when using the callback mode you always get thread & timestamp.
     log_options |=
         LLDB_LOG_OPTION_PREPEND_TIMESTAMP | LLDB_LOG_OPTION_PREPEND_THREAD_NAME;
   } else if (log_file.empty()) {
     log_handler_sp = std::make_shared<StreamLogHandler>(
-        GetOutputFile().GetDescriptor(), !should_close);
+        GetOutputFile().GetDescriptor(), !should_close, buffer_size);
   } else {
     auto pos = m_stream_handlers.find(log_file);
     if (pos != m_stream_handlers.end())
       log_handler_sp = pos->second.lock();
     if (!log_handler_sp) {
       File::OpenOptions flags =
           File::eOpenOptionWriteOnly | File::eOpenOptionCanCreate;
       if (log_options & LLDB_LOG_OPTION_APPEND)
         flags |= File::eOpenOptionAppend;
       else
         flags |= File::eOpenOptionTruncate;
       llvm::Expected<FileUP> file = FileSystem::Instance().Open(
           FileSpec(log_file), flags, lldb::eFilePermissionsFileDefault, false);
       if (!file) {
         error_stream << "Unable to open log file '" << log_file
                      << "': " << llvm::toString(file.takeError()) << "\n";
         return false;
       }
 
       log_handler_sp = std::make_shared<StreamLogHandler>(
-          (*file)->GetDescriptor(), should_close);
+          (*file)->GetDescriptor(), should_close, buffer_size);
       m_stream_handlers[log_file] = log_handler_sp;
     }
   }
   assert(log_handler_sp);
 
   if (log_options == 0)
     log_options =
         LLDB_LOG_OPTION_PREPEND_THREAD_NAME | LLDB_LOG_OPTION_THREADSAFE;

lldb/source/Utility/Log.cpp

void Log::Format(llvm::StringRef file, llvm::StringRef function,
   WriteMessage(message.str());
 }
 
 void LogHandler::EmitThreadSafe(llvm::StringRef message) {
   std::lock_guard<std::mutex> guard(m_mutex);
   Emit(message);
 }
 
-StreamLogHandler::StreamLogHandler(int fd, bool should_close, bool unbuffered)
-    : m_stream(fd, should_close, unbuffered) {}
-
-void StreamLogHandler::Emit(llvm::StringRef message) {
-  m_stream << message;
-  m_stream.flush();
+StreamLogHandler::StreamLogHandler(int fd, bool should_close,
+                                   size_t buffer_size)
+    : m_stream(fd, should_close, buffer_size == 0) {
+  if (buffer_size > 0)
+    m_stream.SetBufferSize(buffer_size);
 }
 
+StreamLogHandler::~StreamLogHandler() { Flush(); }
+
+void StreamLogHandler::Flush() { m_stream.flush(); }
+
+void StreamLogHandler::Emit(llvm::StringRef message) { m_stream << message; }
+
 CallbackLogHandler::CallbackLogHandler(lldb::LogOutputCallback callback,
                                        void *baton)
     : m_callback(callback), m_baton(baton) {}
 
 void CallbackLogHandler::Emit(llvm::StringRef message) {
   m_callback(message.data(), m_baton);
 }
 

lldb/tools/lldb-test/lldb-test.cpp

int main(int argc, const char *argv[]) {
   Dbg->GetCommandInterpreter().HandleCommand(
       "settings set target.inherit-tcc true",
       /*add_to_history*/ eLazyBoolNo, Result);
   Dbg->GetCommandInterpreter().HandleCommand(
       "settings set target.detach-on-error false",
       /*add_to_history*/ eLazyBoolNo, Result);
 
   if (!opts::Log.empty())
-    Dbg->EnableLog("lldb", {"all"}, opts::Log, 0, errs());
+    Dbg->EnableLog("lldb", {"all"}, opts::Log, 0, 0, errs());
 
   if (opts::BreakpointSubcommand)
     return opts::breakpoint::evaluateBreakpoints(*Dbg);
   if (opts::ObjectFileSubcommand)
     return dumpObjectFiles(*Dbg);
   if (opts::SymbolsSubcommand)
     return opts::symbols::dumpSymbols(*Dbg);
   if (opts::IRMemoryMapSubcommand)
     return opts::irmemorymap::evaluateMemoryMapCommands(*Dbg);
   if (opts::AssertSubcommand)
     return opts::assert::lldb_assert(*Dbg);
 
   WithColor::error() << "No command specified.\n";
   return 1;
 }