[lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

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
b) the need to explicitly specify the log source (class and function
names) explicitly - this leads to increased verboseness and
inconsistency
c) the need to write if(log) everywhere -- also increases visual noise

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.)

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