Implemented VLOG() et al.

Implemented VLOG() et al.

Implemented VLOG(), VLOG_IF(), VLOG_IS_ON().  Added --v and --vmodule
switches.

Changed some spammy sync-related logs to use VLOG.

BUG=56965
TEST=New unittests

Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=60976

[akalin, 2010-09-26 20:12:33]

+evmar for review

[Evan Martin, 2010-09-26 20:13:58]

How does this compare to the glog vlog?  (I know using glog has its own
difficulties)

[akalin, 2010-09-26 21:29:15]

On 2010/09/26 20:13:58, Evan Martin wrote:
> How does this compare to the glog vlog?  (I know using glog has its own
> difficulties)

I based this on glog's vlog.  Glog's vlog has some difficulties:

- tied to google's flags facility
- vmodule is turned off for non-gcc (i.e., windows)
- pretty subtle issues around initialization

It has one advantage, though, in that the string parsing that vmodule requires
is only done at most once per call site.  It does this by taking advantage of
gcc's statement expression extension to use anonymous static variables per call
site.  I don't know how important it is for us to have this, but this is why
vmodule is turned off for windows.  I'm trying to come up with a solution that
works for all platforms, but it may be impractical.

Our command-line stuff makes implementing vmodule much easier, since it obviates
a lot of the subtle initialization issues.

The core of the google vlog code is
http://code.google.com/p/google-glog/source/browse/trunk/src/vlog_is_on.cc and
http://code.google.com/p/google-glog/source/browse/trunk/src/glog/vlog_is_on....
, for comparison.

[Evan Martin, 2010-09-27 17:36:45]

I like it.  We need to figure out the performance/caching stuff first but I
think it'll improve our code a lot.

http://codereview.chromium.org/3448028/diff/1/6
File base/logging.cc (right):

http://codereview.chromium.org/3448028/diff/1/6#newcode59
base/logging.cc:59: VlogInfo* g_vlog_info = NULL;
Will valgrind etc report this as a leak?

http://codereview.chromium.org/3448028/diff/1/9
File base/vlog.h (right):

http://codereview.chromium.org/3448028/diff/1/9#newcode37
base/vlog.h:37: int GetVlogLevel(const std::string& file);
It seems you could make this function into a helper function and add a caching
layer here, to fix the statement expression problems mentioned near the macros. 
It won't be as fast as a GCC-specific statement expression cache but it is
probably better than repeatedly reparsing.

Another thought is to add such a cache only for Windows, and then use statement
expressions on Mac/Linux.

[darin (slow to review), 2010-09-27 17:48:33]

http://codereview.chromium.org/3448028/diff/1/7
File base/logging.h (right):

http://codereview.chromium.org/3448028/diff/1/7#newcode84
base/logging.h:84: //    --vmodule=mapreduce=2,file=1,gfs*=3 --v=0
nit: might be nice to use examples from chrome

[akalin, 2010-09-28 02:42:26]

I rejiggered the code a bit to use base::StringPiece instead of std::string to
avoid copies.

I also added a benchmarking unit test.  Here's an example run on my machine:


[ RUN      ] VlogTest.Perf
[12606:12606:0927/193935:1747644561958:INFO:base/vlog_unittest.cc(91)]
4.57191e+07 cps (0.218727s elapsed)
[12606:12606:0927/193937:1747646339217:INFO:base/vlog_unittest.cc(99)]
5.62693e+06 cps (1.77717s elapsed)
[12606:12606:0927/193937:1747646339266:INFO:base/vlog_unittest.cc(100)] slowdown
= 8.12506x
[12606:12606:0927/193939:1747648848786:INFO:base/vlog_unittest.cc(109)]
3.98489e+06 cps (2.50948s elapsed)
[12606:12606:0927/193939:1747648848835:INFO:base/vlog_unittest.cc(110)] slowdown
= 11.4731x

So it takes .2s to perform 10 million calls to GetVlogLevel() with no switches
(the common case).  Using vmodule with 5 entries slows it down by 8x, and using
vmodule with patterns slows it down by 12x.  This benchmarking is crude, but I
think this has negligible overhead.

Maruel tells me that I can check in a change that e.g. changes all LOG(INFO)
into VLOG()s to see if it affects the perf numbers.  I can do that after this is
checked in.

Please take another look.

http://codereview.chromium.org/3448028/diff/1/6
File base/logging.cc (right):

http://codereview.chromium.org/3448028/diff/1/6#newcode59
base/logging.cc:59: VlogInfo* g_vlog_info = NULL;
On 2010/09/27 17:36:45, Evan Martin wrote:
> Will valgrind etc report this as a leak?

I don't think so.  linux_valgrind seems to be happy.

http://codereview.chromium.org/3448028/diff/1/7
File base/logging.h (right):

http://codereview.chromium.org/3448028/diff/1/7#newcode84
base/logging.h:84: //    --vmodule=mapreduce=2,file=1,gfs*=3 --v=0
On 2010/09/27 17:48:33, darin wrote:
> nit: might be nice to use examples from chrome

Done.

http://codereview.chromium.org/3448028/diff/1/9
File base/vlog.h (right):

http://codereview.chromium.org/3448028/diff/1/9#newcode37
base/vlog.h:37: int GetVlogLevel(const std::string& file);
On 2010/09/27 17:36:45, Evan Martin wrote:
> It seems you could make this function into a helper function and add a caching
> layer here, to fix the statement expression problems mentioned near the
macros. 
> It won't be as fast as a GCC-specific statement expression cache but it is
> probably better than repeatedly reparsing.
> 
> Another thought is to add such a cache only for Windows, and then use
statement
> expressions on Mac/Linux.

As we discussed on IRC, I'm hesitant to optimize this, as this shouldn't have
any performance impact in the common case (logging turned off).  It will be
slower if --vmodule is used, but based on the crude benchmarking I did today, I
think even that case isn't too terrible.  What do you think?

[darin (slow to review), 2010-09-28 06:32:57]

http://codereview.chromium.org/3448028/diff/18001/19009
File base/vlog.cc (right):

http://codereview.chromium.org/3448028/diff/18001/19009#newcode35
base/vlog.cc:35: class SaveLastErrno {
why do we need this?  is it important on windows?  i think it uses thread-locale
storage, which is not exactly cheap to access.  can we avoid accessing it?

[akalin, 2010-09-28 17:10:54]

http://codereview.chromium.org/3448028/diff/18001/19009
File base/vlog.cc (right):

http://codereview.chromium.org/3448028/diff/18001/19009#newcode35
base/vlog.cc:35: class SaveLastErrno {
On 2010/09/28 06:32:59, darin wrote:
> why do we need this?  is it important on windows?  i think it uses
thread-locale
> storage, which is not exactly cheap to access.  can we avoid accessing it?

This is so that "VLOG(1) << "foo " << strerror(errno)" works.  I have a unit
test which makes sure errno is preserved, and it seemed to work even without
this class, but pretty much any library function can mess with errno, so I'm
hesitant to remove it.  What do you think?

[Evan Martin, 2010-09-28 17:16:13]

On 2010/09/28 17:10:54, akalin wrote:
> This is so that "VLOG(1) << "foo " << strerror(errno)" works.  I have a unit
> test which makes sure errno is preserved, and it seemed to work even without
> this class, but pretty much any library function can mess with errno, so I'm
> hesitant to remove it.  What do you think?

Maybe we should instead match PLOG and DPLOG with some sort of VPLOG?

[akalin, 2010-09-28 18:00:26]

On 2010/09/28 17:16:13, Evan Martin wrote:
> On 2010/09/28 17:10:54, akalin wrote:
> > This is so that "VLOG(1) << "foo " << strerror(errno)" works.  I have a unit
> > test which makes sure errno is preserved, and it seemed to work even without
> > this class, but pretty much any library function can mess with errno, so I'm
> > hesitant to remove it.  What do you think?
> 
> Maybe we should instead match PLOG and DPLOG with some sort of VPLOG?

Yeah, you're right.  I removed SaveLastErrno and added a TODO to add more VLOG
variants like VPLOG.

Please take another look.

[darin (slow to review), 2010-09-28 18:25:18]

On Tue, Sep 28, 2010 at 10:10 AM, <akalin@chromium.org> wrote:

>
> http://codereview.chromium.org/3448028/diff/18001/19009
> File base/vlog.cc (right):
>
> http://codereview.chromium.org/3448028/diff/18001/19009#newcode35
> base/vlog.cc:35: class SaveLastErrno {
> On 2010/09/28 06:32:59, darin wrote:
>
>> why do we need this?  is it important on windows?  i think it uses
>>
> thread-locale
>
>> storage, which is not exactly cheap to access.  can we avoid accessing
>>
> it?
>
> This is so that "VLOG(1) << "foo " << strerror(errno)" works.  I have a
> unit test which makes sure errno is preserved, and it seemed to work
> even without this class, but pretty much any library function can mess
> with errno, so I'm hesitant to remove it.  What do you think?


I see.  You could add debug-only code that confirms that errno is not
modified, right?

-Darin



>
>
> http://codereview.chromium.org/3448028/show
>

[akalin, 2010-09-28 18:27:25]

On 2010/09/28 18:25:18, darin wrote:
> 
> I see.  You could add debug-only code that confirms that errno is not
> modified, right?

Yeah, I could.  I think evmar's idea of adding VPLOG is more feasible, though,
esp. since it'd work for Windows, too.

[Evan Martin, 2010-09-28 18:56:17]

Since you removed the errno test, does that mean using VLOG clobbers errno?

http://codereview.chromium.org/3448028/diff/11002/14023
File base/vlog.cc (right):

http://codereview.chromium.org/3448028/diff/11002/14023#newcode20
base/vlog.cc:20: (void)base::StringToInt(v_switch, &max_vlog_level_);
Should we check these return values and print warnings when the args are bad?

http://codereview.chromium.org/3448028/diff/11002/14025
File base/vlog_unittest.cc (right):

http://codereview.chromium.org/3448028/diff/11002/14025#newcode70
base/vlog_unittest.cc:70: const int vlog_size = arraysize(vlogs);
kVLogSize
(sorry, can't help it)

[akalin, 2010-09-28 19:38:46]

On 2010/09/28 18:56:17, Evan Martin wrote:
> Since you removed the errno test, does that mean using VLOG clobbers errno?

No, but now we don't care.  VPLOG() can be implemented similarly as PLOG(),
where it explicitly saves errno before calling VLOG_IS_ON().

[akalin, 2010-09-28 19:38:56]

http://codereview.chromium.org/3448028/diff/11002/14023
File base/vlog.cc (right):

http://codereview.chromium.org/3448028/diff/11002/14023#newcode20
base/vlog.cc:20: (void)base::StringToInt(v_switch, &max_vlog_level_);
On 2010/09/28 18:56:18, Evan Martin wrote:
> Should we check these return values and print warnings when the args are bad?

Done.

http://codereview.chromium.org/3448028/diff/11002/14025
File base/vlog_unittest.cc (right):

http://codereview.chromium.org/3448028/diff/11002/14025#newcode70
base/vlog_unittest.cc:70: const int vlog_size = arraysize(vlogs);
On 2010/09/28 18:56:18, Evan Martin wrote:
> kVLogSize
> (sorry, can't help it)

Done.

[Evan Martin, 2010-09-29 19:19:11]

LGTM