Record latencies of connection and arrival of first message in UMA

Record latencies of connection and arrival of first message in UMA

This gives an idea how long it took a connection to complete as well
as the arrival of data messages.

Also records received GCM data burst size and intervals in UMA, and
added previously left-out xml description for another UMA metric.

jar: please review histograms.xml

BUG=386273
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=287645

[fgorski, 2014-07-22 04:08:36]

overall looks ok, please address the comments.

Also, did you all ready add a histogram for the burst?

https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
File components/gcm_driver/gcm_stats_recorder_impl.cc (right):

https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
components/gcm_driver/gcm_stats_recorder_impl.cc:228:
last_connection_initiation_time_ = base::Time::Now();
make sure last_connection_success_time_ is null for the DCHECK in 388 to make
sense more than once.

https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
components/gcm_driver/gcm_stats_recorder_impl.cc:249:
last_connection_success_time_ = base::Time::Now();
make sure last_connection_initiation_time_ is set to null here for the dcheck in
245 to make sense more than one.

[juyik, 2014-07-22 17:51:21]

https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
File components/gcm_driver/gcm_stats_recorder_impl.cc (right):

https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
components/gcm_driver/gcm_stats_recorder_impl.cc:228:
last_connection_initiation_time_ = base::Time::Now();
On 2014/07/22 04:08:36, fgorski wrote:
> make sure last_connection_success_time_ is null for the DCHECK in 388 to make
> sense more than once.

Done.

https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
components/gcm_driver/gcm_stats_recorder_impl.cc:249:
last_connection_success_time_ = base::Time::Now();
On 2014/07/22 04:08:36, fgorski wrote:
> make sure last_connection_initiation_time_ is set to null here for the dcheck
in
> 245 to make sense more than one.

Done.

[fgorski, 2014-07-22 20:11:19]

On 2014/07/22 17:51:21, juyik wrote:
>
https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
> File components/gcm_driver/gcm_stats_recorder_impl.cc (right):
> 
>
https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
> components/gcm_driver/gcm_stats_recorder_impl.cc:228:
> last_connection_initiation_time_ = base::Time::Now();
> On 2014/07/22 04:08:36, fgorski wrote:
> > make sure last_connection_success_time_ is null for the DCHECK in 388 to
make
> > sense more than once.
> 
> Done.
> 
>
https://codereview.chromium.org/409653004/diff/1/components/gcm_driver/gcm_st...
> components/gcm_driver/gcm_stats_recorder_impl.cc:249:
> last_connection_success_time_ = base::Time::Now();
> On 2014/07/22 04:08:36, fgorski wrote:
> > make sure last_connection_initiation_time_ is set to null here for the
dcheck
> in
> > 245 to make sense more than one.
> 
> Done.

lgtm

[juyik, 2014-07-22 20:15:14]

jar@chromium.org: Please review histograms.xml

[juyik, 2014-07-29 00:21:09]

Ping. Hi Jim, can you take a look at histograms.xml?

[jar (doing other things), 2014-07-30 21:25:06]

https://codereview.chromium.org/409653004/diff/20001/components/gcm_driver/gc...
File components/gcm_driver/gcm_stats_recorder_impl.cc (right):

https://codereview.chromium.org/409653004/diff/20001/components/gcm_driver/gc...
components/gcm_driver/gcm_stats_recorder_impl.cc:228:
last_connection_initiation_time_ = base::Time::Now();
I'd strongly suggest using TimeTicks rather than Time.  This ensures that your
clock is monotonic, and won't jump around as folks change their clocks.

https://codereview.chromium.org/409653004/diff/20001/components/gcm_driver/gc...
components/gcm_driver/gcm_stats_recorder_impl.cc:247: UMA_HISTOGRAM_COUNTS(
nit: use UMA_HISTOGRAM_TIMES() and it will take care of the conversion from a
TimeDelta (the difference of two times) to milliseconds.

If you expect the duration to potentially be larger than 10 seconds... then
better yet would be UMA_HISTOGRAM_LONG_TIMES() which will get you up to several
minutes nicely.

If you really want a wider range, then UMA_HISTOGRAM_CUSTOM_TIMES() will give
you more flexibility, but don't go for much more than 50 buckets, and certainly
not more than 100.

[juyik, 2014-07-31 20:55:34]

https://codereview.chromium.org/409653004/diff/20001/components/gcm_driver/gc...
File components/gcm_driver/gcm_stats_recorder_impl.cc (right):

https://codereview.chromium.org/409653004/diff/20001/components/gcm_driver/gc...
components/gcm_driver/gcm_stats_recorder_impl.cc:228:
last_connection_initiation_time_ = base::Time::Now();
On 2014/07/30 21:25:06, jar wrote:
> I'd strongly suggest using TimeTicks rather than Time.  This ensures that your
> clock is monotonic, and won't jump around as folks change their clocks.

Done.

https://codereview.chromium.org/409653004/diff/20001/components/gcm_driver/gc...
components/gcm_driver/gcm_stats_recorder_impl.cc:247: UMA_HISTOGRAM_COUNTS(
On 2014/07/30 21:25:06, jar wrote:
> nit: use UMA_HISTOGRAM_TIMES() and it will take care of the conversion from a
> TimeDelta (the difference of two times) to milliseconds.
> 
> If you expect the duration to potentially be larger than 10 seconds... then
> better yet would be UMA_HISTOGRAM_LONG_TIMES() which will get you up to
several
> minutes nicely.
> 
> If you really want a wider range, then UMA_HISTOGRAM_CUSTOM_TIMES() will give
> you more flexibility, but don't go for much more than 50 buckets, and
certainly
> not more than 100.

Done.

[jar (doing other things), 2014-08-01 04:41:47]

lgtm % nit (add units to all your histograms)

https://codereview.chromium.org/409653004/diff/40001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (left):

https://codereview.chromium.org/409653004/diff/40001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:8252: <histogram
name="GCM.RegistrationCompleteTime" units="milliseconds">
nit: You should follow this pattern, and have a "units" tag as shown here in
each case where you are not using an enum or such.

[juyik, 2014-08-01 19:01:05]

https://codereview.chromium.org/409653004/diff/40001/tools/metrics/histograms...
File tools/metrics/histograms/histograms.xml (left):

https://codereview.chromium.org/409653004/diff/40001/tools/metrics/histograms...
tools/metrics/histograms/histograms.xml:8252: <histogram
name="GCM.RegistrationCompleteTime" units="milliseconds">
On 2014/08/01 04:41:46, jar wrote:
> nit: You should follow this pattern, and have a "units" tag as shown here in
> each case where you are not using an enum or such.

Done.

[juyik, 2014-08-01 19:01:11]

The CQ bit was checked by juyik@chromium.org

[commit-bot: I haz the power, 2014-08-01 19:04:26]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/juyik@chromium.org/409653004/60001

[juyik, 2014-08-01 22:36:20]

The CQ bit was unchecked by juyik@chromium.org

[juyik, 2014-08-05 18:26:59]

The CQ bit was checked by juyik@chromium.org

[commit-bot: I haz the power, 2014-08-05 18:29:19]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/juyik@chromium.org/409653004/100001

[commit-bot: I haz the power, 2014-08-05 23:07:56]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  linux_chromium_rel_swarming on tryserver.chromium.linux
(http://build.chromium.org/p/tryserver.chromium.linux/builders/linux_chromium_...)

[commit-bot: I haz the power, 2014-08-05 23:38:58]

Change committed as 287645