Re: [lldb-dev] logging in lldb

[Adrian McCarthy via lldb-dev]

On Wed, Jan 11, 2017 at 10:38 AM, Zachary Turner  wrote:

>
>
> On Wed, Jan 11, 2017 at 6:59 AM Pavel Labath  wrote:
>
>> Happy new year everyone. :)
>>
>> I have refreshed the implementation at
>>  with something more polished. I
>> consider this almost-ready, I just need feedback on a couple of
>> details:
>>
>> - log->Warning/Debug/Error/Verbose: Currently we have a large number
>> of printf-style logging functions, which are very rarely used (and all
>> they do is prefix the log line with some string), and only one
>> formatv-style. It would be easy to add LLDB_WARN, LLDB_ERR, etc.
>> macros, so that these usages can be ported to the formatv-style.
>> However, I am not sure whether that's really necessary. One of the
>> goals of this process could be to standardize on one function. I would
>> prefer to keep just one log function, but I could be easily convinced
>> otherwise. For reference, these are the current approximate usages of
>> the logging functions (as determined by grep)
>> log->Error: 38 (mostly in ProcessWindows)
>> log->Warning: 25
>> log->Debug: 10 (mostly ClangExpressionParser)
>> log->Verbose: 6 (only ProcessWindows)
>> log->Printf: 2884
>>
> Yea, these are unnecessary and it would be great to get rid of them.
>
>
>>
>> - ProcessWindowsLog: I am not going to go on a reformatting spree to
>> change all logging statements, but I would still like to change remove
>> the logging macros that windows log introduced, since they are very
>> custom, and I'd like to keep the number of logging syntaxes below 3
>> :). Zachary, Adrian, is that OK with you?
>>
> Fine with me, they were only introduced as an alternative to the verbose
> if (log) syntaxes.  If there's an alternative that also solves the problem
> and we can adopt everywhere, then I'm all for it.
>

Fine with me as well.


>
>
>>
>> I must confess have a bit of an ulterior motive for doing this. :) My
>> goal is to start working on the modularization of the codebase. But I
>> don't want it to be just mindless moving of code around. I want to
>> spend some time considering the design of each piece, which should
>> slow things down long enough for the moves to not be annoying, and
>> hopefully produce better components. I'll write more on that soon - I
>> don't want to derail this discussion with it.
>>
> I'd start with one support library which we document and write in stone
> (perhaps even enforce in CMake) that it can have no other dependencies on
> LLDB libraries.  Then start moving various common data structures and
> classes over there.  Like you said, we should save the details for another
> thread, but in any case i look forward to seeing some proposals :)
>
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Zachary Turner via lldb-dev]

On Wed, Jan 11, 2017 at 6:59 AM Pavel Labath  wrote:

> Happy new year everyone. :)
>
> I have refreshed the implementation at
>  with something more polished. I
> consider this almost-ready, I just need feedback on a couple of
> details:
>
> - log->Warning/Debug/Error/Verbose: Currently we have a large number
> of printf-style logging functions, which are very rarely used (and all
> they do is prefix the log line with some string), and only one
> formatv-style. It would be easy to add LLDB_WARN, LLDB_ERR, etc.
> macros, so that these usages can be ported to the formatv-style.
> However, I am not sure whether that's really necessary. One of the
> goals of this process could be to standardize on one function. I would
> prefer to keep just one log function, but I could be easily convinced
> otherwise. For reference, these are the current approximate usages of
> the logging functions (as determined by grep)
> log->Error: 38 (mostly in ProcessWindows)
> log->Warning: 25
> log->Debug: 10 (mostly ClangExpressionParser)
> log->Verbose: 6 (only ProcessWindows)
> log->Printf: 2884
>
Yea, these are unnecessary and it would be great to get rid of them.


>
> - ProcessWindowsLog: I am not going to go on a reformatting spree to
> change all logging statements, but I would still like to change remove
> the logging macros that windows log introduced, since they are very
> custom, and I'd like to keep the number of logging syntaxes below 3
> :). Zachary, Adrian, is that OK with you?
>
Fine with me, they were only introduced as an alternative to the verbose if
(log) syntaxes.  If there's an alternative that also solves the problem and
we can adopt everywhere, then I'm all for it.


>
> I must confess have a bit of an ulterior motive for doing this. :) My
> goal is to start working on the modularization of the codebase. But I
> don't want it to be just mindless moving of code around. I want to
> spend some time considering the design of each piece, which should
> slow things down long enough for the moves to not be annoying, and
> hopefully produce better components. I'll write more on that soon - I
> don't want to derail this discussion with it.
>
I'd start with one support library which we document and write in stone
(perhaps even enforce in CMake) that it can have no other dependencies on
LLDB libraries.  Then start moving various common data structures and
classes over there.  Like you said, we should save the details for another
thread, but in any case i look forward to seeing some proposals :)
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

Happy new year everyone. :)

I have refreshed the implementation at
 with something more polished. I
consider this almost-ready, I just need feedback on a couple of
details:

- log->Warning/Debug/Error/Verbose: Currently we have a large number
of printf-style logging functions, which are very rarely used (and all
they do is prefix the log line with some string), and only one
formatv-style. It would be easy to add LLDB_WARN, LLDB_ERR, etc.
macros, so that these usages can be ported to the formatv-style.
However, I am not sure whether that's really necessary. One of the
goals of this process could be to standardize on one function. I would
prefer to keep just one log function, but I could be easily convinced
otherwise. For reference, these are the current approximate usages of
the logging functions (as determined by grep)
log->Error: 38 (mostly in ProcessWindows)
log->Warning: 25
log->Debug: 10 (mostly ClangExpressionParser)
log->Verbose: 6 (only ProcessWindows)
log->Printf: 2884

- ProcessWindowsLog: I am not going to go on a reformatting spree to
change all logging statements, but I would still like to change remove
the logging macros that windows log introduced, since they are very
custom, and I'd like to keep the number of logging syntaxes below 3
:). Zachary, Adrian, is that OK with you?



On 16 December 2016 at 20:15, Jim Ingham  wrote:
> Yeah, I’m with Jason.  I don’t find the current state of things hard to read 
> or work with.
>
> The proposed solutions seem a little uglier to me.  I try to avoid macros, to 
> me it makes it look like the code is shouting at you, giving the log lines 
> more prominence then they deserve in the overall flow of the code.  And all 
> upper case is harder to read.  If accumulating the log involves substantial 
> code and the code is all in macros it won’t be debuggable, which is a minor 
> shame.  But it’s not a huge deal since you can move the the code out of the 
> log statement temporarily if you need to debug it.

As it stands now, you'll still be able to write if(log) blocks. I
would also recommend this style for consideration:
LLDB_LOG(log, "current complex state is: {0}", GetCurrentComplexState());
- it does not interfere with the flow of the containing function, as
it is succinct, and you can still step through the complex function.

>
> I don’t see the need to work on this, but if it bugs you and you have the 
> time to do it, the moieties weigh evenly enough that I can’t see a reason to 
> object.

I must confess have a bit of an ulterior motive for doing this. :) My
goal is to start working on the modularization of the codebase. But I
don't want it to be just mindless moving of code around. I want to
spend some time considering the design of each piece, which should
slow things down long enough for the moves to not be annoying, and
hopefully produce better components. I'll write more on that soon - I
don't want to derail this discussion with it.

And yeah, the current logging state has been bugging me for a long time. ;)

cheers,
pl
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

Yeah, I’m with Jason.  I don’t find the current state of things hard to read or 
work with.  

The proposed solutions seem a little uglier to me.  I try to avoid macros, to 
me it makes it look like the code is shouting at you, giving the log lines more 
prominence then they deserve in the overall flow of the code.  And all upper 
case is harder to read.  If accumulating the log involves substantial code and 
the code is all in macros it won’t be debuggable, which is a minor shame.  But 
it’s not a huge deal since you can move the the code out of the log statement 
temporarily if you need to debug it.

I don’t see the need to work on this, but if it bugs you and you have the time 
to do it, the moieties weigh evenly enough that I can’t see a reason to object.

Jim

> On Dec 15, 2016, at 4:01 PM, Jason Molenda  wrote:
> 
> Hi Pavel, sorry for not keeping up with the thread, I've been super busy all 
> this week.  I'm not going to object to where this proposal has ended up.  I 
> personally have a preference for the old system but not based on any 
> justifiable reasons.
> 
> 
>> On Dec 15, 2016, at 7:13 AM, Pavel Labath  wrote:
>> 
>> Just to let you know, I will be on vacation until the end of the year,
>> so probably will not respond to any comments until January. If you
>> have any concerns, do let me know, as I'd like to get started when I
>> get back.
>> 
>> pl
>> 
>> On 13 December 2016 at 16:32, Pavel Labath  wrote:
>>> Hello again,
>>> 
>>> I'd to get back to the question of unifying llvm's and lldb's logging
>>> mechanisms that Chris asked about. In the way these two are
>>> implemented now, they have a number of similarities, but also a number
>>> of differences. Among the differences, there is one that I think will
>>> be most painful to resolve, so I'll start with that one:
>>> 
>>> I am talking about how to disable logging at compile-time. Currently,
>>> llvm's logging mechanism can be controlled both at runtime and
>>> compile-time. lldb's can be only controlled at runtime. While we may
>>> not want/need the compile-time knob, it is a very hard requirement for
>>> llvm, which tries to squeeze every ounce of performance from the
>>> hardware. So, if we are going to have a common logging API, we will
>>> need to support being compiled without it.
>>> 
>>> This has impact on the kind of syntax we are able to use. I see two
>>> problems here.
>>> 
>>> 1. The first one is that our log patterns are split into independent
>>> parts. Currently the pattern is:
>>> Log *log = GetLogIf(Flag);
>>> ...
>>> if (log) log->Printf(...);
>>> 
>>> The API we (mostly?) converged to above is:
>>> Log *log = GetLogIf(Flag);
>>> ...
>>> LLDB_LOG(log, ...);
>>> 
>>> If we want to compile the logging away, getting rid of the second part
>>> is easy, as it is already a macro. However, for a completely clean
>>> compile, we would need to remove the first part as well. Since
>>> wrapping it in #ifdef would be too ugly, I think the easiest solution
>>> would be to just make it go away completely.
>>> 
>>> The way I understand it, the reason we do it in two steps now is to
>>> make the code fast if logging is off. My proposal here would be to
>>> make the code very fast even without the additional local variable. If
>>> we could use the macro like:
>>> LLDB_LOG(Flag, ...)
>>> where the macro would expand to something like:
>>> if (LLVM_UNLIKELY(Flag & lldb_private::enabled_channels)) log_stuff(...)
>>> where `enabled_channels` is just a global integral variable then the
>>> overhead of a disabled log statement would be three instructions
>>> (load, and, branch), some of which could be reused if we had more
>>> logging statements in a function. Plus the macro could hint the cpu
>>> and compiler to optimize for the "false" case. This is still an
>>> increase over the status quo, where the overhead of a log statement is
>>> one or two instructions, but I am not sure if this is significant.
>>> 
>>> 2. The second, and probably bigger, issue is the one mentioned by
>>> Jason earlier in this thread -- the ability to insert random code into
>>> if(log) blocks. Right writing the following is easy:
>>> if (log) {
>>> do_random_stuff();
>>> log->Printf(...);
>>> }
>>> 
>>> In the first version of the macro, this is still easy to write, as we
>>> don't have to worry about compile-time. But if we need this to go
>>> away, we will need to resort to the same macro approach as llvm:
>>> LLDB_DEBUG( { do_random_stuff(); LLDB_LOG(...); });
>>> Which has all the disadvantages Jason mentioned. Although, I don't
>>> think this has to be that bad, as we probably will not be doing this
>>> very often, and the issues can be mitigated by putting the actual code
>>> in a function, and only putting the function calls inside the macro.
>>> 
>>> 
>>> 
>>> So, my question to you is: Do you think these two drawbacks are worth
>>> sacrificing for the sake of having a unified llvm-wide logging

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

Hello again,

I'd to get back to the question of unifying llvm's and lldb's logging
mechanisms that Chris asked about. In the way these two are
implemented now, they have a number of similarities, but also a number
of differences. Among the differences, there is one that I think will
be most painful to resolve, so I'll start with that one:

I am talking about how to disable logging at compile-time. Currently,
llvm's logging mechanism can be controlled both at runtime and
compile-time. lldb's can be only controlled at runtime. While we may
not want/need the compile-time knob, it is a very hard requirement for
llvm, which tries to squeeze every ounce of performance from the
hardware. So, if we are going to have a common logging API, we will
need to support being compiled without it.

This has impact on the kind of syntax we are able to use. I see two
problems here.

1. The first one is that our log patterns are split into independent
parts. Currently the pattern is:
Log *log = GetLogIf(Flag);
...
if (log) log->Printf(...);

The API we (mostly?) converged to above is:
Log *log = GetLogIf(Flag);
...
LLDB_LOG(log, ...);

If we want to compile the logging away, getting rid of the second part
is easy, as it is already a macro. However, for a completely clean
compile, we would need to remove the first part as well. Since
wrapping it in #ifdef would be too ugly, I think the easiest solution
would be to just make it go away completely.

The way I understand it, the reason we do it in two steps now is to
make the code fast if logging is off. My proposal here would be to
make the code very fast even without the additional local variable. If
we could use the macro like:
LLDB_LOG(Flag, ...)
where the macro would expand to something like:
if (LLVM_UNLIKELY(Flag & lldb_private::enabled_channels)) log_stuff(...)
where `enabled_channels` is just a global integral variable then the
overhead of a disabled log statement would be three instructions
(load, and, branch), some of which could be reused if we had more
logging statements in a function. Plus the macro could hint the cpu
and compiler to optimize for the "false" case. This is still an
increase over the status quo, where the overhead of a log statement is
one or two instructions, but I am not sure if this is significant.

2. The second, and probably bigger, issue is the one mentioned by
Jason earlier in this thread -- the ability to insert random code into
if(log) blocks. Right writing the following is easy:
if (log) {
  do_random_stuff();
  log->Printf(...);
}

In the first version of the macro, this is still easy to write, as we
don't have to worry about compile-time. But if we need this to go
away, we will need to resort to the same macro approach as llvm:
LLDB_DEBUG( { do_random_stuff(); LLDB_LOG(...); });
Which has all the disadvantages Jason mentioned. Although, I don't
think this has to be that bad, as we probably will not be doing this
very often, and the issues can be mitigated by putting the actual code
in a function, and only putting the function calls inside the macro.



So, my question to you is: Do you think these two drawbacks are worth
sacrificing for the sake of having a unified llvm-wide logging
infrastructure? I am willing to drive this, and implement the llvm
side of things, but I don't want to force this onto everyone, if it is
not welcome. If you do not think this is a worthwhile investment then
I'd rather proceed with the previous lldb-only solution we discussed
above, as that is something I am more passionate above, will already
be a big improvement, and a good stepping stone towards implementing
an llvm-wide solution in the future.

Of course, if you have alternative proposals on how to implement
llvm-wide logging, I'd love to hear about it.

Let me know what you think,
pavel
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Zachary Turner via lldb-dev]

Chiming in over here to say that I put up a revision
 which adds formatv support to various
parts of llvm.  Along with this, I've provided a formatter for `FileSpec`
so that we can now print FileSpecs as easily as we would print integers,
with various options for printing directory, filename, etc.

I think it helps to see some concrete instances of how this can help us,
rather than just focusing on the unfamiliar syntax.  Greg LGTM'ed it, but
since I know there was at least one concern over on this side, I'll wait a
few days to see if the objections still remain after seeing it in action.
I'll be checking here and the code review thread for comments.

On Fri, Dec 9, 2016 at 7:39 AM Zachary Turner  wrote:

> On Fri, Dec 9, 2016 at 7:36 AM Zachary Turner  wrote:
>
>
> On Fri, Dec 9, 2016 at 4:00 AM Jason Molenda via Phabricator <
> revi...@reviews.llvm.org> wrote:
>
>
> I'm not thrilled with the formatv reinvention of format specification.
> The printf formatters are a bizarre little invention, but it's a bizarre
> invention that we've all worked with for decades and everyone who works in
> C knows well.  The formatv format specification may be superior, but I
> don't want to see innovation here, I want clarity with the linga franca
> that every C programmer knows.  I think the barrier to adopting something
> non-standard is very high.
>
> While everyone knows it well, somehow it's still complicated enough that
> its usage is riddled with errors.  I can't even count the number of bugs
> I've fixed related to incorrect usage of format specifiers.
>
>
>
> The formatv format specification string seems to explicitly mention the
> ordering of the arguments, like llvm::formatv("{0} {1} {2}", first, second,
> third).  I'm guessing this allows you to print the arguments in different
> order than they appear?  Like  llvm::formatv("{0} {2} {2} {1}", first,
> second, third)?  What's the benefit of this vrs. the uncertainty of which
> arguments are used in different parts of the string (short of counting them
> out by hand)?  If I have a formatv format specification like "{0} {1} {2}
> {3} {4}" and I want to insert an argument between 2 and 3, I need to
> renumber 3 and 4 now?  Or do I do "{0} {1} {2} {5} {3} {4}" and throw my
> argument on to the end?
>
> Either / or would be fine.  BTW, this is not the primary advantage of
> having the arguments be numbered.  The primary advantage is that it allows
> you to print the same argument multiple times without computing it.
> formatv("{0} {0} {0}", 7);   will print "7 7 7".
>
>
> I guess I should elaborate.  The *real* primary advantage is simply not
> specifying the format specifier at all.  When you have to match the format
> specifier to the type of the argument you've already lost the battle,
> because you've introduced a source of programmer error.  And not just a
> hypothetical source either, considering the number of bugs I've fixed in
> incorrect usage of format specifiers.
>
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Zachary Turner via lldb-dev]

On Fri, Dec 9, 2016 at 4:00 AM Jason Molenda via Phabricator <
revi...@reviews.llvm.org> wrote:

>
> I'm not thrilled with the formatv reinvention of format specification.
> The printf formatters are a bizarre little invention, but it's a bizarre
> invention that we've all worked with for decades and everyone who works in
> C knows well.  The formatv format specification may be superior, but I
> don't want to see innovation here, I want clarity with the linga franca
> that every C programmer knows.  I think the barrier to adopting something
> non-standard is very high.
>
While everyone knows it well, somehow it's still complicated enough that
its usage is riddled with errors.  I can't even count the number of bugs
I've fixed related to incorrect usage of format specifiers.


>
> The formatv format specification string seems to explicitly mention the
> ordering of the arguments, like llvm::formatv("{0} {1} {2}", first, second,
> third).  I'm guessing this allows you to print the arguments in different
> order than they appear?  Like  llvm::formatv("{0} {2} {2} {1}", first,
> second, third)?  What's the benefit of this vrs. the uncertainty of which
> arguments are used in different parts of the string (short of counting them
> out by hand)?  If I have a formatv format specification like "{0} {1} {2}
> {3} {4}" and I want to insert an argument between 2 and 3, I need to
> renumber 3 and 4 now?  Or do I do "{0} {1} {2} {5} {3} {4}" and throw my
> argument on to the end?
>
Either / or would be fine.  BTW, this is not the primary advantage of
having the arguments be numbered.  The primary advantage is that it allows
you to print the same argument multiple times without computing it.
formatv("{0} {0} {0}", 7);   will print "7 7 7".


> If formatv could take something a LOT closer to printf, I'd be better with
> it.  Something like the python string formatters would be a real
> improvement - just %d for base 10 numbers, not having to worry about the
> size of the argument in the format string, for instance, and would still be
> readable & understandable by any C programmer out there.
>
I don't think familiarity with C is a compelling argument.  We're using C++
here, and the more C-isms we can get rid of the better, as long as there is
a compelling advantage.

BTW, you mentioned Python, but incidentally the %d %s style of string
formatting in Python is not recommended (being considered the "old" way),
and is replaced with a "new" way which, it turns out, is almost identical
to the syntax of formatv  (along with C#, Python is where I took
inspiration from in designing it)


Aside from the points mentioned above, formatv has some other nice
advantages.

1) Instead of silently compiling your code and then segfaulting when you
pass a type that printf doesn't know how to format, formatv will report a
helpful compiler error.

2) It allows you to write formatters for user-defined types, so that
instead of re-inventing this every time you write a format line, and
potentially passing many arguments to printf, you can pass one argument to
formatv, and have consistency in every single log line where you ever try
to print this.


Aside from not being familiar to C programmers, I believe it to be better
in every possible way.

On Fri, Dec 9, 2016 at 4:19 AM Pavel Labath  wrote:

> There were additional comments on the lldb-commits thread. I am moving
> them here and responding:
>
> Jason Molenda wrote on the lldb-commits thread:
> > A couple of thoughts / two cents.
> > I don't mind the current if (log) { ... } style of logging, even with
> the PRIx64's and having to do filepath.GetPath().c_str() and all that. I
> like being able to do extra work in a if (log) block of code -- create a
> SymbolContext for something or whatever, and as I'm debugging that section
> of code I like to be able to put a breakpoint there and look more closely.
> If this is all in a preprocessor macro, a breakpoint is going to stop me on
> the if() and then I'm trying to step through a macro? And if my computation
> is down in a lambda I need to figure out how to put a breakpoint in that or
> step into that somehow to look at the values being computed. How do I
> create a SymbolContext my_symctx(...); and then include that in what I log
> if I have to do all of this in the formatv arguments?
>
> I am not proposing we completely eliminate the ability to do have
> blocks of code that run only when logging is enabled. I recognize that
> there are situations where that is necessary. However, 99% of our
> current logging code does not do that, and I am trying to reduce the
> footprint of that. So, I don't think you have to worry about this use
> case.
>
> > I'm not thrilled with the formatv reinvention of format specification.
> The printf formatters are a bizarre little invention, but it's a bizarre
> invention that we've all worked with for decades and everyone who works in
> C knows well. The formatv format specification may be 

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

There were additional comments on the lldb-commits thread. I am moving
them here and responding:

Jason Molenda wrote on the lldb-commits thread:
> A couple of thoughts / two cents.
> I don't mind the current if (log) { ... } style of logging, even with the 
> PRIx64's and having to do filepath.GetPath().c_str() and all that. I like 
> being able to do extra work in a if (log) block of code -- create a 
> SymbolContext for something or whatever, and as I'm debugging that section of 
> code I like to be able to put a breakpoint there and look more closely. If 
> this is all in a preprocessor macro, a breakpoint is going to stop me on the 
> if() and then I'm trying to step through a macro? And if my computation is 
> down in a lambda I need to figure out how to put a breakpoint in that or step 
> into that somehow to look at the values being computed. How do I create a 
> SymbolContext my_symctx(...); and then include that in what I log if I have 
> to do all of this in the formatv arguments?

I am not proposing we completely eliminate the ability to do have
blocks of code that run only when logging is enabled. I recognize that
there are situations where that is necessary. However, 99% of our
current logging code does not do that, and I am trying to reduce the
footprint of that. So, I don't think you have to worry about this use
case.

> I'm not thrilled with the formatv reinvention of format specification. The 
> printf formatters are a bizarre little invention, but it's a bizarre 
> invention that we've all worked with for decades and everyone who works in C 
> knows well. The formatv format specification may be superior, but I don't 
> want to see innovation here, I want clarity with the linga franca that every 
> C programmer knows. I think the barrier to adopting something non-standard is 
> very high.
> The formatv format specification string seems to explicitly mention the 
> ordering of the arguments, like llvm::formatv("{0} {1} {2}", first, second, 
> third). I'm guessing this allows you to print the arguments in different 
> order than they appear? Like llvm::formatv("{0} {2} {2} {1}", first, second, 
> third)? What's the benefit of this vrs. the uncertainty of which arguments 
> are used in different parts of the string (short of counting them out by 
> hand)? If I have a formatv format specification like "{0} {1} {2} {3} {4}" 
> and I want to insert an argument between 2 and 3, I need to renumber 3 and 4 
> now? Or do I do "{0} {1} {2} {5} {3} {4}" and throw my argument on to the end?
> Simply *ability* to put the arguments in any order is my concern. Of course 
> I'm never going to do it, but I'm going to have to work on code where other 
> people have done it.

I think being able to refer to arguments directly i'a useful feature
to have in some circumstances (printf also allows it, although with a
syntax I always have to look up when I need it), but I agree it should
be used sparingly. I don't think anyone will put the arguments out of
order just for the fun of it. We can make that an official policy
somewhere, if you're worried about it. I guess one of the reasons for
the simplicity of the design was to only support the direct-reference
versions (I admit I originally also though I could just write {}, and
get the arguments in order).

FWIW, if I had a printf statement with more than five arguments, I'd
also have to count them by hand to make sure I got them matched right,
especially if PRIx64's get involved.

> I don't personally want to see the file / function / line numbers in my 
> logging. It's fine if that's an option that other people can enable if they 
> want it. There's going to be a growth in the size of our text for the 
> constant strings for every log point having its filename and function, but it 
> will probably not be significant (maybe the strings can be coalesced, I 
> wouldn't bet one way or the other.)

I am not sure what what be a good way to try this out, but I wouldn't
be surprised if the overall size effect of this was a reduction in
binary size -- the thing is, most of our logging statements contain
this information already, but it's a part of the format string, so it
definitely cannot be coalesced. If they were referenced as __FILE__,
any sane compiler/linker will merge those references into a single
string constant.

I am not sure which part of the code base you are working with mostly,
but in my experience most code adds file/function information already
(RegisterContextLLDB seems to be the exception), and you have no way
of turning it off. Currently we are going toward making that optional,
so this would be an improvement in that regard as well.


> If formatv could take something a LOT closer to printf, I'd be better with 
> it. Something like the python string formatters would be a real improvement - 
> just %d for base 10 numbers, not having to worry about the size of the 
> argument in the format string, for instance, and would still be readable & 
> 

Re: [lldb-dev] logging in lldb

[Adrian McCarthy via lldb-dev]

> (of those, 7 print the *wrong* function name)

I think this is the best argument for automating the source information as
much as possible.  Refactoring moves stretches of code into new functions.
Log lines get copy and pasted.  Like comments, the fixed text in the log
lines easily gets out of date, which can make reading a log even harder.

If people want the ability to opt-out of source info on certain log lines,
I could live with that.  But I favor default-on and automatically generated
source info.

On Thu, Dec 8, 2016 at 6:46 AM, Pavel Labath via lldb-dev <
lldb-dev@lists.llvm.org> wrote:

> Hello again,
>
> I have updated the example code to reflect some of the results from
> this discussion. I think we are generally converging XXX, I am going
> to try to summarize it here, to see if we have any issues left to
> discuss.
>
> - everyone seemed to prefer the formatv-based api, so that should be
> the main API going forward. Printf will need to be maintained until
> all users are migrated. I have updated by example to use that.
>
> - there were concerns about performance characteristics of this in the
> case logging is disabled. I'd like to reiterate that this is one of my
> design goals, and the new proposed API has the same overhead (checking
> for nullness of a local variable) as the current one.
>
> - Related to the previous item, Jim was worried about the usage of a
> macro will hide the fact that macro will hide the fact that the
> performance impact of the logging is small. I replied that anyone
> caring about performance that much will be familiar with this already.
> I also think this is no different than what a lot of other logging
> systems do already  -- llvm's DEBUG(), assert(), boost::log all
> evaluate their arguments only if they are "enabled" (whatever that
> meant exactly), even though the call presents itself as a simple
> macro.
> I am not sure whether this topic is closed. Does anyone want to add
> anything to this?
>
> - there was a discussion about automatically adding log source
> information. My original proposal added it unconditionally. Greg
> suggested we make that optional (similar to how we optionally prepend
> timestamp, thread id, ...). Jim was worried that adding the extra data
> will make hamper readability of the logs. I disagreed.
> Having the source information be optional sounds like a good idea (i'd
> propose to make it on by default, as a log of log lines don't make
> sense without it: "__FUNCTION__ called with signal %d" and similar). I
> am not sure whether this answers Jim's concerns though. Jim, what do
> you say to that? If this would be enough (disabling source information
> on a global level), then great. If not, then we can come up with a way
> to suppress this information on a per-call-site basis. Something like:
> LLGB_LOG_SUPP(log, LogInfo::Source, ...)
> where the second argument would be the list of things to suppress for
> this log line.
>
> BTW, I have done some statistics on a semi-randomly chosen file
> ThreadPlanCallFunction.cpp: This file contains 19 logging statements.
> Of those, 10 print the class name, 8 print the class and function name
> (of those, 7 print the *wrong* function name), and there is only two
> that do not print any source information. One of these prints a table
> of registers, so it could so it could suffer from readability
> problems. However, it does this by printing all registers to a
> temporary stream, and then printing that stream. Since the prepending
> would only add the source before the first line of the log, this could
> be another way to sidestep this problem (just output "\n" before your
> multi-line string). All the other log statements in this file would
> benefit from standardizing on the source printing IMO, as that would
> mean we can actually align things correctly, and visually separate the
> repetitive part (which is already present most of the time), and
> variable part.
> What do you think of that?
>
> - Chris suggested merging lldb and llvm logging infrastructure. I have
> given this some thought, and I think it is possible, although it will
> make the implementation more tricky. I will write a separate email
> about that, but I want to give it more thought (and also, the proposal
> might depend on the exact set of requirements we converge on here).
>
> - anything else I missed?
>
> Cheers,
> pl
> ___
> lldb-dev mailing list
> lldb-dev@lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev
>
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

Hello again,

I have updated the example code to reflect some of the results from
this discussion. I think we are generally converging XXX, I am going
to try to summarize it here, to see if we have any issues left to
discuss.

- everyone seemed to prefer the formatv-based api, so that should be
the main API going forward. Printf will need to be maintained until
all users are migrated. I have updated by example to use that.

- there were concerns about performance characteristics of this in the
case logging is disabled. I'd like to reiterate that this is one of my
design goals, and the new proposed API has the same overhead (checking
for nullness of a local variable) as the current one.

- Related to the previous item, Jim was worried about the usage of a
macro will hide the fact that macro will hide the fact that the
performance impact of the logging is small. I replied that anyone
caring about performance that much will be familiar with this already.
I also think this is no different than what a lot of other logging
systems do already  -- llvm's DEBUG(), assert(), boost::log all
evaluate their arguments only if they are "enabled" (whatever that
meant exactly), even though the call presents itself as a simple
macro.
I am not sure whether this topic is closed. Does anyone want to add
anything to this?

- there was a discussion about automatically adding log source
information. My original proposal added it unconditionally. Greg
suggested we make that optional (similar to how we optionally prepend
timestamp, thread id, ...). Jim was worried that adding the extra data
will make hamper readability of the logs. I disagreed.
Having the source information be optional sounds like a good idea (i'd
propose to make it on by default, as a log of log lines don't make
sense without it: "__FUNCTION__ called with signal %d" and similar). I
am not sure whether this answers Jim's concerns though. Jim, what do
you say to that? If this would be enough (disabling source information
on a global level), then great. If not, then we can come up with a way
to suppress this information on a per-call-site basis. Something like:
LLGB_LOG_SUPP(log, LogInfo::Source, ...)
where the second argument would be the list of things to suppress for
this log line.

BTW, I have done some statistics on a semi-randomly chosen file
ThreadPlanCallFunction.cpp: This file contains 19 logging statements.
Of those, 10 print the class name, 8 print the class and function name
(of those, 7 print the *wrong* function name), and there is only two
that do not print any source information. One of these prints a table
of registers, so it could so it could suffer from readability
problems. However, it does this by printing all registers to a
temporary stream, and then printing that stream. Since the prepending
would only add the source before the first line of the log, this could
be another way to sidestep this problem (just output "\n" before your
multi-line string). All the other log statements in this file would
benefit from standardizing on the source printing IMO, as that would
mean we can actually align things correctly, and visually separate the
repetitive part (which is already present most of the time), and
variable part.
What do you think of that?

- Chris suggested merging lldb and llvm logging infrastructure. I have
given this some thought, and I think it is possible, although it will
make the implementation more tricky. I will write a separate email
about that, but I want to give it more thought (and also, the proposal
might depend on the exact set of requirements we converge on here).

- anything else I missed?

Cheers,
pl
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

Sorry, I have been derailed today by trying to make format member
detection work more reasonably. I plan to come up with the next
iteration of the proposal soon, but I am not sure if it will be today,
as it is quite late here already. I do think this needs to be done in
incremental steps, but I'd like to make the iterations slightly bigger
to avoid code churn.

pl

On 7 December 2016 at 16:56, Zachary Turner  wrote:
> Pavel: You might start this effort to improve logging by just adding a
> Formatv member function to log to replace printf.
>
> I suspect many call sites would be made much less verbose this way. I think
> we'll still need to do the rest too, but this seems like the least amount of
> work to make incremental progress
> On Tue, Dec 6, 2016 at 11:13 AM Zachary Turner  wrote:
>>
>> On Tue, Dec 6, 2016 at 10:31 AM Greg Clayton  wrote:
>>>
>>>
>>>
>>>
>>> It should be a formatter option for collections to allow you to print out
>>> different ranges. If I have a target and a target knows how to print the
>>> process and the process knows how to print the threads and the threads know
>>> how to print the stack frames, it doesn't mean I always want to see
>>> everything. Sounds like we can easily control this in the llvm::formatv case
>>> with extra formatting options:
>>>
>>> This might print just a summary of the target:
>>>
>>> llvm::formatv("{0}", target);
>>>
>>> This might print the target and info about the process:
>>>
>>> llvm::formatv("{0;process}", target);
>>>
>>> The question becomes, can we then forward arguments into the "Process"
>>> logger to control if the threads are displayed?
>>>
>>> llvm::formatv("{0;process{threads{frames}}}", target);
>>>
>>> This would allow recursive formatters to be called with specified
>>> arguments. Just a thought, but if we are going to delve into recursive
>>> formatters, we might need to think about that.
>>
>>
>> A formatter can literally do anything with the style string.  So for
>> example, suppose you have formatters defined for Process and Thread.  each
>> of these ultimately boils down to a function:
>>
>> void format(llvm::raw_ostream , const Process , StringRef Style);
>> void format(llvm::raw_ostream , const Thread , StringRef Style);
>>
>> We implement each of these, so Process can define its own Style language,
>> as can Target, as can Thread.  We can come up with something better than
>> this, but say for the sake of illustration Thread's style string worked like
>> this: If empty, print thread id, otherwise treat each alphabetic character
>> as representing a "code" of what to print.  P = process, T = thread id, N =
>> thread name.  So "P - T - N" would print the process id, then the thread id,
>> then the thread name, separated by dashes.
>>
>> Now suppose you want to print a process.  If style string is empty, it
>> prints only the process id, otherwise if it equals T then it prints the
>> first thread, or if it equals T* it prints all threads.  T or T* can
>> optionally be followed by arguments to forward to the thread in square
>> brackets.  So you could have:
>>
>> formatv("Process {0;P - T*[N]}", process);
>>
>> There's obviously a balance between flexibility and conciseness, but I
>> guess that's no different than C++.  It's as flexible as you could possibly
>> need, sometimes to the point of allowing you to make bad design decisions :)
>>
>> In the beginning probably best to just define some simple formatters that
>> don't do anything recursive, and then some obvious patterns might start to
>> fall out and we can refine the styles we support for all of the various LLDB
>> types.
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Zachary Turner via lldb-dev]

On Tue, Dec 6, 2016 at 10:31 AM Greg Clayton  wrote:

>
>
>
> It should be a formatter option for collections to allow you to print out
> different ranges. If I have a target and a target knows how to print the
> process and the process knows how to print the threads and the threads know
> how to print the stack frames, it doesn't mean I always want to see
> everything. Sounds like we can easily control this in the llvm::formatv
> case with extra formatting options:
>
> This might print just a summary of the target:
>
> llvm::formatv("{0}", target);
>
> This might print the target and info about the process:
>
> llvm::formatv("{0;process}", target);
>
> The question becomes, can we then forward arguments into the "Process"
> logger to control if the threads are displayed?
>
> llvm::formatv("{0;process{threads{frames}}}", target);
>
> This would allow recursive formatters to be called with specified
> arguments. Just a thought, but if we are going to delve into recursive
> formatters, we might need to think about that.
>

A formatter can literally do anything with the style string.  So for
example, suppose you have formatters defined for Process and Thread.  each
of these ultimately boils down to a function:

void format(llvm::raw_ostream , const Process , StringRef Style);
void format(llvm::raw_ostream , const Thread , StringRef Style);

We implement each of these, so Process can define its own Style language,
as can Target, as can Thread.  We can come up with something better than
this, but say for the sake of illustration Thread's style string worked
like this: If empty, print thread id, otherwise treat each alphabetic
character as representing a "code" of what to print.  P = process, T =
thread id, N = thread name.  So "P - T - N" would print the process id,
then the thread id, then the thread name, separated by dashes.

Now suppose you want to print a process.  If style string is empty, it
prints only the process id, otherwise if it equals T then it prints the
first thread, or if it equals T* it prints all threads.  T or T* can
optionally be followed by arguments to forward to the thread in square
brackets.  So you could have:

formatv("Process {0;P - T*[N]}", process);

There's obviously a balance between flexibility and conciseness, but I
guess that's no different than C++.  It's as flexible as you could possibly
need, sometimes to the point of allowing you to make bad design decisions :)

In the beginning probably best to just define some simple formatters that
don't do anything recursive, and then some obvious patterns might start to
fall out and we can refine the styles we support for all of the various
LLDB types.
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

> On Dec 6, 2016, at 10:20 AM, Pavel Labath  wrote:
> 
>> 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.
> 
> What I am optimizing for is readability of the source code (the fact
> that it coincides with "the time to write the log statement" is a
> lucky coincidence). I often find that I am looking at a function which
> spans several screens, even though it doesn't actually do much,
> because half of the function is logging. Normally, I would try to
> split this function up into smaller ones, but I find that the amount
> of work done by the function is actually quite reasonable and
> undivisible, but due to logging it gets spread out enormously.
> 
> I would be fine with some way of inhibiting decorations. But, I want
> to hear what you think about this alternative: Just have file names
> and line numbers always aligned. For lines, we could reserve four
> characters, for filenames 35 (only 7 files currently are longer than
> 35 chars -- these would get truncated, or misaligned, as you see fit).
> 

Take a look at the step logs, for instance, which I have to read all the time.  
In that case, when reading them you are trying to follow the logical flow of 
the stepping algorithm, and there is already a lot of noise there.  In that 
case, I don't need to know where the log lines come from, that is clear from 
the log content.  So I definitely not want to have to peer past useless file & 
line or function information.

And more generally, I do think prioritizing ease of reading (or scrolling past) 
log statements in code over ease of making them complete and easy to read them 
is the wrong tradeoff.  The number of hours of my life that have gone into 
peering at logs far outweighs the trouble of scrolling past "if(log)" blocks 
when reading code.  If both goals can be achieved, that's great.  And for 
simple "X was weird" kind of logs, having a nice compact form is great.  But 
for things like the unwind logs, packet, step or expression logs, you don't 
want anything getting in the way of laying out the output in the easiest to 
read form possible.

Jim

___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Greg Clayton via lldb-dev]

> On Dec 6, 2016, at 10:20 AM, Pavel Labath  wrote:
> 
> On 6 December 2016 at 17:39, Jim Ingham  wrote:
>> 
>>> On Dec 6, 2016, at 8:23 AM, Pavel Labath  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.
> Fair enough. llvm::formatv() (see lldb-commits thread, we seem do have
> diverged a bit...) should satisfy both of these requirements
> ("monolithic strings" and "not-streams"). Would you be OK with that?
> (BTW, having a file+function name in each log message makes it easier
> to find the source)
> 

That would be a great option to add to "log enable"!

>> 
>> 
>>> 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.
> 
> What I am optimizing for is readability of the source code (the fact
> that it coincides with "the time to write the log statement" is a
> lucky coincidence). I often find that I am looking at a function which
> spans several screens, even though it doesn't actually do much,
> because half of the function is logging. Normally, I would try to
> split this function up into smaller ones, but I find that the amount
> of work done by the function is actually quite reasonable and
> undivisible, but due to logging it gets spread out enormously.
> 
> I would be fine with some way of inhibiting decorations. But, I want
> to hear what you think about this alternative: Just have file names
> and line numbers always aligned. For lines, we could reserve four
> characters, for filenames 35 (only 7 files currently are longer than
> 35 chars -- these would get truncated, or misaligned, as you see fit).
> 
I would like this to be an option you can enable and not require it to be on.

> 
>> 
>>> 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 would assume people who care about performance to this level will be
> familiar with the performance characteristics of logging. For me this
> potential confusion is less important than making the code flow
> nicely, although I see how you may have different opinion.

Different parts of the code do different amounts of logging. The expression 
parses is quite verbose in its logging, but this logging is required to figure 
out bugs that people run into.

> 
>>> - 

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

On 6 December 2016 at 17:39, Jim Ingham  wrote:
>
>> On Dec 6, 2016, at 8:23 AM, Pavel Labath  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.
Fair enough. llvm::formatv() (see lldb-commits thread, we seem do have
diverged a bit...) should satisfy both of these requirements
("monolithic strings" and "not-streams"). Would you be OK with that?
(BTW, having a file+function name in each log message makes it easier
to find the source)


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

What I am optimizing for is readability of the source code (the fact
that it coincides with "the time to write the log statement" is a
lucky coincidence). I often find that I am looking at a function which
spans several screens, even though it doesn't actually do much,
because half of the function is logging. Normally, I would try to
split this function up into smaller ones, but I find that the amount
of work done by the function is actually quite reasonable and
undivisible, but due to logging it gets spread out enormously.

I would be fine with some way of inhibiting decorations. But, I want
to hear what you think about this alternative: Just have file names
and line numbers always aligned. For lines, we could reserve four
characters, for filenames 35 (only 7 files currently are longer than
35 chars -- these would get truncated, or misaligned, as you see fit).


>
>> 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 would assume people who care about performance to this level will be
familiar with the performance characteristics of logging. For me this
potential confusion is less important than making the code flow
nicely, although I see how you may have different opinion.

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

Re: [lldb-dev] logging in lldb

[Greg Clayton via lldb-dev]

I like the the llvm::formatv stuff and could see using this exclusively. I am 
getting scared of using streams and << the more I think about it after my 
previous email since we would need to mark a log message as starting and ending 
somehow and that would make things messy.

Note that our logging has many options:

(lldb) help log enable
 Enable logging for a single log channel.

Syntax: log enable[ 
[...]]

Command Options Usage:
  log enable [-STagnpstv] [-f ]   
[ [...]]

   -S ( --stack )
Append a stack backtrace to each log line.

   -T ( --timestamp )
Prepend all log lines with a timestamp.

   -a ( --append )
Append to the log file instead of overwriting.

   -f  ( --file  )
Set the destination file to log to.

   -g ( --debug )
Enable debug logging.

   -n ( --thread-name )
Prepend all log lines with the thread name for the thread that 
generates the log line.

   -p ( --pid-tid )
Prepend all log lines with the process and thread ID that generates 
the log line.

   -s ( --sequence )
Prepend all log lines with an increasing integer sequence id.

   -t ( --threadsafe )
Enable thread safe logging to avoid interweaved log lines.

   -v ( --verbose )
Enable verbose logging.
 

So we will need to be able to do each of these with each log line. Streams will 
make things messy. 

Greg



> On Dec 6, 2016, at 10:07 AM, Zachary Turner via lldb-dev 
>  wrote:
> 
> Merging the thread over from lldb-commits:
> 
> 
> 
> On Tue, Dec 6, 2016 at 9:57 AM Jim Ingham via Phabricator 
>  wrote:
> jingham added a comment.
> 
> I not infrequently have some non-trivial code in the "if (log)" block that 
> gathers the information that I am then going to print, or loops over entities 
> printing them.  Putting more complex code like that inside a macro looks 
> awful and is hard to debug.  I don't think that argues for not using the 
> macros in the case where you are logging a simple string, but it does argue 
> for keeping the old way available.
> Not arguing against keeping the old way possible, but as an aside, 
> llvm::formatv() can handle many of these cases pretty nicely.
> 
> For starters, it has builtin support for formatting ranges.  So if you're 
> ever looping over entities formatting them, as long as the entity itself has 
> a formatter defined, you can simply pass it directly to formatv and it will 
> do the right thing.  (It has some customization support built in as well so 
> you can control how to separate items).
> 
> Secondly, When you have to do some work to get the value you want to format, 
> you could either define a custom formatter for the type in question, and the 
> formatter does all the work, or you could write a function to return the 
> value you want to format, and call that in the argument list, as long as the 
> return type has an associated formatter.
> 
> I'm sure there will still be cases where you want to use the old method, but 
> I think this would handle quite a few of them and reduce the amount of code 
> you have to read / write when dealing with logging code.
> ___
> lldb-dev mailing list
> lldb-dev@lists.llvm.org
> http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

> On Dec 6, 2016, at 10:07 AM, Zachary Turner  wrote:
> 
> Merging the thread over from lldb-commits:
> 
> 
> 
> On Tue, Dec 6, 2016 at 9:57 AM Jim Ingham via Phabricator 
>  wrote:
> jingham added a comment.
> 
> I not infrequently have some non-trivial code in the "if (log)" block that 
> gathers the information that I am then going to print, or loops over entities 
> printing them.  Putting more complex code like that inside a macro looks 
> awful and is hard to debug.  I don't think that argues for not using the 
> macros in the case where you are logging a simple string, but it does argue 
> for keeping the old way available.
> Not arguing against keeping the old way possible, but as an aside, 
> llvm::formatv() can handle many of these cases pretty nicely.
> 
> For starters, it has builtin support for formatting ranges.  So if you're 
> ever looping over entities formatting them, as long as the entity itself has 
> a formatter defined, you can simply pass it directly to formatv and it will 
> do the right thing.  (It has some customization support built in as well so 
> you can control how to separate items).
> 
> Secondly, When you have to do some work to get the value you want to format, 
> you could either define a custom formatter for the type in question, and the 
> formatter does all the work, or you could write a function to return the 
> value you want to format, and call that in the argument list, as long as the 
> return type has an associated formatter.
> 
> I'm sure there will still be cases where you want to use the old method, but 
> I think this would handle quite a few of them and reduce the amount of code 
> you have to read / write when dealing with logging code.

I have had to do the "where the heck does this log line come from in the code" 
search many many times debugging external reports.  I worry a bit that anything 
that makes output more magical as you are suggesting also makes this task 
harder.  Again, IME you will write log code fairly infrequently, but you will 
grub around trying to figure out what the logs mean quite frequently.  So you 
always want to optimize for easy of use rather than of emission.

That being said, the formatv stuff does sound pretty cool.

Jim
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Zachary Turner via lldb-dev]

Merging the thread over from lldb-commits:



On Tue, Dec 6, 2016 at 9:57 AM Jim Ingham via Phabricator <
revi...@reviews.llvm.org> wrote:

> jingham added a comment.
>
> I not infrequently have some non-trivial code in the "if (log)" block that
> gathers the information that I am then going to print, or loops over
> entities printing them.  Putting more complex code like that inside a macro
> looks awful and is hard to debug.  I don't think that argues for not using
> the macros in the case where you are logging a simple string, but it does
> argue for keeping the old way available.
>
Not arguing against keeping the old way possible, but as an aside,
llvm::formatv() can handle many of these cases pretty nicely.

For starters, it has builtin support for formatting ranges.  So if you're
ever looping over entities formatting them, as long as the entity itself
has a formatter defined, you can simply pass it directly to formatv and it
will do the right thing.  (It has some customization support built in as
well so you can control how to separate items).

Secondly, When you have to do some work to get the value you want to
format, you could either define a custom formatter for the type in
question, and the formatter does all the work, or you could write a
function to return the value you want to format, and call that in the
argument list, as long as the return type has an associated formatter.

I'm sure there will still be cases where you want to use the old method,
but I think this would handle quite a few of them and reduce the amount of
code you have to read / write when dealing with logging code.
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

BTW, I just want to make it clear in this discussion that logging is a really 
important part of lldb.  This isn't a matter of "you had some debug logging you 
put in to solve a problem, and you didn't want to have to take it out next time 
you use it."  We very often get bugs from customers who can't reduce the 
problem to a small test case, and can't make their code available to us.  So 
logging is the only way you are ever going to solve this class of problems.  
Fortunately the logging in lldb is pretty good at present, and we have all 
often been able to solve this sort of problem on logging alone.

As you write code in lldb you should be thinking "If I had to figure out what 
was going on in some tricky circumstance, and all I had was this log, would I 
be able to figure it out."  And to this end, being able to output complex log 
messages is crucial.

Sorry if this is obvious to folks, but on the off chance it isn't, it's worth a 
few bytes to restate it.

Jim

> On Dec 6, 2016, at 9:39 AM, Jim Ingham via lldb-dev  
> wrote:
> 
>> 
>> On Dec 6, 2016, at 8:23 AM, Pavel Labath  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 

Re: [lldb-dev] logging in lldb

[Chris Bieneman via lldb-dev]

> On Dec 6, 2016, at 9:32 AM, Pavel Labath  wrote:
> 
> Ah, I totally forgot about the llvm DEBUG macro. I would be open to
> trying merge these two approaches together. However, I think our's is
> a much more heavy-weight system, so it might be too heavy for llvm,
> and I am not sure how much would we be willing to lose in the process:
> - we have two level logging architecture ("process" category in "lldb" 
> channel)

This might not map to LLVM, but it might be worth looking into.

> - logging can be enabled/disabled at runtime

This actually should be doable in LLVM. Since the LLVM DEBUG macro controls the 
-debug=... flag, I can't immediately see a reason why that wouldn't work for 
runtime toggling.

> - logs can be redirected to various destinations

The LLVM logging uses streams, so I don't think this is really different. You 
just change the stream under it.

-Chris

> 
> Maybe it will be possible to design it in a way that the complexity is
> apparent to those who wish to use it. I'll need to think about that...
> 
> pl
> 
> 
> On 6 December 2016 at 17:06, Chris Bieneman  wrote:
>> My only concern reading this is that LLVM already has a similar mechanism 
>> for channel-based logging that is used throughout the backends. Is there a 
>> reason to invent our own? Maybe we can take what is in LLVM, enhance it and 
>> use shared functionality?
>> 
>> There are a few differences between your solution and the LLVM one, but I'm 
>> not sure they are sufficient to justify creating a new solution.
>> 
>> The LLVM debug logging solution is documented in the LLVM Programmers Manual 
>> here:
>> http://llvm.org/docs/ProgrammersManual.html#the-debug-macro-and-debug-option
>> 
>> -Chris
>> 
>>> On Dec 6, 2016, at 8:57 AM, Pavel Labath  wrote:
>>> 
>>> On 6 December 2016 at 16:51, Jim Ingham  wrote:
 Sorry, I'm being dense.  What is Dx?
 
 Jim
 
> On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:
> 
> I have created straw-man implementation of such an interface in
> Dx, together with some examples of how it's used, and I'd like to
 
>>> 
>>> https://reviews.llvm.org/D27459 :D
>>> 
>>> Sorry, I forgot to replace this by actual revision when I submitted the 
>>> code.
>>> 
>>> pl
>> 

___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

> On Dec 6, 2016, at 8:23 AM, Pavel Labath  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
> Dx, 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 

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

Ah, I totally forgot about the llvm DEBUG macro. I would be open to
trying merge these two approaches together. However, I think our's is
a much more heavy-weight system, so it might be too heavy for llvm,
and I am not sure how much would we be willing to lose in the process:
- we have two level logging architecture ("process" category in "lldb" channel)
- logging can be enabled/disabled at runtime
- logs can be redirected to various destinations

Maybe it will be possible to design it in a way that the complexity is
apparent to those who wish to use it. I'll need to think about that...

pl


On 6 December 2016 at 17:06, Chris Bieneman  wrote:
> My only concern reading this is that LLVM already has a similar mechanism for 
> channel-based logging that is used throughout the backends. Is there a reason 
> to invent our own? Maybe we can take what is in LLVM, enhance it and use 
> shared functionality?
>
> There are a few differences between your solution and the LLVM one, but I'm 
> not sure they are sufficient to justify creating a new solution.
>
> The LLVM debug logging solution is documented in the LLVM Programmers Manual 
> here:
> http://llvm.org/docs/ProgrammersManual.html#the-debug-macro-and-debug-option
>
> -Chris
>
>> On Dec 6, 2016, at 8:57 AM, Pavel Labath  wrote:
>>
>> On 6 December 2016 at 16:51, Jim Ingham  wrote:
>>> Sorry, I'm being dense.  What is Dx?
>>>
>>> Jim
>>>
 On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:

 I have created straw-man implementation of such an interface in
 Dx, together with some examples of how it's used, and I'd like to
>>>
>>
>> https://reviews.llvm.org/D27459 :D
>>
>> Sorry, I forgot to replace this by actual revision when I submitted the code.
>>
>> pl
>
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

Ah, cool!  I'll have a look.

Jim

> On Dec 6, 2016, at 8:57 AM, Pavel Labath  wrote:
> 
> On 6 December 2016 at 16:51, Jim Ingham  wrote:
>> Sorry, I'm being dense.  What is Dx?
>> 
>> Jim
>> 
>>> On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:
>>> 
>>> I have created straw-man implementation of such an interface in
>>> Dx, together with some examples of how it's used, and I'd like to
>> 
> 
> https://reviews.llvm.org/D27459 :D
> 
> Sorry, I forgot to replace this by actual revision when I submitted the code.
> 
> pl

___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Chris Bieneman via lldb-dev]

My only concern reading this is that LLVM already has a similar mechanism for 
channel-based logging that is used throughout the backends. Is there a reason 
to invent our own? Maybe we can take what is in LLVM, enhance it and use shared 
functionality?

There are a few differences between your solution and the LLVM one, but I'm not 
sure they are sufficient to justify creating a new solution.

The LLVM debug logging solution is documented in the LLVM Programmers Manual 
here:
http://llvm.org/docs/ProgrammersManual.html#the-debug-macro-and-debug-option

-Chris

> On Dec 6, 2016, at 8:57 AM, Pavel Labath  wrote:
> 
> On 6 December 2016 at 16:51, Jim Ingham  wrote:
>> Sorry, I'm being dense.  What is Dx?
>> 
>> Jim
>> 
>>> On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:
>>> 
>>> I have created straw-man implementation of such an interface in
>>> Dx, together with some examples of how it's used, and I'd like to
>> 
> 
> https://reviews.llvm.org/D27459 :D
> 
> Sorry, I forgot to replace this by actual revision when I submitted the code.
> 
> pl

___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Pavel Labath via lldb-dev]

On 6 December 2016 at 16:51, Jim Ingham  wrote:
> Sorry, I'm being dense.  What is Dx?
>
> Jim
>
>> On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:
>>
>> I have created straw-man implementation of such an interface in
>> Dx, together with some examples of how it's used, and I'd like to
>

https://reviews.llvm.org/D27459 :D

Sorry, I forgot to replace this by actual revision when I submitted the code.

pl
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Zachary Turner via lldb-dev]

Code review with an unspecified number I think
On Tue, Dec 6, 2016 at 8:55 AM Jim Ingham  wrote:

> Sorry, I'm being dense.  What is Dx?
>
> Jim
>
> > On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:
> >
> > I have created straw-man implementation of such an interface in
> > Dx, together with some examples of how it's used, and I'd like to
>
>
___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev

Re: [lldb-dev] logging in lldb

[Jim Ingham via lldb-dev]

Sorry, I'm being dense.  What is Dx?

Jim

> On Dec 6, 2016, at 8:23 AM, Pavel Labath  wrote:
> 
> I have created straw-man implementation of such an interface in
> Dx, together with some examples of how it's used, and I'd like to

___
lldb-dev mailing list
lldb-dev@lists.llvm.org
http://lists.llvm.org/cgi-bin/mailman/listinfo/lldb-dev