This is an archive of the discontinued LLVM Phabricator instance.

[lldb] Support a buffered logging mode
ClosedPublic

Authored by JDevlieghere on Jun 16 2022, 10:30 AM.

Details

Summary

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

Diff Detail

Event Timeline

JDevlieghere created this revision.Jun 16 2022, 10:30 AM
Herald added a project: Restricted Project. · View Herald TranscriptJun 16 2022, 10:30 AM
JDevlieghere requested review of this revision.Jun 16 2022, 10:30 AM

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

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"?

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

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.

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

JDevlieghere edited the summary of this revision. (Show Details)Jun 16 2022, 1:15 PM
clayborg added a comment.EditedJun 16 2022, 1:27 PM

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
171–174

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?

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); 
  }
}

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;
};

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.

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'
 ...
JDevlieghere edited the summary of this revision. (Show Details)
clayborg accepted this revision.Jun 21 2022, 3:11 PM

Looks good!

This revision is now accepted and ready to land.Jun 21 2022, 3:11 PM

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

labath accepted this revision.Jun 22 2022, 11:47 PM

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

Yes, that's pretty much it.

This revision was landed with ongoing or failed builds.Jun 23 2022, 9:12 AM
This revision was automatically updated to reflect the committed changes.
Herald added a project: Restricted Project. · View Herald TranscriptJun 23 2022, 9:12 AM