[Lldb-commits] [PATCH] D107079: [lldb] Change the log format to JSON instead of plain text

Thu Jul 29 10:52:35 PDT 2021

jingham added a comment.

When you are using the logging for a reliably reproducible problem (some parsing issue, for instance) then there's no harm to the general "turn on all logging and we'll sort it out on our end".  But for any issues that are timing sensitive the problem is that too much logging changes the timing and often causes bugs to disappear.  This patch will add volume to log emission and slow its emission down, so it goes a bit in the wrong direction.  I don't think that's a reason NOT to do this, hopefully the overhead is small.  But it means we can't assume "turning on all logs" is a reasonable default behavior for logging.  If anything, we need to go in the other direction and add a more fine-grained verbosity so we can ask for "a bit of log channel A and a bit of B and more of C" or whatever.

I'm not entirely sure what you intend when you say:

> Every log message is now a serialized JSON object (that is now also guaranteed to occupy exactly one line) that is just appended to the log file.

Log messages are going to have new-lines in them because it's quite convenient to use the various object Description or Dump methods to log objects and those are generally laid out to be human readable (and are used for that purpose in other contexts.)  By "single line" it seems you mean "all log messages with new lines will have the newline converted to "\n" as a character string before being inserted into the JSON.  This seems more an implementation detail, I'm not sure why you call it out.  In any case, preserving the multi-line structure of log content is important for eventually being able to read them, so as long as the encoders & printers do the right thing, it doesn't really matter how they are encoded.

Conversely, however, it is NOT the case that each LLDB_LOGF call is a single Log message.  For instance, at the beginning and end of each round of "ShouldStop" negotiation, I run through the ThreadPlanStack of each thread that had a non-trivial stop reason and print each thread plan's description in order.  I LOG a header for the output, then (fortunately) I have a routine that dumps all the info to a stream, so I can log that part in one go.  Then I print an end message with another LLDB_LOGF.  Putting these into separate JSON entries makes keeping them together harder - thus making automated tools harder to write - harder to scan with anything but a plain text dumper.

We could require that all unitary log messages build up the whole message off-line into a stream, then log in one go.  But it might be more convenient to have a "start message/end message" pair, so you can call LLDB_LOGF in a loop printing individual objects, then close off the message.  Some kind of RAII deal would be convenient for this.

It would be even more convenient if this allows nesting.  Then you can do "logging the shared library state change - start the list of dylibs - start the log of dylib A, end dylib A, etc..."  That way the individual entity dumps would be structured in the log message that dumped them, and you could progressively reveal them in a neat way.

We definitely need a plain text dumper that we provide.  A very common task in looking through logs is to find an address of some entity in one log message, and then search through the other logs looking at each one to see if it is interesting.  And very often to see if it is embedded in another interesting log transaction, so the context is important.  That's best done with a plain text dump of the log.

================
Comment at: lldb/source/Utility/Log.cpp:362
+
+  llvm::json::OStream J(message);
+  J.object([this, &J, file, function, &payload] {
----------------
Don't use single capitol letter variable names.  They are sort of okay in tiny functions, but tiny functions tend not to stay tiny and then you're trying to find a single letter amongst all the other letters when searching for definitions and uses.

CHANGES SINCE LAST ACTION
  https://reviews.llvm.org/D107079/new/

https://reviews.llvm.org/D107079