[lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

> On Dec 6, 2016, at 8:23 AM, Pavel Labath <labath at google.com> wrote:
> 
> Hello all,
> 
> I've been thinking about how to simplify the way we do logging in
> lldb. The main two problems I see are:
> a) inability to print complex types easily - this was always tricky,
> but lately has become even more problematic, as we're starting to
> introduce llvm::StringRef, chrono, and other non-C types everywhere

Streaming output tends to chunk the output text into smaller bits.  That's a problem when you are doing "I have a log line from some customer, I have no idea where it is in the code, so I'm going to search for the text in the code."  That actually happens pretty frequently.  The more you chunk up the text, the harder this task is.  This problem exists in the current method especially since the restriction to 80 chars meant that lots of contiguous log lines are now nonsensically broken up into chunks.  It would be nice not to make it worse.  This is more about ways to write log lines, however; more cultural than implementation.

Like Greg, I find streaming harder to read than printf, particularly if I'm trying to make things indent nicely for reading.  So again, I'd argue for adding these macros, but not trying to replace the current mechanism.


> b) the need to explicitly specify the log source (class and function
> names) explicitly - this leads to increased verboseness and
> inconsistency

I think having a convenience to add function name decorators is fine, but we need a way not to do it all the time.  We have logs that don't have function names because they log over several functions, and having the different names adds visual noise, would make the rest of the log impossible to line up nicely, and adds no important information.  You will write log statements infrequently, but you will have to read them much more frequently, so taking a little more effort to make them readable is well worth it.

> c) the need to write if(log) everywhere -- also increases visual noise

Sometimes you need to do some preliminary calculations to gather the materials you want to log, so the code in the "if (log)" is not trivial.  It has to be inside the "if (log)" however, since you only want to do logging computations if you are logging.  I'd really rather not have to write this in a macro as that makes it hard to read and harder to debug.  That doesn't argue against adding these macros, but it does argue that we need to keep the old form.

Aesthetically, your form does not make it clear that the logging statements are not getting done if logging is off.  I don't want somebody casually working on the code not to log something because they were unsure of this.  We could address that through documentation, a solution whose goodness is weighted by the faith you have in how many people read this sort of documentation.

> 
> I tried to not reinvent the wheel as much as possible, so I decided to
> model my proposal based on how gtest logs it's failure messages. It is
> not a super-well-known feature of gtest, but you can stream additional
> data into the ASSERT statement, in case you think the plain gtest log
> message will not provide enough context for the user. For example you
> can write:
> for (auto test: test_cases)
>  EXPECT_TRUE(do_test(test)) << "Input was: " << test;
> 
> I think this pattern has potential to solve all the problems I
> outlined above. Usage of streams (llvm streams in our case) enables us
> to do any fancy formatting, including the use of recently introduced
> llvm::formatv. And the presence of the macro means that we can hide
> things like "if(log)" and __FUNCTION__ there. If the macro is written
> carefully, the whole log statement will have minimal overhead (the
> same as our current solution) if logging is disabled.
> 
> I have created straw-man implementation of such an interface in
> Dxxxxx, together with some examples of how it's used, and I'd like to
> hear you comments. I've deliberately made it as a custom layer added
> on top of the current implementation, to show how simple the thing can
> be -- after converting just half of a single file to the new
> interface, the implementation has already "payed off" in the number of
> LoC added/removed. If I will be doing the thing it for real, I'd like
> make the integration with llvm streams much deeper.
> 
> So, my question is: Do you like the design in general (if not, why
> not?). If you do, then I'd like to hear your thoughts about the
> particular details of this design:
> - the new implementation prints File::Function as the source, instead
> of the conventional Class::Function. The reason for this is that the
> the class name is not easily accessible from the preprocessor. I think
> this is fine as generally file_name = class_name+".cpp", but possible
> implementations I can think of are:
>  - file+line: I didn't choose this one as lines do not say much, if
> you don't have the source file open. They can also change from
> revision to revision due to unrelated changes.
>  - __PRETTY_FUNCTION__: It contains the class name, but can get
> pretty messy for complex functions. Possibly we could do some
> processing on this value to shorten it (?)...
>  - Have each (loggable) class contain a static consexpr field NAME__,
> and then reference that from the log macro: works, but it's quite
> messy
> 
> - LLDB_LOG() vs. LLDB_LOG(log) -- All our log variables are named log,
> so maybe we don't have to reference them explicitly? I couldn't decide
> whether that helps or hurts readability. (I wanted to keep the log
> variables, instead of specifying the log flags explicitly, as that
> means individual log statements can be very cheap, and short.)

I'd rather keep this explicit.  I don't know if we do it ever, but it is totally reasonable that one function might want to funnel information to two different channels.  Also, it makes explicit the connection between the log object and the channel it is opened for.  It is a bit weird to have a seemingly unused log creation line, then a bunch of logs later on that don't look connected to it.  The more oddities you put in the code the harder it is for a new engineer to begin to grok it.


Jim


> 
> Note, I am not proposing we do a wholesale replacement of the whole
> lldb code base, as that will be a huge job -- the new implementation
> can live together with the old one quite happily (as it does in my
> example). I will certainly go and refactor code I own (linux and
> android), and anyone else can do the same but I am proposing a more
> gradual migration path, where the log statements are updated as we
> touch the affected functions -- I am hoping people will gravitate
> towards that naturally, as the new log statements will be shorter and
> easier to use with more complex types. After usage of the old logs
> drops below a certain percentage, we can go and replace the rest.
> 
> So, what do you think?
> pl