ATTENTION: Use VLOG() instead of LOG(INFO)

13,692 views
Skip to first unread message

Peter Kasting

unread,
Oct 15, 2010, 6:31:34 PM10/15/10
to Chromium-dev
Until recently some people have been using LOG(INFO) as "debug logging", since the default logging level was WARNING, which didn't print INFO messages.  However, there are problems with this:
  • If everyone does this, then when you set the log level to INFO to try to debug, you're deluged with messages.
  • Semantically, LOG() is supposed to be more for "messages that should always be printed", and INFO means "informative" rather than "debug" or "not printed in normal usage".
This has become a serious issue recently as we've changed the default LOG level to INFO.  Now Chrome builds are much noisier.  This is at least annoying, and in some cases worse as some users have reported slowdowns due to console log spam.

Instead of using LOG(INFO) for debugging, or some set of #defines that map MY_CUSTOM_LOG to various values including LOG(INFO), use VLOG.  VLOG is a recently-added facility that allows for extremely fine-grained logging control:
  • VLOG() levels can be adjusted on a per-module basis at runtime.
  • VLOG() takes an arbitrary integer value (higher numbers should be used for more verbose logging), so you can make your logging levels as granular as you wish.
Example usage:

./chrome --v=1 --vmodule=foo=2,bar=3

This runs Chrome with the global VLOG level set to "print everything at level 1 and lower", but prints levels up to 2 in foo.cc and levels up to 3 in bar.cc.

I have a set of changes locally, which I'll be working to check in, which globally convert LOG(INFO) to VLOG(1).  Please feel free to make drive-by comments on the code reviews if you know of code where this conversion is wrong, the VLOG level should be different than 1, the logging should just be removed, or any other non-default case.  In a few cases where people #defined their own logging facilities I have converted those and stripped the controlling macros (as VLOG's per-module control generally renders them obsolete).

I will also add this information to the Chrome style guide.

PK

Evan Martin

unread,
Oct 15, 2010, 6:35:45 PM10/15/10
to pkas...@google.com, Chromium-dev
On Fri, Oct 15, 2010 at 3:31 PM, Peter Kasting <pkas...@google.com> wrote:
> This has become a serious issue recently as we've changed the default LOG
> level to INFO.  Now Chrome builds are much noisier.  This is at least
> annoying, and in some cases worse as some users have reported slowdowns due
> to console log spam.

Especially if it's impacting users, I'm willing to temporarily undo
the default level change.
Or something like change it for official builds (I didn't really think
about it too hard).
What do you think?

> I have a set of changes locally, which I'll be working to check in, which
> globally convert LOG(INFO) to VLOG(1).

Thank you so much for doing this!

Dirk Pranke

unread,
Oct 15, 2010, 7:22:52 PM10/15/10
to pkas...@google.com, Chromium-dev
So, these are accessible from an about:labs panel, right? :)

-- Dirk

On Fri, Oct 15, 2010 at 3:31 PM, Peter Kasting <pkas...@google.com> wrote:

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

Peter Kasting

unread,
Oct 15, 2010, 8:11:54 PM10/15/10
to Evan Martin, Chromium-dev
On Fri, Oct 15, 2010 at 3:35 PM, Evan Martin <ev...@chromium.org> wrote:
On Fri, Oct 15, 2010 at 3:31 PM, Peter Kasting <pkas...@google.com> wrote:
> This has become a serious issue recently as we've changed the default LOG
> level to INFO.  Now Chrome builds are much noisier.  This is at least
> annoying, and in some cases worse as some users have reported slowdowns due
> to console log spam.

Especially if it's impacting users, I'm willing to temporarily undo
the default level change.
Or something like change it for official builds (I didn't really think
about it too hard).
What do you think?

I wouldn't worry about it on trunk.  I'll be getting the VLOG changes in soon enough.

On the M8 branch, I suggest reverting your change, so that our M8 builds aren't noisy.

PK

Chris Masone

unread,
Oct 23, 2010, 4:42:55 PM10/23/10
to pkas...@google.com, Evan Martin, Chromium-dev
I'm curious about the wildcarding that one can do to set VLOGging level...the example says "browser_*" would set vlog level in all files that start with that string...does this operate on whole paths?  Can I do "--vmodule=*chromeos*=2" to set the vlog level for all the files under chrome/browser/chromeos/ ?

--

Fred Akalin

unread,
Oct 23, 2010, 5:56:12 PM10/23/10
to cma...@chromium.org, pkas...@google.com, Evan Martin, Chromium-dev
No, it operates only on basename minus extension (ignoring -inl).
This matches the google-glog behavior. Is there a need for
directory-based matching? I can think about adding support for it,
but I'm hesitant to diverge from google-glog behavior even more.

Chris Masone

unread,
Oct 23, 2010, 6:21:55 PM10/23/10
to Fred Akalin, pkas...@google.com, Evan Martin, Chromium-dev
From the CHrome OS side, I could see us wanting to enable a higher logging level for chromeos-specific code, much of which is underneath chrome/browser/chromeos, than for the rest of the browser.

Peter Kasting

unread,
Oct 24, 2010, 5:42:08 PM10/24/10
to Fred Akalin, cma...@chromium.org, Evan Martin, Chromium-dev
On Sat, Oct 23, 2010 at 2:56 PM, Fred Akalin <aka...@chromium.org> wrote:
No, it operates only on basename minus extension (ignoring -inl).
This matches the google-glog behavior.  Is there a need for
directory-based matching?  I can think about adding support for it,
but I'm hesitant to diverge from google-glog behavior even more.

I suggest not adding things until we have explicitly found we need them (i.e. not just because we could imagine using them in the future).

VLOG() is already significantly more granular than LOG().  Let's run into its limits before we expand it further.

PK

Chris Masone

unread,
Oct 24, 2010, 6:10:14 PM10/24/10
to Peter Kasting, Fred Akalin, Evan Martin, Chromium-dev
On Sun, Oct 24, 2010 at 2:42 PM, Peter Kasting <pkas...@google.com> wrote:
On Sat, Oct 23, 2010 at 2:56 PM, Fred Akalin <aka...@chromium.org> wrote:
No, it operates only on basename minus extension (ignoring -inl).
This matches the google-glog behavior.  Is there a need for
directory-based matching?  I can think about adding support for it,
but I'm hesitant to diverge from google-glog behavior even more.

I suggest not adding things until we have explicitly found we need them (i.e. not just because we could imagine using them in the future).

Ok, then let me rephrase :-)
On Chrome OS, we'd very much like to enable a higher logging level for code specific to our platform than for the rest of the browser.  We could hit most of that by logging more for stuff under chrome/browser/chromeos/*
 
I understand the desire not to deviate too much from glog, though.  I remember asking ages ago about the possibility of migrating Chromium to google-glog...I can't remember if the answer was "sure, if you have the cycles, please do" or if there were underlying differences that make doing so non-trivial

Lingeshwaran Palaniappan

unread,
Oct 25, 2010, 9:13:21 PM10/25/10
to cma...@chromium.org, Peter Kasting, Fred Akalin, Evan Martin, Chromium-dev
Hi,
From chrome sync side also we would like to get extra logging for the sync stuff while tuning out the noise from other stuff. 

The functionality of vlog as it stands today is that it looks at the file name and it is pretty granular. It is possible to modify vlog to look at the entire filepath.

But thinking more about this an approach like the following would be better. This could retain the finer granularity at the same time provide area wise logging levels. The API signature is:
LOG(ZONE, severity, logmessage);

The zone would be a simple enum like chromeos, sync etc. In the command line the user can specify what severity level he wants for each zone. For the unspecified zones we will simply use the default severity level. On top of it the user can also specify specific file names on the command line which we will match using the current code in place. So it can be as granular as one wants.

The severity could be one of Information, warning, error and fatal(similar to glog)

I have some spare cycles available to do this(towards the middle of november). I can also clean up few areas of the code myself and once all the code has been migrated delete the unused macros.

But first I would like to have feedback from people on this design.
Thanks!
regards,
Lingesh

Peter Kasting

unread,
Oct 25, 2010, 9:30:46 PM10/25/10
to Lingeshwaran Palaniappan, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev
My basic comments are:

* We already have a lot of logging macros.  Do you know what PLOG or RAW_LOG do?  How many people knew about LOG_IF()?  In general, how does someone reading the code know what all these do, or someone writing new code know which to use?  As in Google's internal projects, as much as possible there should be one way to do things.  It would be nice not to add new methods unless we're deleting at least as many old ones.

* Moving away from functionality we got from Google internally is something we should only do for good reasons, because generally, things there have been used longer and more broadly, and reflect design experience.  (This is not always true, of course.)

* Logging for debugging purposes is effectively printf debugging.  We have debuggers for a reason.  If we're adding a lot of complex machinery to make debug logging easier, we may be doing something wrong, like not testing enough, not collecting enough UMA stats, not DCHECKing enough, people not knowing how to use their debuggers well enough, etc.  We've gotten a long way and written a lot of complex code without needing 500 different logging tactics.  We should only add more if we really need to.

PK

Dmitry Polukhin

unread,
Oct 26, 2010, 6:19:12 AM10/26/10
to pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
After massive replacement of LOG(INFO) with VLOG(1), Chrome OS logs became almost completely useless for analyzing what has happed on user machine and why. --v=1 is not a solution for triaging user's caches and issues. It's impossible to do on Release images and sometimes issue has no stable reproducer so if you observe it you need something to analyze - now we have nothing.

I thought that LOG(INFO) should be used for critical actions that happens only once or very rarely and important to triaging things with logs (postmortem analysis). Example, print that Chrome is checking for update or received  server response with update version. If all above should be VLOG(1), I don't understand when LOG(INFO) should be used at all. Could you please give couple example when it LOG(INFO) usage is valid?


PK

--

Scott Hess

unread,
Oct 26, 2010, 10:56:34 AM10/26/10
to dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
The basic problem is that people have been sprinkling LOG(INFO) around
to debug short-term problems (sometimes when developing), and then
leaving them in forever just in case they might be useful. Then when
something happens, you go look at the logs, and have ten thousand
lines of unrelated stuff to wade through, and you have no idea if any
of it is telling you something relevant to the problem at hand, or is
just random developers talking to themselves. Unfortunately, going
through the codebase and evaluating things on a case-by-case basis
would take forever, so things were changed in bulk.

Now that we have VLOG(), I think it would be reasonable to add
LOG(INFO) use back, and expect developers to justify use of LOG(INFO)
instead of VLOG(). It might also be reasonable to expect an
associated bug if you want to check verbose LOG(INFO) into the tree.
That would provide a slight brake on egregious use of LOG(INFO), and
presumably when the bug is fixed the LOG(INFO) lines can be removed.
Another idea was to require an email address so that readers know who
to ask.

Basically, I think the goal should be not to have a bunch of logging
lines just because they are imagined to be cheap and they might be
useful "someday".

-scott

Darin Fisher

unread,
Oct 26, 2010, 11:05:32 AM10/26/10
to sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
Personally, I'm a big fan of having "log modules" or the zones that were mentioned
previously.  NSPR's logging system used by Mozilla has this concept, and it is
great for exactly the reasons given in this thread.

Originally, I argued for adding something like Mozilla logging to Chrome, but folks
preferred to match google's logging system instead so that it would be familiar to
more people.  The argument was that everyone should LOG(INFO) important stuff,
and to filter, you could just grep the log file on the path snippet included in the logs.
Have we reached the point in which that approach does not scale?  I guess so.

-Darin

Dmitry Polukhin

unread,
Oct 26, 2010, 11:08:29 AM10/26/10
to Scott Hess, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
It sounds like we should just switch default reporting level to errors or warning in release branch just before release. And have info level for dev and beta channels. It would be much easier than bulk edit source code and remove useful things. Because we will have to do this bulk edit before each release.

Sanjeev Radhakrishnan

unread,
Oct 26, 2010, 12:25:46 PM10/26/10
to da...@google.com, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
+1. Logging with some concept of zones is very powerful and extremely useful. Windows has had ETW (http://msdn.microsoft.com/en-us/magazine/cc163437.aspx) for years which basically allowed you to specify logging providers and allow consumers to listen to events from a specific provider (Using ETW in conjunction with WPP (http://msdn.microsoft.com/en-us/library/ff556204.aspx) is especially powerful and low-cost). VLOG essentially provides some concept of a zone but the zone is restricted to the file name which may not be suffient in many cases.

I also disagree with the statement that verbose logging is because of an inability to use a debugger (I have many limitations but I think I can say with some confidence that the inability to use a debugger is not one of them). Debugging is what I do on my desktop, logging is what I expect the software to do at an end-user's machine. There are a myriad reasons in client software why an issue may only happen on a specific (or a specific set of) end-user machine(s) (this is unlike what Google3 has to deal with). ETW is used extensively and verbosely in the operating system and this is not because Dave Cutler and his team cannot use a debugger. If there are no listeners for a specific provider the cost is low.

I also agree with the comment about setting the default reporting level to errors or warnings for stable releases. In the absence of WPP this is how we lower the cost of logging at run-time. I disagree that the way to reduce cost is to reduce the amount of logging.

Scott Hess

unread,
Oct 26, 2010, 12:26:27 PM10/26/10
to Dmitry Polukhin, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
I'm not sure what you are suggesting. As I said, if the logging is
actionable, then go for it. If it's just there because it was useful
once and you think maybe it will be useful someday again, then delete
it.

This is very similar to optimization, where you should keep it simple
until you've determined that you actually do need something more
clever (and probably harder to understand and debug). Likewise, don't
check always-on log lines into the codebase until you're actually
debugging something using binaries you did not build, and once you do
tie it to a specific project (which will hopefully someday be
completed) rather than just letting it hang out forever.

If I sound like a crank on this, it's because in my experience log
output grows exponentially unless it is actively fought. Tragedy of
the commons and all.

-scott

Darin Fisher

unread,
Oct 26, 2010, 12:32:40 PM10/26/10
to Sanjeev Radhakrishnan, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
On Tue, Oct 26, 2010 at 9:25 AM, Sanjeev Radhakrishnan <sanj...@chromium.org> wrote:
+1. Logging with some concept of zones is very powerful and extremely useful. Windows has had ETW (http://msdn.microsoft.com/en-us/magazine/cc163437.aspx) for years which basically allowed you to specify logging providers and allow consumers to listen to events from a specific provider (Using ETW in conjunction with WPP (http://msdn.microsoft.com/en-us/library/ff556204.aspx) is especially powerful and low-cost). VLOG essentially provides some concept of a zone but the zone is restricted to the file name which may not be suffient in many cases.

I also disagree with the statement that verbose logging is because of an inability to use a debugger (I have many limitations but I think I can say with some confidence that the inability to use a debugger is not one of them). Debugging is what I do on my desktop, logging is what I expect the software to do at an end-user's machine. There are a myriad reasons in client software why an issue may only happen on a specific (or a specific set of) end-user machine(s) (this is unlike what Google3 has to deal with). ETW is used extensively and verbosely in the operating system and this is not because Dave Cutler and his team cannot use a debugger. If there are no listeners for a specific provider the cost is low.

I also agree with the comment about setting the default reporting level to errors or warnings for stable releases. In the absence of WPP this is how we lower the cost of logging at run-time. I disagree that the way to reduce cost is to reduce the amount of logging.

Note, at runtime in release builds logging is disabled globally unless the user runs with --enable-logging.  In other words, the runtime cost is not really an issue for end users.  So, the default log level is not really that interesting in that context.

Sanjeev Radhakrishnan

unread,
Oct 26, 2010, 12:36:04 PM10/26/10
to Darin Fisher, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
On Tue, Oct 26, 2010 at 9:32 AM, Darin Fisher <da...@chromium.org> wrote:
On Tue, Oct 26, 2010 at 9:25 AM, Sanjeev Radhakrishnan <sanj...@chromium.org> wrote:
+1. Logging with some concept of zones is very powerful and extremely useful. Windows has had ETW (http://msdn.microsoft.com/en-us/magazine/cc163437.aspx) for years which basically allowed you to specify logging providers and allow consumers to listen to events from a specific provider (Using ETW in conjunction with WPP (http://msdn.microsoft.com/en-us/library/ff556204.aspx) is especially powerful and low-cost). VLOG essentially provides some concept of a zone but the zone is restricted to the file name which may not be suffient in many cases.

I also disagree with the statement that verbose logging is because of an inability to use a debugger (I have many limitations but I think I can say with some confidence that the inability to use a debugger is not one of them). Debugging is what I do on my desktop, logging is what I expect the software to do at an end-user's machine. There are a myriad reasons in client software why an issue may only happen on a specific (or a specific set of) end-user machine(s) (this is unlike what Google3 has to deal with). ETW is used extensively and verbosely in the operating system and this is not because Dave Cutler and his team cannot use a debugger. If there are no listeners for a specific provider the cost is low.

I also agree with the comment about setting the default reporting level to errors or warnings for stable releases. In the absence of WPP this is how we lower the cost of logging at run-time. I disagree that the way to reduce cost is to reduce the amount of logging.

Note, at runtime in release builds logging is disabled globally unless the user runs with --enable-logging.  In other words, the runtime cost is not really an issue for end users.  So, the default log level is not really that interesting in that context.

Fair enough. I forgot about that. So the issue not one of runtime cost but log clutter. Something like ETW solves that beautifully.

Scott Hess

unread,
Oct 26, 2010, 12:45:26 PM10/26/10
to Darin Fisher, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
Where this all started is that when you're sheriff debugging a new
failure on the waterfall, it's often hard to tell whether the various
log output is trying to tell you something, or is just noise which has
been there for awhile. Also, when you're trying to LOG(INFO) debug
your own problems, all the other crap is annoying.

I think logging zones would be interesting, because you could perhaps
tie a zone to a bug or email address for purposes of suggesting that
maybe the log lines could be removed.

-scott


On Tue, Oct 26, 2010 at 8:05 AM, Darin Fisher <da...@chromium.org> wrote:

Fred Akalin

unread,
Oct 26, 2010, 1:05:33 PM10/26/10
to Scott Hess, Darin Fisher, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Evan Martin, Chromium-dev, zeli...@chromium.org
I'll throw my two cents in since it doesn't seem to be clear what the
role of VLOG() is and why I implemented it.

The original problem was that LOG(INFO) was too cluttered to be
useful, for the reasons Scott mentioned. The clutter arose from the
lack of any logging level "lower" than LOG(INFO); I think if VLOG()
existed from the start and developers knew about it, they would have
used it instead of LOG(INFO) for the debugging-related messages (e.g.,
"Module foo initialized"). Now that VLOG() is implemented, ideally
we'd reevaluate all the LOG(INFO)s to see if they would have been
VLOG()s in the first place, or if they truly are generally
informative. Given that that would take much too long, and that it
seems to me that most of the LOG(INFO)s should have been VLOG()s, the
most practical solution would be to convert all LOG(INFO)s to VLOG(1)s
(once) and let people convert back to LOG(INFO) if they feel it's
necessary (which I think would be rare). Going forward, I trust that
Chromium developers will use their best judgment as to the best
logging level for any new logs, assuming that everyone knows about
VLOG() (and --vmodule).

Lingeshwaran Palaniappan

unread,
Oct 26, 2010, 1:08:44 PM10/26/10
to Sanjeev Radhakrishnan, Darin Fisher, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
Thanks for all the feedback. If you have more feedback please feel free to post to the original thread. I will collect all the feedback and send a summary of what seems to be the consensus requirements for the logging feature tomorrow morning. 

That would help us come up with a proper design for this.
Thanks!
regards,
-LP

Peter Kasting

unread,
Oct 26, 2010, 1:53:05 PM10/26/10
to dpol...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
Basically, +1 to what Scott and Fred said.

Most of the LOG(INFO) statements we had were clearly debug logging.  In my initial email I explicitly asked reviewers to take a look at my changes and note if any should be dealt with differently than converting to VLOG(1).  I think a good half of them or more could have simply been removed, but only a couple reviewers actually said this.  One person noted a couple that should have actually been LOG(WARNING) or LOG(ERROR).  One set of unit test failures alerted me to a couple that needed to stay LOG(INFO).

If you really need LOG(INFO), then use it.  It's not banned.  It's just that we clearly didn't need it in some 1600 places and I don't have the ability to know which ones are the small percentage where we do.

I would really like it if people went through the source base, removed all VLOGs that weren't explicitly necessary (which ought to be the majority), and converted back to LOG(INFO) any rare cases where we truly do need to unconditionally log an informative message.

Does that help?

PK

Dmitry Polukhin

unread,
Oct 26, 2010, 2:32:22 PM10/26/10
to Peter Kasting, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
This sounds reasonable for Chrome on developed platforms but I'm not sure that it works for Chrome OS. Several times I got bug with steps that I wasn't able to reproduce and only logs helped me to understand why something didn't happened (or happened something that no one expected). Logs were very useful source of information to get at least some clue what was wrong. I strongly prefer see much more output than don't see anything (grep helps me to emulate --vmodule with more powerful semantic). It sounds like on Chrome OS it is reasonable to add command line "--v=1" to preserve previous behavior and still see useful logs (IMHO, it is not any better than having LOG(INFO) as it was).

Peter Kasting

unread,
Oct 26, 2010, 2:45:56 PM10/26/10
to Dmitry Polukhin, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
I'm confused as to what you're arguing.

VLOG() is strictly more powerful than LOG() was.  If you want to see verbose logging anyway, running with --v=1 is just like running the old code with the default log level at INFO.  So we haven't harmed your ability to see everything.  But as an added bonus, you can also elect to turn logging up or down on particular modules.  So for example if I know that resource_dispatcher.cc (or whatever) logs a bunch of info I don't care about, I can add --vmodule=resource_dispatcher=0 and simply turn it off.

So I'm not sure how we've harmed Chrome OS.  VLOG() means "verbose log".  LOG(INFO), as I've said repeatedly, is still available for the rare case when an informative message needs to be logged in "non-verbose" output.

PK

Fred Akalin

unread,
Oct 26, 2010, 2:54:20 PM10/26/10
to Dmitry Polukhin, Peter Kasting, lipa...@chromium.org, cma...@chromium.org, Evan Martin, Chromium-dev, zeli...@chromium.org
On Tue, Oct 26, 2010 at 11:32 AM, Dmitry Polukhin
<dpol...@chromium.org> wrote:
> This sounds reasonable for Chrome on developed platforms but I'm not sure
> that it works for Chrome OS. Several times I got bug with steps that I
> wasn't able to reproduce and only logs helped me to understand why something
> didn't happened (or happened something that no one expected). Logs were very
> useful source of information to get at least some clue what was wrong. I
> strongly prefer see much more output than don't see anything (grep helps me
> to emulate --vmodule with more powerful semantic). It sounds like on Chrome
> OS it is reasonable to add command line "--v=1" to preserve
> previous behavior and still see useful logs (IMHO, it is not any better than
> having LOG(INFO) as it was).

I don't understand how this argument is ChromeOS-specific. There are
certainly cases in Chrome when bugs are hard to reproduce, and only
logs help, and the problem is general enough that you want all logging
to be turned on. In that case, --v=1 would work too, but I don't
think it should be the default for Chrome.

Peter Kasting

unread,
Oct 26, 2010, 7:34:41 PM10/26/10
to Fred Akalin, cma...@chromium.org, Evan Martin, Chromium-dev, Lingeshwaran Palaniappan
On Sat, Oct 23, 2010 at 2:56 PM, Fred Akalin <aka...@chromium.org> wrote:
Is there a need for
directory-based matching?  I can think about adding support for it,
but I'm hesitant to diverge from google-glog behavior even more.

After considering this thread and chatting with Darin, I think this would be a good change.  It would allow us to avoid any new macros and any more massive code changeovers, complex API designs, allocation of zones, etc.  Instead, we could support something conceptually like "chrome --vpath=chrome/browser/sync=1" with a comparatively minor set of changes.  This would be useful for debugging both in the field and locally.

On Mon, Oct 25, 2010 at 6:13 PM, Lingeshwaran Palaniappan <lipa...@google.com> wrote:
The functionality of vlog as it stands today is that it looks at the file name and it is pretty granular. It is possible to modify vlog to look at the entire filepath.

But thinking more about this an approach like the following would be better. This could retain the finer granularity at the same time provide area wise logging levels. The API signature is:
LOG(ZONE, severity, logmessage);

I am explicitly opposed to doing this.  I would like to see reasons why this is compellingly superior to adding path support to VLOG.  As far as I can see the only plus is that some command lines might be shorter with this for "zones" that do not have a reasonably concise mapping to file paths, which does not seem compelling.

PK 

Peter Kasting

unread,
Oct 26, 2010, 8:43:17 PM10/26/10
to Fred Akalin, cma...@chromium.org, Evan Martin, Chromium-dev, Lingeshwaran Palaniappan
On Tue, Oct 26, 2010 at 5:39 PM, Fred Akalin <aka...@chromium.org> wrote:
I'm explicitly
advocating for a single switch instead of vmodule and vpath.

Sure.  Whatever seems easiest to use.

PK 

Fred Akalin

unread,
Oct 26, 2010, 8:39:36 PM10/26/10
to Peter Kasting, cma...@chromium.org, Evan Martin, Chromium-dev, Lingeshwaran Palaniappan
> After considering this thread and chatting with Darin, I think this would be
> a good change.  It would allow us to avoid any new macros and any more
> massive code changeovers, complex API designs, allocation of zones, etc.
>  Instead, we could support something conceptually like "chrome
> --vpath=chrome/browser/sync=1" with a comparatively minor set of changes.
>  This would be useful for debugging both in the field and locally.

One idea is to change the semantics of vmodule (and maybe rename it)
so that if a pattern contains a slash, it'll match based on the entire
filename instead of just the module (basename minus extension minus
-inl). For example:

--vmodule=browser_process*=2,*/chromeos/*=1

would mean that filenames that start with "browser_process" will get a
vlog level of 2, and paths containing "/chromeos/" (e.g.,
chrome/browser/chromeos, chrome/test/chromeos) would get a vlog level
of 1.

This may be what you're already suggesting, but I'm explicitly


advocating for a single switch instead of vmodule and vpath.

Thoughts?

Dmitry Polukhin

unread,
Oct 27, 2010, 3:33:34 AM10/27/10
to Peter Kasting, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
As I said LOG(INFO)+grep is more powerful than VLOG. I can easily do things that --vmodule does:
chrome 2>&1 | grep preferences.cc (only specific module)
chrome 2>&1 | grep -v preferences.cc (everything except specific module)
chrome 2>&1 | grep /chromeos/ (directory filter)
And much more including filtration by line numbers, patterns in outputted text, etc. Therefore, if we don't take into account runtime performance, VLOG advantage is relatively small. But I can use grep with VLOG so there is no problem here.

My point was that bulk replacement of LOG(INFO) with VLOG(1) effectively changed default log level from INFO to WARNING (i.e. old INFO lines are not printed by default anymore) on Chrome OS. Perhaps it is good thing for Windows, Linux, Mac but I'm not sure about Chrome OS. But it looks the majority is OK with the change. I'm calling it "default" because Chrome on Chrome OS is running with " --log-level=0 --enable-logging" (perhaps it was the main source of confusion why I said that my ability to triage things was affected).

Dmitry Polukhin

unread,
Oct 27, 2010, 3:34:29 AM10/27/10
to Peter Kasting, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
As I said LOG(INFO)+grep is more powerful than VLOG. I can easily do things that --vmodule does:
chrome 2>&1 | grep preferences.cc (only specific module)
chrome 2>&1 | grep -v preferences.cc (everything except specific module)
chrome 2>&1 | grep /chromeos/ (directory filter)
And much more including filtration by line numbers, patterns in outputted text, etc. Therefore, if we don't take into account runtime performance, VLOG advantage is relatively small. But I can use grep with VLOG so there is no problem here.

My point was that bulk replacement of LOG(INFO) with VLOG(1) effectively changed default log level from INFO to WARNING (i.e. old INFO lines are not printed by default anymore) on Chrome OS. Perhaps it is good thing for Windows, Linux, Mac but I'm not sure about Chrome OS. But it looks the majority is OK with the change. I'm calling it "default" because Chrome on Chrome OS is running with " --log-level=0 --enable-logging" (perhaps it was the main source of confusion why I said that my ability to triage things was affected).

Sigurður Ásgeirsson

unread,
Oct 27, 2010, 2:30:08 PM10/27/10
to da...@google.com, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
On Windows, I've integrated the Chrome logging machinery with Event Tracing for Windows (ETW), which allows turning log levels up or down at runtime, and provides a super efficient, non-serializing transport for the log messages. 
On the receiving/controlling side there's a UI viewer called Sawbuck [http://code.google.com/p/sawbuck], that'll sink the messages and gives you regexp filtering and searching the logs (plus some value adds, like the stack trace to the log site).
Try this out - Sawbuck is a single-click install on Windows, but the ETW integration is enabled behind an environment variable, so you might need to relaunch your Chrome with CHROME_ETW_LOGGING set. 

Sigurður Ásgeirsson

unread,
Oct 27, 2010, 3:29:25 PM10/27/10
to da...@google.com, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
... the point being that if the approach of controlling log volume at runtime, then filtering/searching logs at the sink is well liked, maybe we could try and figure out ways to get the same functionality to other platforms.

Lingeshwaran Palaniappan

unread,
Oct 27, 2010, 5:26:29 PM10/27/10
to Sigurður Ásgeirsson, da...@google.com, sh...@google.com, dpol...@chromium.org, pkas...@chromium.org, lipa...@chromium.org, cma...@chromium.org, Fred Akalin, Evan Martin, Chromium-dev, zeli...@chromium.org
Actually this is where I think we should be moving towards!!

I still owe a summary of requirements to the group from all these emails. The number of responses is somewhat huge. I should be able to find some time by eod to send a summary of what everybody wants!!

2010/10/27 Sigurður Ásgeirsson <si...@chromium.org>

Fred Akalin

unread,
Oct 28, 2010, 10:01:52 PM10/28/10
to Peter Kasting, cma...@chromium.org, Evan Martin, Chromium-dev, Lingeshwaran Palaniappan
On Tue, Oct 26, 2010 at 4:34 PM, Peter Kasting <pkas...@google.com> wrote:
> On Sat, Oct 23, 2010 at 2:56 PM, Fred Akalin <aka...@chromium.org> wrote:
> After considering this thread and chatting with Darin, I think this would be
> a good change.  It would allow us to avoid any new macros and any more
> massive code changeovers, complex API designs, allocation of zones, etc.
>  Instead, we could support something conceptually like "chrome
> --vpath=chrome/browser/sync=1" with a comparatively minor set of changes.
>  This would be useful for debugging both in the field and locally.

This has been implemented and checked in as @63436. Basically, if a
--vmodule pattern has a slash*, it will try to match the entire path
against it instead of just the module name. Note that this means
you'll almost always need to use wildcards for directory patterns,
e.g. --vmodule=*/chromeos/*=2,*chrome/browser/sync*=3.

* forward or back slash, but it must match your current platform --
I'll fix this in a future CL

Reply all
Reply to author
Forward
0 new messages