Is DVLOG(0) useful?

[Drew Wilson]

I'm seeing a few instances of DVLOG(0) in the codebase, and they seem to spam the console of any debug builds, similar to DLOG(INFO).

We no longer seem to allow DLOG(INFO) thanks to a presubmit case - is DVLOG(0) useful in some case that DLOG(INFO) isn't?

[Ami Fischman]

I think several people (myself among them) assumed that [D]VLOG(0) wouldn't print unless extra flags were passed, thus 322805 and friends converting LOG(INFO) to VLOG(0).  It's hilarious that VLOG(0)==LOG(INFO).

I wonder if it'd make sense to decrease

const int VlogInfo::kDefaultVlogLevel = 0;
to -1.

-a

On Mon, Dec 2, 2013 at 9:05 AM, Drew Wilson <atwi...@chromium.org> wrote:

I'm seeing a few instances of DVLOG(0) in the codebase, and they seem to spam the console of any debug builds, similar to DLOG(INFO).

We no longer seem to allow DLOG(INFO) thanks to a presubmit case - is DVLOG(0) useful in some case that DLOG(INFO) isn't?

--
--
Chromium Developers mailing list: chromi...@chromium.org
View archives, change email options, or unsubscribe:
http://groups.google.com/a/chromium.org/group/chromium-dev

To unsubscribe from this group and stop receiving emails from it, send an email to chromium-dev...@chromium.org.

[Ami Fischman]

I have no problem with that.

On Mon, Dec 2, 2013 at 1:51 PM, Peter Kasting <pkas...@chromium.org> wrote:

On Mon, Dec 2, 2013 at 10:47 AM, Ami Fischman <fisc...@chromium.org> wrote:

I think several people (myself among them) assumed that [D]VLOG(0) wouldn't print unless extra flags were passed, thus 322805 and friends converting LOG(INFO) to VLOG(0).  It's hilarious that VLOG(0)==LOG(INFO).

FWIW, I've always asked people to convert to VLOG(1) instead of VLOG(0) -- sorry I missed that people were doing the latter this time.

I think rather than change the default log level from 0 to -1 we should just fix VLOG(0)s to be VLOG(1)s.

PK 

[Peter Kasting]

On Mon, Dec 2, 2013 at 10:47 AM, Ami Fischman <fisc...@chromium.org> wrote:

I think several people (myself among them) assumed that [D]VLOG(0) wouldn't print unless extra flags were passed, thus 322805 and friends converting LOG(INFO) to VLOG(0).  It's hilarious that VLOG(0)==LOG(INFO).

[Fred Akalin]

That probably won't do what you want. That constant is only really used when garbage is passed into --vmodule for the log level.

FWIW, the rationale for the VLOG level is that INFO = 0, WARNING = 1, ERROR = 2, FATAL = 3, ... so it seems "natural" to make VLOG(n) be essentially log level -n. But looking at the source implementation of VLOG, it seems that this behavior diverges (i.e., VLOG(0) is distinct from LOG(INFO) internally). Sorry.

-- Fred

On Mon, Dec 2, 2013 at 10:47 AM, Ami Fischman <fisc...@chromium.org> wrote:

[Scott Hess]

Indeed: VLOG(-4) causes a crash with backtrace like LOG(FATAL).

IMHO it would be appropriate to modify the code so that VLOG requires a strictly positive value OR caps at a minimum of 1.  Unfortunately, a dynamic check might miss many uses.

-scott

[Chris Hopman]

So, we changed all LOG(INFO) to VLOG(0) and disallowed LOG(INFO). Now we are changing all VLOG(0) to VLOG(1). I would assume that we would then want to also disallow VLOG(0).

Maybe we should stop and think about this one...

Problem: Chrome by default logs too much stuff.

Solution 1:

  Disallow LOG(INFO). Maybe eventually update documentation everywhere that this isn't allowed.

  Disallow VLOG(0). Maybe eventually update documentation everywhere that this isn't allowed.

  Change all LOG(INFO) and VLOG(0) to VLOG(1). This costs 10s (100s?) of bytes per LOG(INFO) changed.

Solution 2:

  Change default logging level so that LOG(INFO) is not printed by default. Maybe eventually update the documentation about default log level (much less updating required than above).

Feel free to propose other solutions, but I (obviously) don't think we should be doing solution 1.

[Peter Kasting]

On Mon, Dec 2, 2013 at 2:24 PM, Chris Hopman <cjho...@chromium.org> wrote:

  Change all LOG(INFO) and VLOG(0) to VLOG(1). This costs 10s (100s?) of bytes per LOG(INFO) changed.

Why?

PK 

[Chris Hopman]

Well, looking closer it seems we don't use the LOG(INFO)-specific constructor so about 10-20bytes/callsite of that cost is already lost (google3's logging with almost the same constructor signatures claims 17bytes/callsite).

Still, the non-inlined part of VLOG_IS_ON has two more arguments than that of LOG_IS_ON.

[Peter Kasting]

On Mon, Dec 2, 2013 at 2:45 PM, Chris Hopman <cjho...@chromium.org> wrote:

Well, looking closer it seems we don't use the LOG(INFO)-specific constructor so about 10-20bytes/callsite of that cost is already lost (google3's logging with almost the same constructor signatures claims 17bytes/callsite).

Still, the non-inlined part of VLOG_IS_ON has two more arguments than that of LOG_IS_ON.

The actual effect of two more args is not obvious to me, but seems likely to be small.

More importantly, logging in general is already strongly discouraged across Chrome due (among several other reasons) to the binary size cost of the actual log message.  It seems like the additional cost of a VLOG constructor over a LOG one is not terribly important given that, in general, LOG messages should be extremely rare.

Or to say this a different way: the best fix for these issues is often not to convert LOG(INFO) and VLOG(0) to VLOG(1), but to delete the log statements completely.

PK

[Chris Hopman]

On Mon, Dec 2, 2013 at 2:49 PM, Peter Kasting <pkas...@chromium.org> wrote:

On Mon, Dec 2, 2013 at 2:45 PM, Chris Hopman <cjho...@chromium.org> wrote:

Well, looking closer it seems we don't use the LOG(INFO)-specific constructor so about 10-20bytes/callsite of that cost is already lost (google3's logging with almost the same constructor signatures claims 17bytes/callsite).

Still, the non-inlined part of VLOG_IS_ON has two more arguments than that of LOG_IS_ON.

The actual effect of two more args is not obvious to me, but seems likely to be small.

It's not obvious to me either, but the 17bytes/callsite in the constructor is, basically, from one additional arg.

Still, I, too, don't worry too much about a couple bytes extra overhead (switching to ninja cost something like 6 extra bytes per LOG call, I believe). Feel free to remove that from the Solution 1 list and add one of the below that I missed:

Solution 1.1:

  Add presubmit check for uses of LOG(INFO) and VLOG(0).

or

Solution 1.2:

  Discourage use of LOG(INFO) and VLOG(0) in code reviews, probably inconsistently.

 

More importantly, logging in general is already strongly discouraged across Chrome due (among several other reasons) to the binary size cost of the actual log message.  It seems like the additional cost of a VLOG constructor over a LOG one is not terribly important given that, in general, LOG messages should be extremely rare.

Is this strong discouragement something new? If not, then I don't know that we can expect it to be a solution going forward when it's not been a solution to this point.

 

Or to say this a different way: the best fix for these issues is often not to convert LOG(INFO) and VLOG(0) to VLOG(1), but to delete the log statements completely.

Sure, that works to clean up the current state. It doesn't address future changes though.

[Peter Kasting]

On Mon, Dec 2, 2013 at 3:06 PM, Chris Hopman <cjho...@chromium.org> wrote:

Solution 1.1:

  Add presubmit check for uses of LOG(INFO) and VLOG(0).

SGTM.

More importantly, logging in general is already strongly discouraged across Chrome due (among several other reasons) to the binary size cost of the actual log message.  It seems like the additional cost of a VLOG constructor over a LOG one is not terribly important given that, in general, LOG messages should be extremely rare.

Is this strong discouragement something new? If not, then I don't know that we can expect it to be a solution going forward when it's not been a solution to this point.

It's not obvious to me that the existing problem is of such large scale that we can consider what we've done in the past to be a failure.  But as noted above, I'm all for a presubmit check that considers LOG(INFO) and VLOG(0) to be banned and considers VLOG(n) a warning.

PK

[Scott Graham]

On Mon, Dec 2, 2013 at 3:06 PM, Chris Hopman <cjho...@chromium.org> wrote:

On Mon, Dec 2, 2013 at 2:49 PM, Peter Kasting <pkas...@chromium.org> wrote:

On Mon, Dec 2, 2013 at 2:45 PM, Chris Hopman <cjho...@chromium.org> wrote:

Well, looking closer it seems we don't use the LOG(INFO)-specific constructor so about 10-20bytes/callsite of that cost is already lost (google3's logging with almost the same constructor signatures claims 17bytes/callsite).

Still, the non-inlined part of VLOG_IS_ON has two more arguments than that of LOG_IS_ON.

The actual effect of two more args is not obvious to me, but seems likely to be small.

It's not obvious to me either, but the 17bytes/callsite in the constructor is, basically, from one additional arg.

Still, I, too, don't worry too much about a couple bytes extra overhead (switching to ninja cost something like 6 extra bytes per LOG call, I believe).

Is there a bug that expands on this? Why did the build system affect generated code size?

 

Feel free to remove that from the Solution 1 list and add one of the below that I missed:

Solution 1.1:

  Add presubmit check for uses of LOG(INFO) and VLOG(0).

or

Solution 1.2:

  Discourage use of LOG(INFO) and VLOG(0) in code reviews, probably inconsistently.

 

More importantly, logging in general is already strongly discouraged across Chrome due (among several other reasons) to the binary size cost of the actual log message.  It seems like the additional cost of a VLOG constructor over a LOG one is not terribly important given that, in general, LOG messages should be extremely rare.

Is this strong discouragement something new? If not, then I don't know that we can expect it to be a solution going forward when it's not been a solution to this point.

 

Or to say this a different way: the best fix for these issues is often not to convert LOG(INFO) and VLOG(0) to VLOG(1), but to delete the log statements completely.

Sure, that works to clean up the current state. It doesn't address future changes though.

[Chris Hopman]

The __FILE__ macro expands to a path relative to the directory that the compiler is run in. Ninja runs this in the output directory while make ran it in the top-level src directory. Thus, with ninja, these paths all include an extra "../../".

[Richard]

Sorry to resurrect this old thread. Did anything ever actually happen to prevent people from using VLOG(0) or DVLOG(0)? We still have hundreds of uses of these across the codebase, and it seems like the authors expected this to cause the log to not be printed by default. Is there a presubmit check now, but we haven't cleaned up the old cases? Or did the change just never happen?

[Peter Kasting]

On Wed, Feb 25, 2015 at 2:16 AM, Richard <to...@chromium.org> wrote:

Sorry to resurrect this old thread. Did anything ever actually happen to prevent people from using VLOG(0) or DVLOG(0)? We still have hundreds of uses of these across the codebase, and it seems like the authors expected this to cause the log to not be printed by default. Is there a presubmit check now, but we haven't cleaned up the old cases? Or did the change just never happen?

Since no one wrote anything like "I will go make this happen", it's probably safe to assume no one did anything.

PK