Page MenuHomePhabricator

[Logging] Replace Log::Printf with LLDB_LOG macro (NFC)
ClosedPublic

Authored by JDevlieghere on Jul 22 2019, 6:32 PM.

Details

Summary

This patch replaces explicit calls to log::Printf with the new LLDB_LOGF
macro. The macro is similar to LLDB_LOG but supports printf-style format
strings, instead of formatv-style format strings.

So instead of writing:

if (log)
  log->Printf("%s\n", str);

You'd write:

LLDB_LOG(log, "%s\n", str);

This change was done mechanically with the command below. I replaced the
spurious if-checks with vim, since I know how to do multi-line
replacements with it.

find . -type f -name '*.cpp' -exec \
sed -i '' -E 's/log->Printf\(/LLDB_LOGF\(log, /g' "{}" +

Diff Detail

Event Timeline

JDevlieghere created this revision.Jul 22 2019, 6:32 PM
Herald added a reviewer: shafik. · View Herald Transcript
Herald added a project: Restricted Project. · View Herald Transcript

IIUC, LLDB_LOG already adds the file and function. A bunch of these logs are also adding FUNCTION, so that's probably going to come out twice now. You should probably remove the duplicates.

jingham requested changes to this revision.Jul 22 2019, 6:52 PM

Actually, I don't want this change as is. Some logs - like the expression and step logs - are laid out for readability, and LLDB_LOG automatically adds the file & function which will make them much harder to read.

We need a variant that doesn't inject this information, and then this change should use that variant. Or we can remove the file & function from LLDB_LOG and decide to let the people add those as they wish. I don't have a strong opinion one way or the other, but I certainly don't want this extra noise in the step or expression logs.

This revision now requires changes to proceed.Jul 22 2019, 6:52 PM

Actually, I don't want this change as is. Some logs - like the expression and step logs - are laid out for readability, and LLDB_LOG automatically adds the file & function which will make them much harder to read.

We need a variant that doesn't inject this information, and then this change should use that variant. Or we can remove the file & function from LLDB_LOG and decide to let the people add those as they wish. I don't have a strong opinion one way or the other, but I certainly don't want this extra noise in the step or expression logs.

I agree with you. I always use LLDB_LOG, but not because it includes the file and function, but because it's consistent, it gives me the ability to use the LLVM formatter, and I don't have to explicitly check whether the log is NULL or not. I can only speak for myself of course.

@labath Since you added the macro, what's your take on this? Do you care a lot about the file and function, and should we have two macros, one that includes this and one that doesn't? Or should we have just one macro, and have users decide whether they need this information or not?

I don't think you can make a change like this mechanically, and the reason is not the file-function prepending, but the fact that the two styles use a different format specifier syntax (printf vs. the llvm formatv thingy). If you change the function without changing the format strings, you just create a bunch of static log messages...

Actually, I don't want this change as is. Some logs - like the expression and step logs - are laid out for readability, and LLDB_LOG automatically adds the file & function which will make them much harder to read.

We need a variant that doesn't inject this information, and then this change should use that variant. Or we can remove the file & function from LLDB_LOG and decide to let the people add those as they wish. I don't have a strong opinion one way or the other, but I certainly don't want this extra noise in the step or expression logs.

I agree with you. I always use LLDB_LOG, but not because it includes the file and function, but because it's consistent, it gives me the ability to use the LLVM formatter, and I don't have to explicitly check whether the log is NULL or not. I can only speak for myself of course.

@labath Since you added the macro, what's your take on this? Do you care a lot about the file and function, and should we have two macros, one that includes this and one that doesn't? Or should we have just one macro, and have users decide whether they need this information or not?

The reason I added the file-function prepending stuff was because a lot of our logging statements do things like:

if(log)
  log->Printf("MyUsuallyVeryLongClassName::%s real stuff...", args..., __FUNCTION__);

This means that the Printf call usually does not fit a single line, and so each logging statement ends up taking at least three lines (together with the if(log) stuff). By making sure the origin of the log statement is automatically added to the message, I was hoping that we'd only log the actual interesting stuff, and so we'd have succinct log statements which don't interfere with the flow of the rest of the code (LLDB_LOG(log, "real stuff...", args...)).

So, that was the direction I wanted to take things in. However, I wouldn't say that has been entirely successful, so if you want to take a different direction now, that's fine with me. I just want to point out two things:

  • The file-function prepending stuff is optional. In fact it's not even enabled by default -- you have to pass a --file-function flag to the "log enable" command to get this behavior
  • The prepending code goes through a lot of trouble to make sure the file-function field is always of the same width. This means that if you have a log file which contains these things, you can just scroll to the right to avoid seeing them, or (assuming your editor supports block operations) easily cut them out.
JDevlieghere added a comment.EditedJul 23 2019, 7:36 AM

I don't think you can make a change like this mechanically, and the reason is not the file-function prepending, but the fact that the two styles use a different format specifier syntax (printf vs. the llvm formatv thingy). If you change the function without changing the format strings, you just create a bunch of static log messages...

Thanks for pointing this out. Somehow I convinced myself that formatv supported both, but on further inspection that is not true. I guess we could change the format strings too, but I'm afraid that is a more controversial change.

Actually, I don't want this change as is. Some logs - like the expression and step logs - are laid out for readability, and LLDB_LOG automatically adds the file & function which will make them much harder to read.

We need a variant that doesn't inject this information, and then this change should use that variant. Or we can remove the file & function from LLDB_LOG and decide to let the people add those as they wish. I don't have a strong opinion one way or the other, but I certainly don't want this extra noise in the step or expression logs.

I agree with you. I always use LLDB_LOG, but not because it includes the file and function, but because it's consistent, it gives me the ability to use the LLVM formatter, and I don't have to explicitly check whether the log is NULL or not. I can only speak for myself of course.

@labath Since you added the macro, what's your take on this? Do you care a lot about the file and function, and should we have two macros, one that includes this and one that doesn't? Or should we have just one macro, and have users decide whether they need this information or not?

The reason I added the file-function prepending stuff was because a lot of our logging statements do things like:

if(log)
  log->Printf("MyUsuallyVeryLongClassName::%s real stuff...", args..., __FUNCTION__);

This means that the Printf call usually does not fit a single line, and so each logging statement ends up taking at least three lines (together with the if(log) stuff). By making sure the origin of the log statement is automatically added to the message, I was hoping that we'd only log the actual interesting stuff, and so we'd have succinct log statements which don't interfere with the flow of the rest of the code (LLDB_LOG(log, "real stuff...", args...)).

So, that was the direction I wanted to take things in. However, I wouldn't say that has been entirely successful, so if you want to take a different direction now, that's fine with me. I just want to point out two things:

  • The file-function prepending stuff is optional. In fact it's not even enabled by default -- you have to pass a --file-function flag to the "log enable" command to get this behavior
  • The prepending code goes through a lot of trouble to make sure the file-function field is always of the same width. This means that if you have a log file which contains these things, you can just scroll to the right to avoid seeing them, or (assuming your editor supports block operations) easily cut them out.

That explains my confusion as to it being part of the macro. I never noticed it showing up in the log, and this explains why.

martong resigned from this revision.Jul 23 2019, 8:00 AM
JDevlieghere edited the summary of this revision. (Show Details)

Introduce LLDB_LOGF macro to support printf-style format strings.

labath accepted this revision.Jul 24 2019, 1:20 AM

I'm fine with this if Jim is.

lldb/source/Expression/IRExecutionUnit.cpp
601

looks like there are some if(log)s still remaining. Maybe the {} around the printf confused your vim macro?

jingham accepted this revision.Jul 24 2019, 10:05 AM

Sure, this is okay.

lldb/source/Expression/IRExecutionUnit.cpp
601

There will always be some "if (log)" statements. Whenever consing up the log message involves work, you should always say:

if (log) {

/// Do expensive work
LLDB_LOG...

}

Not saying that all the remaining "if (logs)" are for that reason, but then intent is NOT to remove all such statements as they serve a useful purpose.

This revision is now accepted and ready to land.Jul 24 2019, 10:05 AM
This revision was automatically updated to reflect the committed changes.
Herald added a project: Restricted Project. · View Herald TranscriptJul 24 2019, 10:59 AM
labath added inline comments.Jul 24 2019, 11:00 PM
lldb/source/Expression/IRExecutionUnit.cpp
601

I'm fine with if(log)s staying if they serve a purpose (or even if they're hard to remove in this patch). However, I would expect that with LLDB_LOG, they become much less frequently needed, because the formatter is much more powerful (e.g., there is no need to write a for loop just to print an array, etc.)

jingham added inline comments.Jul 25 2019, 10:50 AM
lldb/source/Expression/IRExecutionUnit.cpp
601

Yes, it's also not entirely obvious (YAY for macros!!!) that code in the LLDB_LOG* arguments doesn't get evaluated if log == nullptr, but that also reduces the need for standalone if (logs).

BTW, we were going to document somewhere that LLDB_LOG actually used format_providers but I didn't see that anywhere. I submitted:

https://reviews.llvm.org/D65293

to put this somewhere in the lldb sources. Not sure if this is the best place, or if there is more that it would be useful to add.