[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

156–159

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

 #include <cstdio>
 
 namespace llvm {
 class raw_ostream;
 class ThreadPool;
 }
 
 namespace lldb_private {
-class LogHandler;
-class CallbackLogHandler;
 class Address;
+class CallbackLogHandler;
 class CommandInterpreter;
+class LogHandler;
 class Process;
+class RotatingLogHandler;
 class Stream;
 class SymbolContext;
 class Target;
 
 namespace repro {
 class DataRecorder;
 }
 
public:
 
   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);
 
+  bool EnableRotatingLog(unsigned size, uint32_t log_options,
+                         llvm::raw_ostream &error_stream);
+  bool DumpRotatingLog(const FileSpec &dir, llvm::raw_ostream &error_stream);
+
   void SetLoggingCallback(lldb::LogOutputCallback log_callback, void *baton);
 
   // Properties Functions
   enum StopDisassemblyType {
     eStopDisassemblyTypeNever = 0,
     eStopDisassemblyTypeNoDebugInfo,
     eStopDisassemblyTypeNoSource,
     eStopDisassemblyTypeAlways
std::array<lldb::ScriptInterpreterSP, lldb::eScriptLanguageUnknown>
       m_script_interpreters;
 
   IOHandlerStack m_io_handler_stack;
   std::recursive_mutex m_io_handler_synchronous_mutex;
 
   llvm::Optional<uint64_t> m_current_event_id;
 
   llvm::StringMap<std::weak_ptr<LogHandler>> m_stream_handlers;
+  llvm::StringMap<std::weak_ptr<RotatingLogHandler>> m_rotating_handlers;
   std::shared_ptr<CallbackLogHandler> m_callback_handler_sp;
   ConstString m_instance_name;
   static LoadPluginCallbackType g_load_plugin_callback;
   typedef std::vector<llvm::sys::DynamicLibrary> LoadedPluginsList;
   LoadedPluginsList m_loaded_plugins;
   HostThread m_event_handler_thread;
   HostThread m_io_handler_thread;
   Broadcaster m_sync_broadcaster; ///< Private debugger synchronization.

lldb/source/Commands/CommandObjectLog.cpp

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 =
CommandObjectLogTimer(CommandInterpreter &interpreter)
     LoadSubCommand(
         "increment",
         CommandObjectSP(new CommandObjectLogTimerIncrement(interpreter)));
   }
 
   ~CommandObjectLogTimer() override = default;
 };
 
+class CommandObjectLogBufferedEnable : public CommandObjectParsed {
+public:
+  CommandObjectLogBufferedEnable(CommandInterpreter &interpreter)
+      : CommandObjectParsed(
+            interpreter, "log buffered enable <buffer size>",
+            "enable logging to an in-memory buffer for the default category of "
+            "every log channel. These log files can later be written to disk "
+            "with the log buffer dump command.",
+            nullptr) {
+
+    CommandArgumentEntry arg;
+    CommandArgumentData size_arg;
+
+    // Define the first (and only) variant of this arg.
+    size_arg.arg_type = eArgTypeUnsignedInteger;
+    size_arg.arg_repetition = eArgRepeatPlain;
+
+    arg.push_back(size_arg);
+    m_arguments.push_back(arg);
+  }
+
+  ~CommandObjectLogBufferedEnable() override = default;
+
+protected:
+  bool DoExecute(Args &args, CommandReturnObject &result) override {
+    uint32_t log_options = 0;
+    size_t buffer_size = 100;
+
+    if (args.GetArgumentCount() == 1) {
+      if (args[0].ref().consumeInteger(0, buffer_size)) {
+        result.AppendErrorWithFormat("invalid buffer size: %s",
+                                     args[0].ref().data());
+      }
+    }
+
+    std::string error;
+    llvm::raw_string_ostream error_stream(error);
+    bool success =
+        GetDebugger().EnableRotatingLog(buffer_size, log_options, error_stream);
+
+    result.GetErrorStream() << error_stream.str();
+    result.SetStatus(success ? eReturnStatusSuccessFinishNoResult
+                             : eReturnStatusFailed);
+    return result.Succeeded();
+  }
+};
+
+class CommandObjectLogBufferedDump : public CommandObjectParsed {
+public:
+  CommandObjectLogBufferedDump(CommandInterpreter &interpreter)
+      : CommandObjectParsed(
+            interpreter, "log buffered dump <directory>",
+            "dump the buffer logs to disk. This command will create a log file "
+            "for every log channel in the given directory containing the "
+            "contents of the in-memory buffer at the time of the dump.",
+            nullptr) {
+    CommandArgumentEntry arg;
+    CommandArgumentData dir_arg;
+
+    // Define the first (and only) variant of this arg.
+    dir_arg.arg_type = eArgTypeDirectoryName;
+    dir_arg.arg_repetition = eArgRepeatPlain;
+
+    arg.push_back(dir_arg);
+    m_arguments.push_back(arg);
+  }
+
+  void
+  HandleArgumentCompletion(CompletionRequest &request,
+                           OptionElementVector &opt_element_vector) override {
+    CommandCompletions::InvokeCommonCompletionCallbacks(
+        GetCommandInterpreter(), CommandCompletions::eDiskDirectoryCompletion,
+        request, nullptr);
+  }
+
+  ~CommandObjectLogBufferedDump() override = default;
+
+protected:
+  bool DoExecute(Args &args, CommandReturnObject &result) override {
+    if (args.GetArgumentCount() != 1) {
+      result.AppendErrorWithFormat("%s takes a directory argument.\n",
+                                   m_cmd_name.c_str());
+      return false;
+    }
+
+    FileSpec dir(args[0].ref());
+
+    std::string error;
+    llvm::raw_string_ostream error_stream(error);
+    bool success = GetDebugger().DumpRotatingLog(dir, error_stream);
+    result.GetErrorStream() << error_stream.str();
+    result.SetStatus(eReturnStatusSuccessFinishResult);
+    result.SetStatus(success ? eReturnStatusSuccessFinishNoResult
+                             : eReturnStatusFailed);
+    return result.Succeeded();
+  }
+};
+
+class CommandObjectLogBuffered : public CommandObjectMultiword {
+public:
+  CommandObjectLogBuffered(CommandInterpreter &interpreter)
+      : CommandObjectMultiword(
+            interpreter, "log buffered",
+            "Enable and dump buffered in-memory logging.",
+            "log buffered < enable <buffer size> | dump <directory> >") {
+    LoadSubCommand("enable", CommandObjectSP(new CommandObjectLogBufferedEnable(
+                                 interpreter)));
+    LoadSubCommand(
+        "dump", CommandObjectSP(new CommandObjectLogBufferedDump(interpreter)));
+  }
+
+  ~CommandObjectLogBuffered() override = default;
+};
+
 CommandObjectLog::CommandObjectLog(CommandInterpreter &interpreter)
     : CommandObjectMultiword(interpreter, "log",
                              "Commands controlling LLDB internal logging.",
                              "log <subcommand> [<command-options>]") {
   LoadSubCommand("enable",
                  CommandObjectSP(new CommandObjectLogEnable(interpreter)));
   LoadSubCommand("disable",
                  CommandObjectSP(new CommandObjectLogDisable(interpreter)));
   LoadSubCommand("list",
                  CommandObjectSP(new CommandObjectLogList(interpreter)));
   LoadSubCommand("timers",
                  CommandObjectSP(new CommandObjectLogTimer(interpreter)));
+  LoadSubCommand("buffered",
+                 CommandObjectSP(new CommandObjectLogBuffered(interpreter)));
 }
 
 CommandObjectLog::~CommandObjectLog() = default;

lldb/source/Core/Debugger.cpp

bool Debugger::EnableLog(llvm::StringRef channel,
   if (log_options == 0)
     log_options =
         LLDB_LOG_OPTION_PREPEND_THREAD_NAME | LLDB_LOG_OPTION_THREADSAFE;
 
   return Log::EnableLogChannel(log_handler_sp, log_options, channel, categories,
                                error_stream);
 }
 
+bool Debugger::EnableRotatingLog(unsigned size, uint32_t log_options,
+                                 llvm::raw_ostream &error_stream) {
+  if (!m_rotating_handlers.empty())
+    return false;
+
+  // Create a RotatingLogHandler for each channel's default category.
+  for (llvm::StringRef channel : Log::ListChannels()) {
+    auto log_handler_sp = RotatingLogHandler::Create(size);
+    m_rotating_handlers[channel] = log_handler_sp;
+    Log::EnableLogChannel(log_handler_sp, log_options, channel, {"default"},
+                          error_stream);
+  }
+  return true;
+}
+
+bool Debugger::DumpRotatingLog(const FileSpec &dir,
+                               llvm::raw_ostream &error_stream) {
+  if (m_rotating_handlers.empty())
+    return false;
+
+  assert(FileSystem::Instance().IsDirectory(dir) &&
+         "Caller should have made sure the directory is valid");
+
+  const File::OpenOptions flags = File::eOpenOptionWriteOnly |
+                                  File::eOpenOptionCanCreate |
+                                  File::eOpenOptionTruncate;
+
+  for (const auto &entry : m_rotating_handlers) {
+    llvm::StringRef category = entry.first();
+    std::shared_ptr<RotatingLogHandler> handler = entry.second.lock();
+    if (!handler)
+      continue;
+
+    std::string filename = (llvm::Twine(category) + ".log").str();
+    FileSpec log_file = dir.CopyByAppendingPathComponent(filename);
+
+    llvm::Expected<FileUP> file = FileSystem::Instance().Open(
+        log_file, flags, lldb::eFilePermissionsFileDefault, false);
+    if (!file) {
+      error_stream << "Unable to open log file '" << log_file.GetPath()
+                   << "': " << llvm::toString(file.takeError()) << "\n";
+      continue;
+    }
+
+    llvm::raw_fd_ostream stream((*file)->GetDescriptor(), /*shouldClose=*/true);
+    handler->Dump(stream);
+  }
+
+  return true;
+}
+
 ScriptInterpreter *
 Debugger::GetScriptInterpreter(bool can_create,
                                llvm::Optional<lldb::ScriptLanguage> language) {
   std::lock_guard<std::recursive_mutex> locker(m_script_interpreter_mutex);
   lldb::ScriptLanguage script_language =
       language ? *language : GetScriptLanguage();
 
   if (!m_script_interpreters[script_language]) {

lldb/source/Utility/Log.cpp

void RotatingLogHandler::Dump(llvm::raw_ostream &stream) const {
   const size_t stop_idx = start_idx + GetNumMessages();
   for (size_t i = start_idx; i < stop_idx; ++i) {
     const size_t idx = NormalizeIndex(i);
     stream << m_messages[idx];
   }
   stream.flush();
 }
 
-std::shared_ptr<RotatingLogHandler> RotatingLogHandlerCreate(size_t size) {
+std::shared_ptr<RotatingLogHandler> RotatingLogHandler::Create(size_t size) {
   return std::make_shared<RotatingLogHandler>(size);
 }