When logging, use only debug variants

239 views
Skip to first unread message

Brett Wilson

unread,
Oct 21, 2011, 2:46:07 AM10/21/11
to Chromium-dev
I did some measurements of a Windows release build (no WPO) with no
debug logging (normal non-official release builds compile with debug
logging enabled, I turned it off for all of these tests to be more
like an official build).

More than 500K of the 24MB size of chrome.dll consists of non-debug
log statements. These are the strings and the code to do the checks
and do all the stream operations. This does not count CHECK which
presumably we want to crash. This size is unreasonable to be pushing
to all of our users' computers.

So: do not use non-debug logging. Early in the project we used DLOG
and variants almost exclusively as we didn't want the extra overhead.
But I see people do this more and more now because people treat it as
free and potentially useful. It is not free, and it is also likely not
useful.


Reviewers should please challenge all non-"D" logging statements. We
should treat these as something exceptional and temporary, like we do
when we're trying to track down an obscure crash and somebody will put
a bunch of extra CHECKs in. If you have a real need for non-debug
logging, there should be a reason for why you need it and a bug for
removing it when this reason is over.

Continue to use CHECK/DLOG(FATAL) for security sensitive issues where
we want to terminate the program. But these should probably be the
only case and should be rare.


If you need logging, the normal answer is that you should use a debug
build or a normal release build (which will have all debug logging in
it).

I'm going to immediately make VLOG only imply "debug" (there is no
DVLOG, so now VLOG will be what DVLOG would mean if it existed). This
will save about 250K.

Brett

Greg Thompson

unread,
Oct 21, 2011, 10:04:07 AM10/21/11
to bre...@chromium.org, Chromium-dev
On Fri, Oct 21, 2011 at 2:46 AM, Brett Wilson <bre...@chromium.org> wrote:
So: do not use non-debug logging. Early in the project we used DLOG
and variants almost exclusively as we didn't want the extra overhead.
But I see people do this more and more now because people treat it as
free and potentially useful. It is not free, and it is also likely not
useful.
 
Non-debug logging has turned out to be extremely useful for the Windows installer.  There are many "interesting" user configurations out in the wild that we can't predict, so we sometimes/often are able to track down problems in the installer by looking at user-supplied log files.  Could we have an exception to this new policy for src/chrome/installer/*?

Fred Akalin

unread,
Oct 21, 2011, 5:24:24 PM10/21/11
to bre...@chromium.org, Chromium-dev
On Thu, Oct 20, 2011 at 11:46 PM, Brett Wilson <bre...@chromium.org> wrote:
> More than 500K of the 24MB size of chrome.dll consists of non-debug
> log statements. These are the strings and the code to do the checks
> and do all the stream operations. This does not count CHECK which
> presumably we want to crash. This size is unreasonable to be pushing
> to all of our users' computers.

Why? What are the benefits of saving 2% of the size of chrome.dll?
Will it reduce the overall installer size? If so, given that strings
are highly compressible, how much? Will it reduce Chrome startup
time? If so, by how much and why? Are the strings lumped together in
one place in the dll, or are they scattered with other constants which
are more often used?

Logging in release builds is one of those things that are rarely
needed, but when you need them, you *really* need them. I'm concerned
that we're sacrificing a potentially useful debugging method for
dubious gains.

> Reviewers should please challenge all non-"D" logging statements. We
> should treat these as something exceptional and temporary, like we do
> when we're trying to track down an obscure crash and somebody will put
> a bunch of extra CHECKs in. If you have a real need for non-debug
> logging, there should be a reason for why you need it and a bug for
> removing it when this reason is over.

This seems impractical for stable builds.

> I'm going to immediately make VLOG only imply "debug" (there is no
> DVLOG, so now VLOG will be what DVLOG would mean if it existed). This
> will save about 250K.

This is not a good way to solve the problem. When I wrote VLOG, it
was to prevent the spew caused by everyone writing to LOG(INFO). If
VLOG is made debug-only, then there's no way to get release logging
that's behind a flag. Either you use LOG(INFO), and contribute to
spew, or you use VLOG and lose the benefits of being able to get that
logging in official builds.

When VLOG was first introduced, Peter Kasting made a bunch of changes
to convert LOG(INFO) to VLOG(1). We should probably do something
similar here to change VLOG(*) to DVLOG(*) instead of changing the
meaning of an existing macro.

Ilya Sherman

unread,
Oct 21, 2011, 5:38:01 PM10/21/11
to aka...@chromium.org, bre...@chromium.org, Chromium-dev
On Fri, Oct 21, 2011 at 2:24 PM, Fred Akalin <aka...@chromium.org> wrote:
> I'm going to immediately make VLOG only imply "debug" (there is no
> DVLOG, so now VLOG will be what DVLOG would mean if it existed). This
> will save about 250K.

This is not a good way to solve the problem.  When I wrote VLOG, it
was to prevent the spew caused by everyone writing to LOG(INFO).  If
VLOG is made debug-only, then there's no way to get release logging
that's behind a flag.  Either you use LOG(INFO), and contribute to
spew, or you use VLOG and lose the benefits of being able to get that
logging in official builds.

When VLOG was first introduced, Peter Kasting made a bunch of changes
to convert LOG(INFO) to VLOG(1).  We should probably do something
similar here to change VLOG(*) to DVLOG(*) instead of changing the
meaning of an existing macro.

+1.  I'm all for making DVLOG the default, but VLOG in Release mode has legitimate use cases, as Fred pointed out.

Brett Wilson

unread,
Oct 21, 2011, 6:02:53 PM10/21/11
to Fred Akalin, Chromium-dev
On Fri, Oct 21, 2011 at 2:24 PM, Fred Akalin <aka...@chromium.org> wrote:
> On Thu, Oct 20, 2011 at 11:46 PM, Brett Wilson <bre...@chromium.org> wrote:
>> More than 500K of the 24MB size of chrome.dll consists of non-debug
>> log statements. These are the strings and the code to do the checks
>> and do all the stream operations. This does not count CHECK which
>> presumably we want to crash. This size is unreasonable to be pushing
>> to all of our users' computers.
>
> Why?  What are the benefits of saving 2% of the size of chrome.dll?
> Will it reduce the overall installer size?  If so, given that strings
> are highly compressible, how much?  Will it reduce Chrome startup
> time?  If so, by how much and why?  Are the strings lumped together in
> one place in the dll, or are they scattered with other constants which
> are more often used?

The strings are not lumped together. And a bunch of the space is code
bloat. For example, here is the release mode code generated:

VLOG(1) << "hello";

011E29DD push 14h
011E29DF xor ebx,ebx
011E29E1 push offset string "at_exit_unittest.cc" (143F088h)
011E29E6 xor ebp,ebp
011E29E8 mov dword ptr [esp+1Ch],ebx
011E29EC call dword ptr [__imp_logging::GetVlogLevelHelper (143DEE0h)]
011E29F2 add esp,8
011E29F5 cmp eax,1
011E29F8 jl AtExitTest_Basic_Test::TestBody+7Eh (11E2A2Eh)
011E29FA push 0FFFFFFFFh
011E29FC push 32h
011E29FE push offset string "at_exit_unittest.cc" (143F088h)
011E2A03 lea ecx,[esp+44h]
011E2A07 call dword ptr [__imp_logging::LogMessage::LogMessage
(143DF00h)]
011E2A0D add eax,8
011E2A10 push offset string "hello" (143F104h)
011E2A15 mov ebx,1
011E2A1A push eax
011E2A1B mov dword ptr [esp+0F8h],ebp
011E2A22 mov dword ptr [esp+1Ch],ebx
011E2A26 call std::operator<<<std::char_traits<char> > (11E1810h)
011E2A2B add esp,8
011E2A2E or edi,0FFFFFFFFh
011E2A31 mov dword ptr [esp+0F0h],edi
011E2A38 test bl,1
011E2A3B je AtExitTest_Basic_Test::TestBody+97h (11E2A47h)
011E2A3D lea ecx,[esp+38h]
011E2A41 call dword ptr
[__imp_logging::LogMessage::~LogMessage (143DEFCh)]

This is a pretty epic amount of code for something that looks like it's a NOP.

Every time you type VLOG, you get this code on 100's of millions on
people's computers, which includes the name of the file as a string
and all the strings you specify in the log statement. I don't think
people appreciate this bloat.


> Logging in release builds is one of those things that are rarely
> needed, but when you need them, you *really* need them.  I'm concerned
> that we're sacrificing a potentially useful debugging method for
> dubious gains.

Please give examples. I'm suggesting that in the very few cases where
it may be useful, that you copy a regular debug or non-official
release build to that computer.


>> Reviewers should please challenge all non-"D" logging statements. We
>> should treat these as something exceptional and temporary, like we do
>> when we're trying to track down an obscure crash and somebody will put
>> a bunch of extra CHECKs in. If you have a real need for non-debug
>> logging, there should be a reason for why you need it and a bug for
>> removing it when this reason is over.
>
> This seems impractical for stable builds.

I don't know what this means.

>> I'm going to immediately make VLOG only imply "debug" (there is no
>> DVLOG, so now VLOG will be what DVLOG would mean if it existed). This
>> will save about 250K.
>
> This is not a good way to solve the problem.  When I wrote VLOG, it
> was to prevent the spew caused by everyone writing to LOG(INFO).  If
> VLOG is made debug-only, then there's no way to get release logging
> that's behind a flag.  Either you use LOG(INFO), and contribute to
> spew, or you use VLOG and lose the benefits of being able to get that
> logging in official builds.
>
> When VLOG was first introduced, Peter Kasting made a bunch of changes
> to convert LOG(INFO) to VLOG(1).  We should probably do something
> similar here to change VLOG(*) to DVLOG(*) instead of changing the
> meaning of an existing macro.

I guess I don't get the use case for a log that's so important we have
to ship it to everybody all the time, but it so unimportant that you
don't ever want to see it without jumping through extra hoops.

People have shown over the past year that they can't use VLOG
properly, and consistently treat it as "even less important than DLOG"
without realizing that it's actually shipped in all release builds.
Almost nobody uses DVLOG.

Brett

Fred Akalin

unread,
Oct 21, 2011, 6:31:35 PM10/21/11
to Brett Wilson, Chromium-dev
On Fri, Oct 21, 2011 at 3:02 PM, Brett Wilson <bre...@chromium.org> wrote:
> This is a pretty epic amount of code for something that looks like it's a NOP.

The bulk of that code is effectively the LOG(INFO) -- VLOG(1) only
adds the function call to VlogIsOnHelper and the branch on its return
value. The branch is highly predictable, but of course there are many
call sites, so maybe we should annotate it as 'unlikely' for the
compiler.

I think if developers think that logging is a NOP, then the solution
is to educate them and not take away logging. If you're using logging
in a place where the logging code adds significant performance
overhead, (e.g., a tight inner loop) then you shouldn't use logging in
that code.

> Every time you type VLOG, you get this code on 100's of millions on
> people's computers, which includes the name of the file as a string
> and all the strings you specify in the log statement. I don't think
> people appreciate this bloat.

Really? I think people care more about e.g., startup time, page load
time, than they do about binary size. I'm still skeptical that what
you're doing will cause any perceptible performance increase.

> Please give examples. I'm suggesting that in the very few cases where
> it may be useful, that you copy a regular debug or non-official
> release build to that computer.

Sure. A user files a bug about some weird behavior X. The developer
for that feature notices that there's some logging that would shed
some light on why that behavior is happening. The developer points
the user to http://www.chromium.org/for-testers/enable-logging and
asks him to send a log with --v=1 --vmodule='...'. The user complies,
and the developer figures out the problem and fixes it. Hooray!

Without the logging, the developer is mystified. He then maybe goes
on to do something else. Or, he could ask the user to download a
debug build (from where? do we have debug versions of shipped Chrome
versions?) or a non-official release build (again, from where?) and
run it with the right command line parameters to use the same profile
where the problem occurs (not that easy). The user thinks its too
hard and doesn't do it. The bug doesn't get fixed. Sad. :(

>>> Reviewers should please challenge all non-"D" logging statements. We
>>> should treat these as something exceptional and temporary, like we do
>>> when we're trying to track down an obscure crash and somebody will put
>>> a bunch of extra CHECKs in. If you have a real need for non-debug
>>> logging, there should be a reason for why you need it and a bug for
>>> removing it when this reason is over.
>>
>> This seems impractical for stable builds.
>
> I don't know what this means.

If there's an obscure crash in a stable build, what's the turnaround
time to get CHECKs into it to debug the problem?

> I guess I don't get the use case for a log that's so important we have
> to ship it to everybody all the time, but it so unimportant that you
> don't ever want to see it without jumping through extra hoops.

The difference is that debug builds have logging on by default and
release builds don't. So there can be logging that is important
enough to ship out but not important enough to display to every
developer.

> People have shown over the past year that they can't use VLOG
> properly, and consistently treat it as "even less important than DLOG"
> without realizing that it's actually shipped in all release builds.
> Almost nobody uses DVLOG.

Before Peter's mass LOG(INFO) -> VLOG(1) change, almost no one used
VLOG. I suspect that if you do a mass VLOG -> DVLOG change, you'll
find that everyone will use DVLOG by default. New code tends to
follow the style of the surrounding old code.

Ilya Sherman

unread,
Oct 21, 2011, 6:34:08 PM10/21/11
to bre...@chromium.org, Fred Akalin, Chromium-dev
On Fri, Oct 21, 2011 at 3:02 PM, Brett Wilson <bre...@chromium.org> wrote:
Please give examples. I'm suggesting that in the very few cases where
it may be useful, that you copy a regular debug or non-official
release build to that computer.

...

I guess I don't get the use case for a log that's so important we have
to ship it to everybody all the time, but it so unimportant that you
don't ever want to see it without jumping through extra hoops.

My specific use case for a release-build VLOG is to help QA folks to get some additional insight into what the Autofill backend is "thinking".  Yes, they could just download a debug or non-official release build -- that's fine for one-offs, but a huge pain if you need to do it regularly.  I think you might be underestimating the cost of locating a {debug, non-official} build that exactly corresponds to whatever release build you're running (or recompiling it from scratch) and configuring it identically to how your primary build is configured.

So, no, this log info is not so important that it *has to* ship to *everyone*, but the overall benefits outweigh the costs, IMO.

People have shown over the past year that they can't use VLOG
properly, and consistently treat it as "even less important than DLOG"
without realizing that it's actually shipped in all release builds.
Almost nobody uses DVLOG.

I was previously unaware that we had both VLOG and DVLOG.  In fact, from your original email, it sounds like we've never even have a DVLOG macro available.  Rather than removing the ability to use VLOG in release builds, how about converting the 99% of current VLOG users over to DVLOG, and adding a note to the style guide?  Unless you believe that even a handful of VLOG statements will seriously hamper the release builds we ship to users, I think it's reasonable to give Chromium developers the information they need to choose, and then trust them to make the right choice -- as we do for so many things on this project.

Brett Wilson

unread,
Oct 21, 2011, 7:00:00 PM10/21/11
to Fred Akalin, Chromium-dev


On Oct 21, 2011 3:31 PM, "Fred Akalin" <aka...@chromium.org> wrote:
>
> On Fri, Oct 21, 2011 at 3:02 PM, Brett Wilson <bre...@chromium.org> wrote:
> > This is a pretty epic amount of code for something that looks like it's a NOP.
>
> The bulk of that code is effectively the LOG(INFO) -- VLOG(1) only
> adds the function call to VlogIsOnHelper and the branch on its return
> value.  The branch is highly predictable, but of course there are many
> call sites, so maybe we should annotate it as 'unlikely' for the
> compiler.

I'm not arguing that VLOG is much worse than LOG. I'm saying people treat it as one level below DLOG yet it's actually expensive.

> I think if developers think that logging is a NOP, then the solution
> is to educate them and not take away logging.  If you're using logging
> in a place where the logging code adds significant performance
> overhead, (e.g., a tight inner loop) then you shouldn't use logging in
> that code.

Like I said, our VLOG usage adds up to 250k. That has a real startup and runtine cost.

> > Every time you type VLOG, you get this code on 100's of millions on
> > people's computers, which includes the name of the file as a string
> > and all the strings you specify in the log statement. I don't think
> > people appreciate this bloat.
>
> Really?  I think people care more about e.g., startup time, page load
> time, than they do about binary size.  I'm still skeptical that what
> you're doing will cause any perceptible performance increase.
>
> > Please give examples. I'm suggesting that in the very few cases where
> > it may be useful, that you copy a regular debug or non-official
> > release build to that computer.
>
> Sure.  A user files a bug about some weird behavior X.  The developer
> for that feature notices that there's some logging that would shed
> some light on why that behavior is happening.  The developer points
> the user to http://www.chromium.org/for-testers/enable-logging and
> asks him to send a log with --v=1 --vmodule='...'.  The user complies,
> and the developer figures out the problem and fixes it.  Hooray!
>
> Without the logging, the developer is mystified.  He then maybe goes
> on to do something else.  Or, he could ask the user to download a
> debug build (from where?  do we have debug versions of shipped Chrome
> versions?) or a non-official release build (again, from where?) and
> run it with the right command line parameters to use the same profile
> where the problem occurs (not that easy).  The user thinks its too
> hard and doesn't do it.  The bug doesn't get fixed.  Sad. :(

This is a made up example. Ilya gave a real example. I'm skeptical there are that many real examples.

I'm OK doing a bulk VLOG -> DVLOG rename and seeing if it works. But I think it's too complicated. In theory log type and debug/release are totally independent. In practice, I don't think people think about it this way.

Fred Akalin

unread,
Oct 21, 2011, 7:09:53 PM10/21/11
to Brett Wilson, Chromium-dev
> I'm OK doing a bulk VLOG -> DVLOG rename and seeing if it works. But I think
> it's too complicated. In theory log type and debug/release are totally
> independent. In practice, I don't think people think about it this way.

I realize that is more complicated, but I think it's a less
objectionable solution. People can change back to VLOG if they deem
it necessary. Most people probably won't.

I can help, if necessary.

Peter Kasting

unread,
Oct 21, 2011, 8:54:06 PM10/21/11
to aka...@chromium.org, Brett Wilson, Chromium-dev
On Fri, Oct 21, 2011 at 3:31 PM, Fred Akalin <aka...@chromium.org> wrote:
I think if developers think that logging is a NOP, then the solution
is to educate them and not take away logging.

I don't have a strong opinion about the larger issues here, but I just want to note on principle that if we can make our APIs "do the right thing" instead of relying on developers to understand tradeoffs, that will be a win, especially as we continue to grow the team.  I know I personally forget or fail to understand tradeoffs all the time.

Personally I've never found logging to be as useful as [D]CHECK(), in that I can almost always express the information that would be useful to log as a set of assertions that I can then check for.  And I also confess that, like Brett says, I assumed that VLOG() was basically zero-cost.  Perhaps my anecdotal data is not very representative, however.

PK

Lingeshwaran Palaniappan

unread,
Oct 21, 2011, 9:13:57 PM10/21/11
to pkas...@google.com, aka...@chromium.org, Brett Wilson, Chromium-dev
How about we make VLOG cheap?
A simplistic solution is instead of VLOG actually emitting the string we just emit a number(That corresponds to a string). Which can later be converted to the corresponding string by a tool or a listener if real time is needed. 

This optimization would not work if printing variables. But that is something that we can educate developers on.(Make as much of the string static as possible etc).
this will address the code bloat but will not address the perf issue. 

Thanks!

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

Carlos Pizano

unread,
Oct 21, 2011, 9:37:44 PM10/21/11
to Chromium-dev, Peter Kasting, aka...@chromium.org, Brett Wilson
>> Logging in release builds is one of those things that are rarely
>> needed, but when you need them, you *really* need them.

I find that this way of thinking leads to slow, bloated code. Your
code runs in 200M+ machines.
Just the sheer number of times my code is hit per hour makes me feel
it should not do needless things.

>> I assumed that VLOG() was basically zero-cost.

Well, nearly yes, but no if everybody sprinkles a few of these every
few lines just in case.

>> Really? I think people care more about e.g., startup time, page load
>> time, than they do about binary size.

Binary size *is* start-up time. It has gotten to the point that we
have people dedicated to write code to re-organize the code pages so
we have a semblance of the start up speed we had 3 years ago.



William Chan (陈智昌)

unread,
Oct 21, 2011, 9:59:04 PM10/21/11
to c...@chromium.org, Chromium-dev, Peter Kasting, aka...@chromium.org, Brett Wilson
I have to say that 500K sounds rather large to me. Thanks Brett for providing these numbers. I think 500K is worth noting. Here's why:

* Larger binaries mean more to download. Not everyone's on broadband.
* If we ever want to put Chromium on mobile devices, we should be concerned about the binary size.
* More bloat means slower startup (more pages to load into memory). Hopefully the memory accesses are localized.

I am all for making DVLOG and DLOG and all those guys be the default. I have been lax before, I will try to crack down now. I don't think we should get rid of normal LOG because it IS useful sometimes. But we should be prudent. I think a one-time audit will go a long way, and if most code is using the debug variant, then people will follow convention. I think that we could safely eliminate 90% of these LOGs.

On Fri, Oct 21, 2011 at 6:37 PM, Carlos Pizano <c...@chromium.org> wrote:
>> Logging in release builds is one of those things that are rarely
>> needed, but when you need them, you *really* need them.

I find that this way of thinking leads to slow, bloated code. Your
code runs in 200M+ machines.
Just the sheer number of times my code is hit per hour makes me feel
it should not do needless things.

I agree with the sentiment, but I'd like to be a bit more exact here. It depends on what you're working on, but most likely your code is not running on all those machines. I write plenty of exceptional code that almost never runs. 80/20 Pareto Principle and what not.
 

>>  I assumed that VLOG() was basically zero-cost.

Well, nearly yes, but no if everybody sprinkles a few of these every
few lines just in case.

+1. I'm not a big fan of the death by a thousand cuts argument, since I usually care more about what profiles show, but the binary size increase shown by Brett is significant enough to me that I think we should care.
 

>> Really?  I think people care more about e.g., startup time, page load
>> time, than they do about binary size.

Binary size *is* start-up time. It has gotten to the point that we
have people dedicated to write code to re-organize the code pages so
we have a semblance of the start up speed  we had 3 years ago.

+1

Satoru Takabayashi

unread,
Oct 22, 2011, 1:17:08 AM10/22/11
to will...@chromium.org, c...@chromium.org, Chromium-dev, Peter Kasting, aka...@chromium.org, Brett Wilson
I'm all for smaller binaries but I usually test Chromium with Release builds, so I was wondering if we could provide a way to use VLOG from Release builds:

1) Disable VLOG only from binaries built with branding=Chrome.
2) Disable VLOG from 'Release' builds by default but allow developers to enable VLOG by some GYP flag that they can have in ~/.gyp/include.gyp.

Satoru

Brett Wilson

unread,
Oct 22, 2011, 1:31:11 AM10/22/11
to Satoru Takabayashi, will...@chromium.org, c...@chromium.org, Chromium-dev, Peter Kasting, aka...@chromium.org
On Fri, Oct 21, 2011 at 10:17 PM, Satoru Takabayashi
<sat...@chromium.org> wrote:
> I'm all for smaller binaries but I usually test Chromium with Release
> builds, so I was wondering if we could provide a way to use VLOG from
> Release builds:
> 1) Disable VLOG only from binaries built with branding=Chrome.
> 2) Disable VLOG from 'Release' builds by default but allow developers to
> enable VLOG by some GYP flag that they can have in ~/.gyp/include.gyp.

Even DVLOG will be the same as DLOG, which is actually currently
enabled in non-official builds with some switches. There is also a
#define flag to override this.

Brett

Brett Wilson

unread,
Oct 22, 2011, 1:37:38 AM10/22/11
to Fred Akalin, Chromium-dev

That would be great. Maybe pick some directories of chrome/browser and
convert them :)

With owners this may be a complicated change. Is VLOG -> DVLOG
search-and-replace the type of thing we can decide to do without
owners?

Brett

Satoru Takabayashi

unread,
Oct 22, 2011, 8:45:20 AM10/22/11
to Brett Wilson, will...@chromium.org, c...@chromium.org, Chromium-dev, Peter Kasting, aka...@chromium.org
Taking another look at the thread, my previous post seemed to be irrelevant . You originally meant to disable VLOG for "official release build", right? I somehow misinterpreted that you were suggesting to disable VLOG for release build regardless of whether it's official or not.

BTW, I learned how logging behaviors were configured in logging.h:

if official release build:
  ENABLE_DLOG = 0
  ENABLE_DCHECK = 0
if non-official release build:
  ENABLE_DLOG = 0
  ENABLE_DCHECK = 1  // so that --enable-dcheck works
if debug build:
  ENABLE_DLOG = 1
  ENABLE_DCHECK = 1

Your original post said "If you need logging, the normal answer is that you should use a debug
build or a normal release build (which will have all debug logging in it).", but  DLOG seems to be stripped from non-official release build. Am I misunderstanding something, again?

Satoru


Brett

Sigurður Ásgeirsson

unread,
Oct 23, 2011, 10:00:40 AM10/23/11
to bre...@chromium.org, Fred Akalin, Chromium-dev
On Fri, Oct 21, 2011 at 18:02, Brett Wilson <bre...@chromium.org> wrote:
On Fri, Oct 21, 2011 at 2:24 PM, Fred Akalin <aka...@chromium.org> wrote:
> On Thu, Oct 20, 2011 at 11:46 PM, Brett Wilson <bre...@chromium.org> wrote:
>> More than 500K of the 24MB size of chrome.dll consists of non-debug
>> log statements. These are the strings and the code to do the checks
>> and do all the stream operations. This does not count CHECK which
>> presumably we want to crash. This size is unreasonable to be pushing
>> to all of our users' computers.
>
> Why?  What are the benefits of saving 2% of the size of chrome.dll?
> Will it reduce the overall installer size?  If so, given that strings
> are highly compressible, how much?  Will it reduce Chrome startup
> time?  If so, by how much and why?  Are the strings lumped together in
> one place in the dll, or are they scattered with other constants which
> are more often used?

The strings are not lumped together. And a bunch of the space is code
bloat. For example, here is the release mode code generated:

VLOG(1) << "hello";


Not to be a pedant, but this code has to be from a component build. I suspect the official release can carve this code down quite a bit with e.g. cross-module inlining.
Maybe it's time to look at ways to reduce the code bloat, at least in official builds? I posit it should be possible to optimize this down to a test followed by single printf-like function invocation. The unfortunate syntax we chose for logging might make this expensive in compilation time, however :(.

Every time you type VLOG, you get this code on 100's of millions on
people's computers, which includes the name of the file as a string
and all the strings you specify in the log statement. I don't think
people appreciate this bloat.


Syzygy will shortly help with the startup and runtime overhead to this by moving the unused code and data out of the hot path (and hot working set pages). We won't help the size overhead, however.

Brett Wilson

unread,
Oct 23, 2011, 12:14:58 PM10/23/11
to Sigurður Ásgeirsson, Fred Akalin, Chromium-dev
On Sun, Oct 23, 2011 at 7:00 AM, Sigurður Ásgeirsson <si...@chromium.org> wrote:
> On Fri, Oct 21, 2011 at 18:02, Brett Wilson <bre...@chromium.org> wrote:
>>
>> On Fri, Oct 21, 2011 at 2:24 PM, Fred Akalin <aka...@chromium.org> wrote:
>> > On Thu, Oct 20, 2011 at 11:46 PM, Brett Wilson <bre...@chromium.org>
>> > wrote:
>> >> More than 500K of the 24MB size of chrome.dll consists of non-debug
>> >> log statements. These are the strings and the code to do the checks
>> >> and do all the stream operations. This does not count CHECK which
>> >> presumably we want to crash. This size is unreasonable to be pushing
>> >> to all of our users' computers.
>> >
>> > Why?  What are the benefits of saving 2% of the size of chrome.dll?
>> > Will it reduce the overall installer size?  If so, given that strings
>> > are highly compressible, how much?  Will it reduce Chrome startup
>> > time?  If so, by how much and why?  Are the strings lumped together in
>> > one place in the dll, or are they scattered with other constants which
>> > are more often used?
>>
>> The strings are not lumped together. And a bunch of the space is code
>> bloat. For example, here is the release mode code generated:
>>
>> VLOG(1) << "hello";
>>
>
> Not to be a pedant, but this code has to be from a component build. I
> suspect the official release can carve this code down quite a bit with e.g.
> cross-module inlining.

You're right. I get 79 bytes with WPO (compared to 104 here). Still a
lot, though.

Brett

Greg Thompson

unread,
Oct 23, 2011, 12:57:35 PM10/23/11
to lipa...@google.com, pkas...@google.com, Brett Wilson, Chromium-dev, aka...@chromium.org


On Oct 21, 2011 9:14 PM, "Lingeshwaran Palaniappan" <lipa...@google.com> wrote:
>
> How about we make VLOG cheap?
> A simplistic solution is instead of VLOG actually emitting the string we just emit a number(That corresponds to a string). Which can later be converted to the corresponding string by a tool or a listener if real time is needed. 

This is more or less how MS's WPP Software Tracing works. It supports logging data too (printf-style strings). It has very low overhead when nothing is consuming trace events.

Sigurður Ásgeirsson

unread,
Oct 23, 2011, 3:55:42 PM10/23/11
to g...@chromium.org, lipa...@google.com, pkas...@google.com, Brett Wilson, Chromium-dev, aka...@chromium.org
On Sun, Oct 23, 2011 at 12:57, Greg Thompson <g...@chromium.org> wrote:


On Oct 21, 2011 9:14 PM, "Lingeshwaran Palaniappan" <lipa...@google.com> wrote:
>
> How about we make VLOG cheap?
> A simplistic solution is instead of VLOG actually emitting the string we just emit a number(That corresponds to a string). Which can later be converted to the corresponding string by a tool or a listener if real time is needed. 

This is more or less how MS's WPP Software Tracing works. It supports logging data too (printf-style strings). It has very low overhead when nothing is consuming trace events.

WPP's properties are super great in all respects, except that it's a PITA to integrate with. 
For those who don't know of WPP, the properties you get are (in order of importance from my POV):
  1. Runtime-controllable log verbosity.
    You can crank the log verbosity for running programs up or down (per log facility) by command line tools or through APIs.
  2. Typesafe format string logging.
    Without compiler support to check format strings, they're a very poor choice for error logging, as there'll invariably be mismatches between format strings and parameters. WPP achieves type safety through an external preprocessor and macro magic that's an unbelievable PITA to integrate with anything else.
  3. The format strings are not in the executable.
    The format strings are pushed to the symbols, so they don't get in distribution's or user's way, but any log tool with symbol access can retrieve them to yield formatted output.
  4. Virtually no overhead to logging when no-one is listening.
    The code injected for a log statement boils down to if (some_global) PrintfLikeFunctionInvocation(format string, params);
  5. Very low overhead and virtually no synchronization when someone is listening.
    There's no string formatting done on logging, the binary params are just snarfed to a buffer, that's then shunted to ETW. ETW in turn maintains a buffer parked against the logical CPU, so in most cases there's no synchronization when pushing a message.
I've been thinking that it should be possible to achieve pretty much same properties for our logging machinery through a combination of some template magic and source (post) processing.
IMHO it'd be a great boon to be able to leave a bunch of logging in all shipped Chromen, provided that we had the facility for allowing users to easily capture and upload logs to go with error reports.

Sawbuck [http://code.google.com/p/sawbuck] already makes it easy to crank Chrome (Windows) logging volume up or down at runtime, and you can then ask users to copy snippets of the log traffic into error reports.
Sawdust [http://code.google.com/p/sawbuck/source/browse/#svn%2Ftrunk%2Fsawdust] is a (incomplete) tool that'll quietly capture logs into circular ETW log files, and then provides a one-click uploader to http://crash for error reports. The idea is that users who perhaps occasionally see trouble of some particular sort should be able to install the tool (it's a traybar icon), then submit their logs when the trouble manifests.

Fred Akalin

unread,
Oct 24, 2011, 3:55:32 PM10/24/11
to bre...@chromium.org, Chromium-dev
On Thu, Oct 20, 2011 at 11:46 PM, Brett Wilson <bre...@chromium.org> wrote:
> Reviewers should please challenge all non-"D" logging statements. We
> should treat these as something exceptional and temporary, like we do
> when we're trying to track down an obscure crash and somebody will put
> a bunch of extra CHECKs in. If you have a real need for non-debug
> logging, there should be a reason for why you need it and a bug for
> removing it when this reason is over.

In a code review I saw someone interpret this as 'don't use CHECKs',
i.e. it's a 'non-D logging statement'. Is this part of what you
meant?

Relatedly, don't we interact with check failures mostly by crash
reports? If so, then the logging facilities provided by CHECK don't
really do much, right, since they don't end up in the backtraces. I
wonder if there would be savings in changing CHECKs into plain
BreakDebugger() calls for official builds.

Brett Wilson

unread,
Oct 24, 2011, 4:27:18 PM10/24/11
to Fred Akalin, Chromium-dev
On Mon, Oct 24, 2011 at 12:55 PM, Fred Akalin <aka...@chromium.org> wrote:
> On Thu, Oct 20, 2011 at 11:46 PM, Brett Wilson <bre...@chromium.org> wrote:
>> Reviewers should please challenge all non-"D" logging statements. We
>> should treat these as something exceptional and temporary, like we do
>> when we're trying to track down an obscure crash and somebody will put
>> a bunch of extra CHECKs in. If you have a real need for non-debug
>> logging, there should be a reason for why you need it and a bug for
>> removing it when this reason is over.
>
> In a code review I saw someone interpret this as 'don't use CHECKs',
> i.e. it's a 'non-D logging statement'.  Is this part of what you
> meant?

I think it's generally the case that you should avoid CHECKs, yes.
Only use CHECK if you specifically want to crash in a Release build.
Reasons include security-sensitive things or troublesome areas where
sometimes there are bad pointers floating around that will crash later
and provide useless stacks. It's usually not worthwhile to use CHECKs
for things like "the function parameter is NULL" (I often recommend
not even DCHECKing this case since it usually crashes in an obvious
way, but situations will vary).

> Relatedly, don't we interact with check failures mostly by crash
> reports?  If so, then the logging facilities provided by CHECK don't
> really do much, right, since they don't end up in the backtraces.  I
> wonder if there would be savings in changing CHECKs into plain
> BreakDebugger() calls for official builds.

If we have a lot of CHECKs (I'm not actually sure how many there are
and if it will make a difference), this sounds like it might be a good
idea.

Brett

Peter Kasting

unread,
Oct 24, 2011, 4:30:04 PM10/24/11
to aka...@chromium.org, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 12:55 PM, Fred Akalin <aka...@chromium.org> wrote:
In a code review I saw someone interpret this as 'don't use CHECKs',
i.e. it's a 'non-D logging statement'.  Is this part of what you
meant?

In general, we should be using CHECK in two cases:

(1) If failing an assertion will lead to a complete security compromise, or some similarly disastrous outcome.  For example, if we're trying to validate data coming from the renderer, we might want to crash the browser or renderer rather than let an attacker exploit an assertion failure to take over the user's system.

(2) We're trying to determine where some assertions are failing for real-world systems by inserting CHECKs to get crash dumps for code that might be violating its contracts.

Outside these cases, we should mostly be using DCHECK rather than CHECK.

Relatedly, don't we interact with check failures mostly by crash
reports?  If so, then the logging facilities provided by CHECK don't
really do much, right, since they don't end up in the backtraces.  I
wonder if there would be savings in changing CHECKs into plain
BreakDebugger() calls for official builds.

I don't know what BreakDebugger() does, but if it doesn't crash the process (when not in a debugger), that would be bad because it would fail to achieve the goal of case (1) above.

PK

Scott Hess

unread,
Oct 24, 2011, 4:34:37 PM10/24/11
to bre...@chromium.org, Fred Akalin, Chromium-dev

In my experience, what the CHECK() is logging is almost always
obvious. But there's no reason we couldn't add a breakpad key to pass
the offending log line along with the crash.

-scott

Fred Akalin

unread,
Oct 24, 2011, 4:55:42 PM10/24/11
to Peter Kasting, bre...@chromium.org, Chromium-dev
> I don't know what BreakDebugger() does, but if it doesn't crash the process
> (when not in a debugger), that would be bad because it would fail to achieve
> the goal of case (1) above.
> PK

Yeah, it's not a great name. It does crash the process when not in
the debugger; it's exactly what CHECK() and LOG(FATAL) use.

Fred Akalin

unread,
Oct 24, 2011, 5:01:02 PM10/24/11
to Scott Hess, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 1:34 PM, Scott Hess <sh...@chromium.org> wrote:
> In my experience, what the CHECK() is logging is almost always
> obvious.  But there's no reason we couldn't add a breakpad key to pass
> the offending log line along with the crash.

Right, the fact that what the CHECK() is logging is almost always
obvious is an indication that we can save some code in official
builds.

To clarify, CHECK()s need to create a LogMessage object to support the
"CHECK(...) << "blah blah"" syntax, and also for variants like
CHECK_EQ(). So if the log message isn't important, then CHECK(foo)
can simply expand to "if (!foo) BreakDebugger();" instead of what it
does now, which is more like "if (!foo) { <create LogMessage object,
then immediately destroy it, with ~LogMessage calling BreakDebugger>
}".

On the other hand, there may be times when the log message is
important. It seems to me, say, doing that on explicit LOG(FATAL)s
would be the way to go, and then uploading the log message to breakpad
in that case.

Peter Kasting

unread,
Oct 24, 2011, 5:05:04 PM10/24/11
to aka...@chromium.org, Scott Hess, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 2:01 PM, Fred Akalin <aka...@chromium.org> wrote:
To clarify, CHECK()s need to create a LogMessage object to support the
"CHECK(...) << "blah blah"" syntax, and also for variants like
CHECK_EQ().  So if the log message isn't important, then CHECK(foo)
can simply expand to "if (!foo) BreakDebugger();" instead of what it
does now, which is more like "if (!foo) { <create LogMessage object,
then immediately destroy it, with ~LogMessage calling BreakDebugger>
}".

On the other hand, there may be times when the log message is
important.  It seems to me, say, doing that on explicit LOG(FATAL)s
would be the way to go, and then uploading the log message to breakpad
in that case.

I would support this.

Frankly, I'd support it for DCHECKs too (and make people use DLOG(FATAL) or something if they want a message).  The only messages I've seen on DCHECKs have been pretty lame, e.g.

  DCHECK(foo) << "foo is NULL!  Someone didn't initialize it.";

PK 

James Hawkins

unread,
Oct 24, 2011, 5:30:36 PM10/24/11
to pkas...@google.com, aka...@chromium.org, Scott Hess, bre...@chromium.org, Chromium-dev
Agreed.  Hopefully making this change will motivate devs to write better, non-ambiguous DCHECK conditionals.

Fred Akalin

unread,
Oct 24, 2011, 6:17:14 PM10/24/11
to Satoru Takabayashi, Brett Wilson, will...@chromium.org, c...@chromium.org, Chromium-dev, Peter Kasting
On Sat, Oct 22, 2011 at 5:45 AM, Satoru Takabayashi
<sat...@chromium.org> wrote:

> BTW, I learned how logging behaviors were configured in logging.h:
> if official release build:
>   ENABLE_DLOG = 0
>   ENABLE_DCHECK = 0
> if non-official release build:
>   ENABLE_DLOG = 0
>   ENABLE_DCHECK = 1  // so that --enable-dcheck works
> if debug build:
>   ENABLE_DLOG = 1
>   ENABLE_DCHECK = 1
> Your original post said "If you need logging, the normal answer is that you
> should use a debug
> build or a normal release build (which will have all debug logging in it).",
> but  DLOG seems to be stripped from non-official release build. Am I
> misunderstanding something, again?

No, that is correct.

Given that the current behavior is that DLOG is enabled only for debug
builds, what should we do?

Changing it to be turned on in non-official release builds is
possible, but that seems surprising. On the other hand, DCHECK is
already enabled in release builds, and that's pretty surprising, too.

Scott Hess

unread,
Oct 24, 2011, 6:31:31 PM10/24/11
to Peter Kasting, aka...@chromium.org, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 2:05 PM, Peter Kasting <pkas...@chromium.org> wrote:

There's always LOG_IF(FATAL, test) if one cares.

That said, also consider that the existing implementation of CHECK()
is helpful in debugging failures on the waterfall, where you don't get
a crash report. This may be covered by the code which dumps the
backtrace, I'd have to look around to see if it's complete. If we
threw out the ability to stream arguments to CHECK(), it could
probably be re-implemented more simply with little or no loss of
functionality.

-scott

Fred Akalin

unread,
Oct 24, 2011, 6:40:31 PM10/24/11
to Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 3:31 PM, Scott Hess <sh...@chromium.org> wrote:
> There's always LOG_IF(FATAL, test) if one cares.
>
> That said, also consider that the existing implementation of CHECK()
> is helpful in debugging failures on the waterfall, where you don't get
> a crash report.  This may be covered by the  code which dumps the
> backtrace, I'd have to look around to see if it's complete.  If we
> threw out the ability to stream arguments to CHECK(), it could
> probably be re-implemented more simply with little or no loss of
> functionality.

Just to be clear, there are two proposals:

1. Make CHECK(...) not emit anything and ignore stream arguments for
official builds. This shouldn't affect debug/waterfall builds, etc.
2. Make CHECK(...) not take stream parameters in general. It would
still emit a log message (and CHECK_EQ would also emit what it
currently does) but it would be (hopefully) less emitted code.

Aaron Boodman

unread,
Oct 24, 2011, 9:31:36 PM10/24/11
to aka...@chromium.org, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev

I really like using CHECK* instead of DCHECK. I know that Brett and Peter don't.

In the early days of the project I once heard guidance from Darin that
it was often better to get a crash report with a clearly violated
assertion, rather than carry on in a zombie state, getting weird error
reports from users. That guidance really resonated with me, and I've
been following it since.

It seems we've backed off from then (or I misunderstood the subtlety),
but I would still like to continue using this in the extensions system
as long as it isn't too** costly. Is it OK to use CHECK if there's no
message? Can we make it OK?

* I'm talking specifically about CHECK/DCHECK - not LOG, VLOG, etc. I
already use those only rarely.
**I'm not talking about using it in tight loops or other
performance-sensitive ways.

- a

Lingeshwaran Palaniappan

unread,
Oct 24, 2011, 9:40:59 PM10/24/11
to aka...@chromium.org, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
Fred - With some preprocessor trickery it is possible to make CHECK(condition) << "log stmt" in retail builds to emit code something like the following:
// "log stmt"
breakdebugger();
(i.e., the log stmt is commented out)

In debug builds it can remain the way it is today.(i.e., it is emitted)

The advantage seems to be when a developer gets the crash report and looks at the code he will still see the log stmt which might aid in debugging.
Another advantage seems to be we don't have to change all the files that use CHECK.

Thanks!
regards,
Lingesh 

Lingeshwaran Palaniappan

unread,
Oct 24, 2011, 9:47:16 PM10/24/11
to aka...@chromium.org, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
Never mind this is same as Fred's proposal :) Sorry for the traffic.

Peter Kasting

unread,
Oct 24, 2011, 10:06:34 PM10/24/11
to Aaron Boodman, aka...@chromium.org, Scott Hess, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 6:31 PM, Aaron Boodman <a...@chromium.org> wrote:
It seems we've backed off from then (or I misunderstood the subtlety),
but I would still like to continue using this in the extensions system
as long as it isn't too** costly. Is it OK to use CHECK if there's no
message? Can we make it OK?

**I'm not talking about using it in tight loops or other
performance-sensitive ways.

I don't think it's explicitly wrong to use CHECK like this.

I do think that it's better to be in the habit of using DCHECK if one is going to be in a habit.  Not having to verify your assertions saves a tiny bit of code size for our users even if it doesn't have a meaningful perf impact (and it prevents you from accidentally having a perf impact).  And most of the time we assume DCHECK is enough because we assume that things we're confident enough to assert are always true are, in fact, always true, and we don't need to double-check ourselves.  Seeing a CHECK always makes me stop and wonder if this is in fact an assertion that we're not sure of and so we feel the need to check it in official builds.  It's nice not to worry your code's readers :)

All that said, I don't think we intend to make the rules about this hard-and-fast, so if in your judgment your usage of CHECK is justified, I'm not prepared to gainsay you.

PK

Fred Akalin

unread,
Oct 25, 2011, 3:23:38 PM10/25/11
to Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 3:40 PM, Fred Akalin <aka...@chromium.org> wrote:
> Just to be clear, there are two proposals:
>
> 1. Make CHECK(...) not emit anything and ignore stream arguments for
> official builds.  This shouldn't affect debug/waterfall builds, etc.
> 2. Make CHECK(...) not take stream parameters in general.  It would
> still emit a log message (and CHECK_EQ would also emit what it
> currently does) but it would be (hopefully) less emitted code.
>

Since this thread is getting long, I've filed a bug for all the issues raised.

VLOG -> DVLOG: http://code.google.com/p/chromium/issues/detail?id=101424
Dropping CHECK messages in official builds:
http://code.google.com/p/chromium/issues/detail?id=101559
Making CHECK not expose a stream:
http://code.google.com/p/chromium/issues/detail?id=101561

Fred Akalin

unread,
Oct 31, 2011, 4:17:50 PM10/31/11
to Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
On Tue, Oct 25, 2011 at 12:23 PM, Fred Akalin <aka...@chromium.org> wrote:
> VLOG -> DVLOG: http://code.google.com/p/chromium/issues/detail?id=101424

I was going to start on this bug (debug logging needs to be be behind
a flag for non-official release modes, like dchecks) but I'll be on
leave in the near future (2 weeks or so).

Brett is on leave, also, for a while.

So if anyone wants to pick this up while we're gone, they're welcome
to. Otherwise, I'll do so when I get back.

Lingeshwaran Palaniappan

unread,
Oct 31, 2011, 4:43:46 PM10/31/11
to aka...@chromium.org, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
Fred - if you dont mind giving me a brain dump I can take a crack at it and get it ready for review..

Fred Akalin

unread,
Nov 1, 2011, 7:13:48 PM11/1/11
to Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
I put the brain dump on the bug:
http://code.google.com/p/chromium/issues/detail?id=101424 . It should
be detailed enough to work from. Thanks for volunteering!

William Chan (陈智昌)

unread,
Nov 10, 2011, 4:01:15 PM11/10/11
to aka...@chromium.org, Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
+rvargas

This review got sent to me. I haven't kept up to date with all the discussion, but Ricardo still disagrees with it. I'd like it discussed a bit further here before I proceed with the base/OWNERS review. I've copy pasted the relevant discussion from the codereview thread.

Ricardo:
=====
I still don't believe that this is something that we should do.

If we can provide a release but not official build, we can also add very
specific code to debug whatever is happening (being that regular LOGs, CHECKs,
dialogs or whatever), and remove that debugging crust after the bug is fixed.

I don't believe the long term value of debugging log statements(*) to be high
enough to justify their existence, much less the complexity and
counter-intuitiveness of a general mechanism to enable them to live on release
builds.

However, I'm not a base owner, and that means that I could not approve this CL
even if I wanted it to land.

(*) I don't mean we should get rid of DLOGS, I mean the type of messages that
someone has to add to debug something on the bots (for instance)... something so
uncommon that it's priority goes to DVLOG with some number. If it has that
priority for real (even DLOG(INFO)), it should go away on release.
=====

Lingeshwaran:
=====
I had a chat with Ricardo as well. It looks like his main point of concern
is that our logging system is heavy weight and slow.

However both of us do agree that it is important to see what is happening
inside a release build if a need arises.

Even if we build a light and fast logging system we would still need a
mechanism for enabling/disabling logging in release builds. I don't think
there is disagreement there. And this CL provides the way for that.
Although when we re-design the logging system the guts of it might change
the consumers of it can still rely on the fact that DVLOG is on by default
in debug, off by default in non release and can be enabled as needed, and
stripped out in official builds.(So consumers dont have to change much).

Also in the past VLOGs have proved really effective to debug some bot only
failures(at least I can attest to one instance in which it took us a week
to track down a bot only failure and we tracked it down primarily by
enabling vlog on certain files and letting it run a couple of days on the
bots). Until we redesign the logging system it does not make sense to fly
blind with no logs for non official release builds.
=====

Ricardo (in response to "I don't think there is disagreement there"):
=====
Nope. We also disagree there. Having macros that are meant to be debug-only be
now compiled in release builds but somewhat disabled through a command line
option (or lack of) is counter intuitive, and adds another layer of complexity
to logging.h (even if at this point the change looks quite trivial there).

I don't think the crux of the issue is some future redesign of the logging
system. It is what I tried to express before: debugging specific issues on the
bots should be a one time add / remove thing. If someone finds him(her)self
doing that all the time for the same logs, then that points to either the lack
of a better troubleshooting method in that part of the code, or the need for a
LOG (or VLOG) enabled all the time (not Dxx).
=====

Tommi

unread,
Nov 11, 2011, 4:30:24 AM11/11/11
to si...@chromium.org, g...@chromium.org, lipa...@google.com, pkas...@google.com, Brett Wilson, Chromium-dev, aka...@chromium.org
What about the proposal below?  It would help with reducing the binary size, improve performance and allow more verbose logging.
Granted, this is a big undertaking, but that hasn't stopped us before.

Jonathan Dixon

unread,
Nov 11, 2011, 3:35:20 PM11/11/11
to will...@chromium.org, aka...@chromium.org, Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
I missed one step in this thread: What is the use-case for --enable-dlog?
Either DLOGs are built into a given build, or they are not.
- If they are built in we are already carrying the cost of them in binary size regardless, and have the ability to turn on & off with --log-level, --v, et al.
- And if they're not built in, well no flag would seem to achieve that much.

like wise I never quite understood the use-case for --enable-dcheck. ISTM if you pay the cost of compiling them in you may as well just run them rather than run a check to see if you should run the checks...

On the original aim of having a way to strip VLOG I'm highly in favor. On the particular point of consistency I can see the case for DLOG having a command switch like DCHECK does, notwithstanding my comments on the usefulness of them above.


on a pure convenience point I've had times where it would have been nice to force ENABLE_DLOG and ENABLE_DCHECK to 1 just through a gyp flag, but I don't think that's the topic here.

Tim Steele

unread,
Nov 14, 2011, 7:00:11 PM11/14/11
to a...@google.com, aka...@chromium.org, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev
On Mon, Oct 24, 2011 at 6:31 PM, Aaron Boodman <a...@chromium.org> wrote:
On Mon, Oct 24, 2011 at 3:40 PM, Fred Akalin <aka...@chromium.org> wrote:
> On Mon, Oct 24, 2011 at 3:31 PM, Scott Hess <sh...@chromium.org> wrote:
>> There's always LOG_IF(FATAL, test) if one cares.
>>
>> That said, also consider that the existing implementation of CHECK()
>> is helpful in debugging failures on the waterfall, where you don't get
>> a crash report.  This may be covered by the  code which dumps the
>> backtrace, I'd have to look around to see if it's complete.  If we
>> threw out the ability to stream arguments to CHECK(), it could
>> probably be re-implemented more simply with little or no loss of
>> functionality.
>
> Just to be clear, there are two proposals:
>
> 1. Make CHECK(...) not emit anything and ignore stream arguments for
> official builds.  This shouldn't affect debug/waterfall builds, etc.
> 2. Make CHECK(...) not take stream parameters in general.  It would
> still emit a log message (and CHECK_EQ would also emit what it
> currently does) but it would be (hopefully) less emitted code.

I really like using CHECK* instead of DCHECK. I know that Brett and Peter don't.

In the early days of the project I once heard guidance from Darin that
it was often better to get a crash report with a clearly violated
assertion, rather than carry on in a zombie state, getting weird error
reports from users. That guidance really resonated with me, and I've
been following it since.

Yeah, Darin (and Linus in context of sync) shared this with me as well, and it resonates to this day, every day, with every sync bug we've ever encountered. Having an end-state broken dataset is nowhere near as useful as knowing how it got there in the wild.  When a user files a sync bug saying "my bookmarks look like <...>, but i'd expect it them to look like <...>", it's really, really, really hard to jump to a conclusion like "oh, your laptop running M10 that you only sometimes turn on appears to be the first to have introduced this corruption into the system".  So we have a fair bit of CHECKing in sync code, despite the fact that our style guide heavily discourages it.

Of course, the best tool for knowing how things wound up as they did would be logging, and I'm not sure anything would stand to benefit more from that than sync. But I understand the decision to make our lives harder if it makes Chrome faster. It's no surprise though that the people you see clamoring to salvage logging in release builds on this thread are people working mostly on sync :)  I'd love to know more about the magic that Siggi has in mind (I don't know anything about WPP), how hard it would be to implement, and how to help.


It seems we've backed off from then (or I misunderstood the subtlety),
but I would still like to continue using this in the extensions system
as long as it isn't too** costly. Is it OK to use CHECK if there's no
message? Can we make it OK?

* I'm talking specifically about CHECK/DCHECK - not LOG, VLOG, etc. I
already use those only rarely.
**I'm not talking about using it in tight loops or other
performance-sensitive ways.

- a

William Chan (陈智昌)

unread,
Nov 15, 2011, 11:36:08 AM11/15/11
to aka...@chromium.org, Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
Thanks for the discussion guys. It seems to be covering a whole range of subjects, which are definitely worth talking about. I'm concerned about this particular change right now: http://codereview.chromium.org/8467028/, which enables DVLOG in release builds if a flag is passed, but the code wouldn't be compiled in for official builds.

Upon reflection, if the only use case is for the bots, then I am with Ricardo. Just add a temporary LOG. Adding this facility only encourages people to leave DVLOGs for long periods of time. If there is another use case for DVLOGs on release builds that has been discussed elsewhere, I have missed it and it might change my opinion.

Do others disagree? I'd love to here other opinions here if so.

Fred Akalin

unread,
Nov 16, 2011, 9:56:13 PM11/16/11
to William Chan (陈智昌), Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
On Tue, Nov 15, 2011 at 8:36 AM, William Chan (陈智昌)
<will...@chromium.org> wrote:
> Thanks for the discussion guys. It seems to be covering a whole range of
> subjects, which are definitely worth talking about. I'm concerned about this
> particular change right now: http://codereview.chromium.org/8467028/, which
> enables DVLOG in release builds if a flag is passed, but the code wouldn't
> be compiled in for official builds.
> Upon reflection, if the only use case is for the bots, then I am with
> Ricardo. Just add a temporary LOG. Adding this facility only encourages
> people to leave DVLOGs for long periods of time. If there is another use
> case for DVLOGs on release builds that has been discussed elsewhere, I have
> missed it and it might change my opinion.
> Do others disagree? I'd love to here other opinions here if so.

Hey guys. I was the one who was originally planning to land that
change, but I asked Lingesh to do it since I was going on leave.

My original rationale was that we were already doing it (i.e., on by
default for debug builds, off by default for release builds but behind
a flag, and stripped out for official builds) for DCHECKs, so we can
do it for DLOGs as well. However, on reflection, I don't think I've
ever used DCHECKs on release builds, ever. In fact, what exactly is
this use case for this? Has anyone used it? In fact, I notice there's
a "dcheck_always_on" gyp flag in build/common.gypi with the comment
"Set to 1 to enable dcheck in release without having to use the
flag.". If that is the only use case for dchecks in release mode, I'd
like to remove the command-lineflag altogether and keep the gyp flag,
and maybe we can do something similar for dlogs.

In any case, to keep from ratholing in this particular issue, here's
what I suggest:

1) Skip Lingesh's CL for now. Lingesh and I will proceed with
converting VLOGs to DVLOGs. If there's a need for logs for release
bots, etc., one can always convert the DVLOGs back to VLOGs
temporarily.
2) I will investigate whether we need a command-line flag for DCHECKs
on release builds, or if the gyp flag suffices.
3) I will also investigate whether it's desirable to have a gyp flag
to enable DLOGs on release builds.

I hope we can all agree on #1. Comments and discussion on #2 and #3
are welcome.

Steven Bennetts

unread,
Nov 17, 2011, 4:56:10 PM11/17/11
to aka...@chromium.org, William Chan (陈智昌), Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
I frequently run release builds (primarily on ChromeOS) with --enable-dcheck. It is convenient not to have to re-compile to do so.

Personally I would like to see us enable DCHECK for developer release builds by default. I have tracked down at least two subtle bugs that were eventually caught with DCHECKs. I have also been bitten numerous times by failing DCHECKs when debugging something with a Debug build; these checks would have been caught and fixed much sooner if all developer builds triggered them.

A counter argument is that if improperly written, DCHECKs can have side effects, so enabling them by default would make developer Release builds that much more different from production builds. Even so, I would personally rather have the increased DCHECK coverage, as I believe this is more likely to catch edge cases than to mask production failures due to bad DCHECKs.


Achuith Bhandarkar

unread,
Nov 17, 2011, 5:11:52 PM11/17/11
to stev...@google.com, aka...@chromium.org, William Chan (陈智昌), Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
+1 to Steven's point about increased DCHECK coverage - I don't believe we run tests on any bots with DCHECKs enabled (please correct me if I'm wrong). I feel like we could catch a number of easy-to-fix bugs if we did. 

In particular, I feel like we probably have a few thread-safety violations that could be caught by existing threading DCHECKs that could end up fixing hard-to-reproduce races/crashes. 

Nico Weber

unread,
Nov 17, 2011, 5:13:18 PM11/17/11
to ach...@google.com, stev...@google.com, aka...@chromium.org, William Chan (陈智昌), Lingeshwaran Palaniappan, Scott Hess, Peter Kasting, bre...@chromium.org, Chromium-dev, Ricardo Vargas
On Thu, Nov 17, 2011 at 2:11 PM, Achuith Bhandarkar <ach...@google.com> wrote:
> +1 to Steven's point about increased DCHECK coverage - I don't believe we
> run tests on any bots with DCHECKs enabled (please correct me if I'm wrong).

(All dbg builds on the main waterfall run with DCHECKs enabled, with
is about 50% of the bots. All bots used by the commit queue run
release builds with DCHECKs explicitly enabled, too).

Reply all
Reply to author
Forward
0 new messages