[UMA] Add performance profile data to UMA uploads.

[UMA] Add performance profile data to UMA uploads.

BUG=103480
TEST=unit_test --gtest_filter=MetricsLogTest.*


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

[Ilya Sherman, 2012-04-18 01:18:43]

https://chromiumcodereview.appspot.com/9702015/diff/8001/chrome/browser/metri...
File chrome/browser/metrics/metrics_service.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/8001/chrome/browser/metri...
chrome/browser/metrics/metrics_service.cc:815: // member variable at the end of
the init task.  Reviewers, do you know?
(?)

[jar (doing other things), 2012-04-18 03:18:45]

https://chromiumcodereview.appspot.com/9702015/diff/8001/chrome/browser/metri...
File chrome/browser/metrics/metrics_service.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/8001/chrome/browser/metri...
chrome/browser/metrics/metrics_service.cc:815: // member variable at the end of
the init task.  Reviewers, do you know?
On 2012/04/18 01:18:44, Ilya Sherman wrote:
> (?)
This seems a bit wrongish.  I think we generally try to use g_brows_process so
that we get to see if the thread still exists.  I would have expected this to
allow us to cache the value.... and then mess up later.

I would expect that we should instead use the value when we need it (testing to
see if it is still available).

[Ilya Sherman, 2012-04-18 21:46:15]

https://chromiumcodereview.appspot.com/9702015/diff/8001/chrome/browser/metri...
File chrome/browser/metrics/metrics_service.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/8001/chrome/browser/metri...
chrome/browser/metrics/metrics_service.cc:815: // member variable at the end of
the init task.  Reviewers, do you know?
On 2012/04/18 03:18:45, jar wrote:
> On 2012/04/18 01:18:44, Ilya Sherman wrote:
> > (?)
> This seems a bit wrongish.  I think we generally try to use g_brows_process so
> that we get to see if the thread still exists.  I would have expected this to
> allow us to cache the value.... and then mess up later.
> 
> I would expect that we should instead use the value when we need it (testing
to
> see if it is still available).

Ok, split this off to https://chromiumcodereview.appspot.com/10117034/

[jar (doing other things), 2012-04-19 03:04:56]

https://chromiumcodereview.appspot.com/9702015/diff/9008/chrome/browser/metri...
File chrome/browser/metrics/metrics_log.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/9008/chrome/browser/metri...
chrome/browser/metrics/metrics_log.cc:234:
MetricsLogBase::CreateHashes(it->birth.thread_name,
We may end up needing to profile this... to see how long it takes... and if it
is too wasteful.
It sure seems like a shame to calculate the SHA hash of the same thread, time
and again.
At a minimum, we should watch for the task that does this protobuf-ication, and
see if it stands out.

https://chromiumcodereview.appspot.com/9702015/diff/9008/chrome/browser/metri...
chrome/browser/metrics/metrics_log.cc:794:
profile->set_time_source(ProfilerEventProto::WALL_CLOCK_TIME);
We need to validate this as being the source.  I think we need to augment the
code that changes the time source, so that it sets an inspectable value... which
we can use here to establish the "true" source.
As currently coded, if a person plays with the TCMalloc time source... they'll
corrupt our stats.

[Ilya Sherman, 2012-04-19 21:26:08]

https://chromiumcodereview.appspot.com/9702015/diff/9008/chrome/browser/metri...
File chrome/browser/metrics/metrics_log.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/9008/chrome/browser/metri...
chrome/browser/metrics/metrics_log.cc:234:
MetricsLogBase::CreateHashes(it->birth.thread_name,
On 2012/04/19 03:04:56, jar wrote:
> We may end up needing to profile this... to see how long it takes... and if it
> is too wasteful.
> It sure seems like a shame to calculate the SHA hash of the same thread, time
> and again.
> At a minimum, we should watch for the task that does this protobuf-ication,
and
> see if it stands out.

I think the relevant task is "OnProfilerDataCollected", which on my Debug build
does not show up as a hot spot -- the max run time is 12ms (and that includes
loads of about:profiler as well).  Let's definitely keep an eye on it though.

https://chromiumcodereview.appspot.com/9702015/diff/9008/chrome/browser/metri...
chrome/browser/metrics/metrics_log.cc:794:
profile->set_time_source(ProfilerEventProto::WALL_CLOCK_TIME);
On 2012/04/19 03:04:56, jar wrote:
> We need to validate this as being the source.  I think we need to augment the
> code that changes the time source, so that it sets an inspectable value...
which
> we can use here to establish the "true" source.
> As currently coded, if a person plays with the TCMalloc time source... they'll
> corrupt our stats.

Done.

[jar (doing other things), 2012-04-20 02:10:10]

https://chromiumcodereview.appspot.com/9702015/diff/18001/base/tracked_object...
File base/tracked_objects.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/18001/base/tracked_object...
base/tracked_objects.cc:653:
ThreadData::SetAlternateTimeSource(alternate_time_source);
This is an interesting change.  Is the justification that we we check for the
environment variable in the allocator shim for TCMalloc, and that suffices?

If I had to delete such partially repetitious code from any one place, it would
probably be from the TCMalloc setter.  This code is more general, and is
probably the hub location to both decide, and to (some day) record the decision
that was made so that it can be used for filling protobufs and such.

Am I missing something?

[Ilya Sherman, 2012-04-20 22:26:21]

https://chromiumcodereview.appspot.com/9702015/diff/18001/base/tracked_object...
File base/tracked_objects.cc (right):

https://chromiumcodereview.appspot.com/9702015/diff/18001/base/tracked_object...
base/tracked_objects.cc:653:
ThreadData::SetAlternateTimeSource(alternate_time_source);
On 2012/04/20 02:10:10, jar wrote:
> This is an interesting change.  Is the justification that we we check for the
> environment variable in the allocator shim for TCMalloc, and that suffices?

Yep, that seems to be how the code was already set up.  Note that the previously
existing code called into GetAlternateTimeSource(), just as the new code does --
the allocator shim seems to be responsible for actually setting the alternate
time source to be based on TCMalloc.  My guess is that this is because TCMalloc
lives in third_part/, and base/ typically shouldn't have dependencies on
third_party/.  It looks like base/allocator/ has a whole gyp file dedicated to
setting up a special-case exception.

You probably know better than I do: is it ok to #include
third_party/tcmalloc/chromium/src/thread_cache.h in the tracked_objects file? 
That seems to be where the alternate time source --
GetBytesAllocatedOnCurrentThread() -- is declared.

> If I had to delete such partially repetitious code from any one place, it
would
> probably be from the TCMalloc setter.  This code is more general, and is
> probably the hub location to both decide, and to (some day) record the
decision
> that was made so that it can be used for filling protobufs and such.

Right now it looks like base/profiler/alternate_timer.{h, cc} is keeping track
of the bookkeeping for that.  Does that sound ok to you, or would you strongly
prefer to have the logic live within the tracked_objects.cc implementation file?

> Am I missing something?

[jar (doing other things), 2012-04-23 17:26:24]

I'm sold on the pattern you're using, so LGTM.

Comments (for future CLs?):

First, with regard to the crazy calling structure to set this
alternate-timer up: Yes, it was an *immense* hassle to get the calling
rules "just right" and especially to work even when we create a dll build
on windows.

I'm convinced by this discussion that the "right" place to record what the
meaning of a current "alternate time source" should be the
alternate_timer.cc. Currently, that file does not track what the setter for
a callback actually is :-(.

Currently, alternate_timer.cc only has a setter, and a getter.  Currently,
the setter is *only* used by TCMalloc.  I'm fine with having the profiler
(tracked_objects) just take *any* alternate time function it has, willy
nilly, but we should probably (eventually) inquire (from tracked _object.cc
to alternate_timer.cc) to find out what the alternate is.  Since we decide
to use an alternate very early on (when initializing the profiler) we
should at the same time as we make that decision, find out what the
alternate timer "means." (i.e., learn that it is a malloc bytes "timer"),
and remember that decision (so that later changes to the timer, which are
ignored by tracked objects, don't confuse us when we write into a protobuf).

I expected (and continue to hope) that we may eventually have "CPU time on
thread" as yet another alternate time source, so we can't just
(permanantly) presume that if there is an alternate time source, then it
much be an allocator count.

I don't know if this statement of the timer source should go in this CL,
but it should land RSN:  When we "set" the alternate time source, we should
at the same time (in the same setter??) state using an enum what we believe
the time source is.  The enum should probably be declared in
alternate_timer.h, so that there is no modular problem (i.e., all parties
that use this base functionality can access the enum).



On Fri, Apr 20, 2012 at 3:26 PM, <isherman@chromium.org> wrote:

>
> https://chromiumcodereview.**appspot.com/9702015/diff/**
>
18001/base/tracked_objects.cc<https://chromiumcodereview.appspot.com/9702015/diff/18001/base/tracked_objects.cc>
> File base/tracked_objects.cc (right):
>
> https://chromiumcodereview.**appspot.com/9702015/diff/**
>
18001/base/tracked_objects.cc#**newcode653<https://chromiumcodereview.appspot.com/9702015/diff/18001/base/tracked_objects.cc#newcode653>
> base/tracked_objects.cc:653:
> ThreadData::**SetAlternateTimeSource(**alternate_time_source);
> On 2012/04/20 02:10:10, jar wrote:
>
>> This is an interesting change.  Is the justification that we we check
>>
> for the
>
>> environment variable in the allocator shim for TCMalloc, and that
>>
> suffices?
>
> Yep, that seems to be how the code was already set up.  Note that the
> previously existing code called into GetAlternateTimeSource(), just as
> the new code does -- the allocator shim seems to be responsible for
> actually setting the alternate time source to be based on TCMalloc.  My
> guess is that this is because TCMalloc lives in third_part/, and base/
> typically shouldn't have dependencies on third_party/.  It looks like
> base/allocator/ has a whole gyp file dedicated to setting up a
> special-case exception.
>
> You probably know better than I do: is it ok to #include
> third_party/tcmalloc/chromium/**src/thread_cache.h in the tracked_objects
> file?  That seems to be where the alternate time source --
> GetBytesAllocatedOnCurrentThre**ad() -- is declared.
>
>
>  If I had to delete such partially repetitious code from any one place,
>>
> it would
>
>> probably be from the TCMalloc setter.  This code is more general, and
>>
> is
>
>> probably the hub location to both decide, and to (some day) record the
>>
> decision
>
>> that was made so that it can be used for filling protobufs and such.
>>
>
> Right now it looks like base/profiler/alternate_timer.**{h, cc} is keeping
> track of the bookkeeping for that.  Does that sound ok to you, or would
> you strongly prefer to have the logic live within the tracked_objects.cc
> implementation file?
>
>
>  Am I missing something?
>>
>
>
https://chromiumcodereview.**appspot.com/9702015/<https://chromiumcodereview....
>

[commit-bot: I haz the power, 2012-04-23 18:04:20]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/isherman@chromium.org/9702015/18001

[Ilya Sherman, 2012-04-23 18:04:52]

On 2012/04/23 17:26:24, jar wrote:
> I'm sold on the pattern you're using, so LGTM.
> 
> Comments (for future CLs?):
> 
> First, with regard to the crazy calling structure to set this
> alternate-timer up: Yes, it was an *immense* hassle to get the calling
> rules "just right" and especially to work even when we create a dll build
> on windows.
> 
> I'm convinced by this discussion that the "right" place to record what the
> meaning of a current "alternate time source" should be the
> alternate_timer.cc. Currently, that file does not track what the setter for
> a callback actually is :-(.
> 
> Currently, alternate_timer.cc only has a setter, and a getter.  Currently,
> the setter is *only* used by TCMalloc.  I'm fine with having the profiler
> (tracked_objects) just take *any* alternate time function it has, willy
> nilly, but we should probably (eventually) inquire (from tracked _object.cc
> to alternate_timer.cc) to find out what the alternate is.  Since we decide
> to use an alternate very early on (when initializing the profiler) we
> should at the same time as we make that decision, find out what the
> alternate timer "means." (i.e., learn that it is a malloc bytes "timer"),
> and remember that decision (so that later changes to the timer, which are
> ignored by tracked objects, don't confuse us when we write into a protobuf).
> 
> I expected (and continue to hope) that we may eventually have "CPU time on
> thread" as yet another alternate time source, so we can't just
> (permanantly) presume that if there is an alternate time source, then it
> much be an allocator count.
> 
> I don't know if this statement of the timer source should go in this CL,
> but it should land RSN:  When we "set" the alternate time source, we should
> at the same time (in the same setter??) state using an enum what we believe
> the time source is.  The enum should probably be declared in
> alternate_timer.h, so that there is no modular problem (i.e., all parties
> that use this base functionality can access the enum).

That all sounds reasonable.  I'll make that change in a follow-up CL.  Thanks :)

[commit-bot: I haz the power, 2012-04-23 18:41:20]

Try job failure for 9702015-18001 (retry) on linux_rel for step "update".
It's a second try, previously, step "browser_tests" failed.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=linux_rel&...

Step "update" is always a major failure.
Look at the try server FAQ for more details.

[commit-bot: I haz the power, 2012-04-23 18:53:14]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/isherman@chromium.org/9702015/18001

[commit-bot: I haz the power, 2012-04-23 19:46:01]

Try job failure for 9702015-18001 (retry) on win for step "compile" (clobber
build).
It's a second try, previously, step "compile" failed.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win&number...

[commit-bot: I haz the power, 2012-04-23 22:30:08]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/isherman@chromium.org/9702015/41001

[commit-bot: I haz the power, 2012-04-23 23:37:10]

Try job failure for 9702015-41001 (retry) on win for step "compile" (clobber
build).
It's a second try, previously, step "compile" failed.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win&number...

[commit-bot: I haz the power, 2012-04-24 00:59:24]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/isherman@chromium.org/9702015/47002

[commit-bot: I haz the power, 2012-04-24 01:17:49]

Try job failure for 9702015-47002 (retry) on win for step "compile" (clobber
build).
It's a second try, previously, step "compile" failed.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win&number...

[commit-bot: I haz the power, 2012-04-24 19:55:33]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/isherman@chromium.org/9702015/55001

[commit-bot: I haz the power, 2012-04-24 21:45:38]

Change committed as 133773