Add UMA for how long service workers run for.

Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.

Ideally we'd additionally like to know 1) about SW's that
never stop, and 2) why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but there's some complexity
there so we're starting simple.

BUG=683047
Review-Url: https://codereview.chromium.org/2706923003
Cr-Commit-Position: refs/heads/master@{#457669}
Committed: https://chromium.googlesource.com/chromium/src/+/f93cb21f636207e7f0573bf99681bfce4951e0f7

[falken, 2017-02-23 04:16:34]

Description was changed from

==========
WIP SW running times.

BUG=683047
==========

to

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. Ideally we'd like to know why
a SW stays alive particularly if it's for a long time, and
also be able to distinguish valid use from abusive use, but
there is no known way to do that.

BUG=683047
==========

[falken, 2017-02-23 04:16:34]

falken@chromium.org changed reviewers:
+ nhiroki@chromium.org

[falken, 2017-02-23 04:22:30]

Description was changed from

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. Ideally we'd like to know why
a SW stays alive particularly if it's for a long time, and
also be able to distinguish valid use from abusive use, but
there is no known way to do that.

BUG=683047
==========

to

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. Ideally we'd like to know why
a SW stays alive particularly if it's for a long time, and
also be able to distinguish valid use from abusive use, but
we are not yet able to do this.

BUG=683047
==========

[falken, 2017-02-23 04:24:15]

Description was changed from

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. Ideally we'd like to know why
a SW stays alive particularly if it's for a long time, and
also be able to distinguish valid use from abusive use, but
we are not yet able to do this.

BUG=683047
==========

to

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.
* ServiceWorker.StillRunningTime
  - Recorded every 5 minutes. If a service worker has been
running for over 5 minutes, that worker's running time is
recorded (wall time).

StillRunningTime is needed to catch workers that never stop,
if they exist.

Ideally we'd like to know why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but we are not yet able to do this.

BUG=683047
==========

[falken, 2017-02-23 04:25:00]

Description was changed from

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.
* ServiceWorker.StillRunningTime
  - Recorded every 5 minutes. If a service worker has been
running for over 5 minutes, that worker's running time is
recorded (wall time).

StillRunningTime is needed to catch workers that never stop,
if they exist.

Ideally we'd like to know why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but we are not yet able to do this.

BUG=683047
==========

to

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.
* ServiceWorker.StillRunningTime
  - Recorded every 5 minutes. If a service worker has been
running for over 5 minutes, that worker's running time is
recorded (wall time).

StillRunningTime is needed to catch workers that never stop,
if they exist.

Ideally we'd like to know why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but there's some complexity there
so we're starting simple.

BUG=683047
==========

[falken, 2017-02-23 04:28:23]

ptal

[falken, 2017-02-23 04:28:32]

The CQ bit was checked by falken@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-02-23 04:28:51]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[nhiroki, 2017-02-23 07:54:24]

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_context_core.h (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_context_core.h:316: struct
RunningInfo {
Who uses this?

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_lifetime_tracker.cc (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:13: constexpr
base::TimeDelta kTimerDuration = base::TimeDelta::FromMinutes(5);
Can you add a comment about why we chose 5 mins?

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:17:
base::WrapUnique(new base::DefaultTickClock)) {}
base::MakeUnique<base::DefaultTickClock>()?

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:25:
ServiceWorkerLifetimeTracker::~ServiceWorkerLifetimeTracker() {}
= default;

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:28:
DCHECK(running_workers_.find(version_id) == running_workers_.end());
DCHECK(!base::ContainsKey(running_workers_, version_id)); could be simpler.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:34:
weak_factory_.GetWeakPtr()));
I wonder if we don't have to make |this| weak because timer_ should be stopped
on the dtor of |this|.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_lifetime_tracker.h (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.h:38:
FRIEND_TEST_ALL_PREFIXES(ServiceWorkerLifetimeTrackerTest, Metrics);
Is this FRIEND_TEST_ALL_PREFIXES necessary? It looks like this test touches only
public functions.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_metrics.cc (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_metrics.cc:982:
UMA_HISTOGRAM_LONG_TIMES("ServiceWorker.Runtime", time);
According to a header comment[1], UMA_HISTOGRAM_LONG_TIMES can record duration
up to an hour. I feel it'd be somewhat short. WDYT?

[1]
https://chromium.googlesource.com/chromium/src/+/dbfe909f3404ff148339c0396556...

[falken, 2017-02-23 08:18:18]

Thanks!

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_context_core.h (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_context_core.h:316: struct
RunningInfo {
On 2017/02/23 07:54:23, nhiroki wrote:
> Who uses this?

An old version of the CL. Deleted.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_lifetime_tracker.cc (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:13: constexpr
base::TimeDelta kTimerDuration = base::TimeDelta::FromMinutes(5);
On 2017/02/23 07:54:23, nhiroki wrote:
> Can you add a comment about why we chose 5 mins?

Good idea. Done.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:17:
base::WrapUnique(new base::DefaultTickClock)) {}
On 2017/02/23 07:54:23, nhiroki wrote:
> base::MakeUnique<base::DefaultTickClock>()?

Done.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:25:
ServiceWorkerLifetimeTracker::~ServiceWorkerLifetimeTracker() {}
On 2017/02/23 07:54:23, nhiroki wrote:
> = default;

Done.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:28:
DCHECK(running_workers_.find(version_id) == running_workers_.end());
On 2017/02/23 07:54:23, nhiroki wrote:
> DCHECK(!base::ContainsKey(running_workers_, version_id)); could be simpler.

Done.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.cc:34:
weak_factory_.GetWeakPtr()));
On 2017/02/23 07:54:23, nhiroki wrote:
> I wonder if we don't have to make |this| weak because timer_ should be stopped
> on the dtor of |this|.

Ah I think you're right. Done.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_lifetime_tracker.h (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_lifetime_tracker.h:38:
FRIEND_TEST_ALL_PREFIXES(ServiceWorkerLifetimeTrackerTest, Metrics);
On 2017/02/23 07:54:23, nhiroki wrote:
> Is this FRIEND_TEST_ALL_PREFIXES necessary? It looks like this test touches
only
> public functions.

Ah, that was also refactored away. Done.

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_metrics.cc (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_metrics.cc:982:
UMA_HISTOGRAM_LONG_TIMES("ServiceWorker.Runtime", time);
On 2017/02/23 07:54:23, nhiroki wrote:
> According to a header comment[1], UMA_HISTOGRAM_LONG_TIMES can record duration
> up to an hour. I feel it'd be somewhat short. WDYT?
> 
> [1]
>
https://chromium.googlesource.com/chromium/src/+/dbfe909f3404ff148339c0396556...

Yes I saw this but figured for our purposes 1 hour is not much different from a
1 day, also I figure the buckets would get more coarse even though we would like
to distinguish between shorter times (e.g., 1 sec vs 10 sec vs 1 minute is
pretty significant). Not totally sure. WDYT?

[falken, 2017-02-23 08:24:59]

The CQ bit was checked by falken@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-02-23 08:25:23]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-02-23 08:56:47]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-02-23 08:56:48]

Dry run: Try jobs failed on following builders:
  cast_shell_linux on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/cast_shell_linu...)

[nhiroki, 2017-02-23 09:05:06]

lgtm

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
File content/browser/service_worker/service_worker_metrics.cc (right):

https://codereview.chromium.org/2706923003/diff/90001/content/browser/service...
content/browser/service_worker/service_worker_metrics.cc:982:
UMA_HISTOGRAM_LONG_TIMES("ServiceWorker.Runtime", time);
On 2017/02/23 08:18:18, falken wrote:
> On 2017/02/23 07:54:23, nhiroki wrote:
> > According to a header comment[1], UMA_HISTOGRAM_LONG_TIMES can record
duration
> > up to an hour. I feel it'd be somewhat short. WDYT?
> > 
> > [1]
> >
>
https://chromium.googlesource.com/chromium/src/+/dbfe909f3404ff148339c0396556...
> 
> Yes I saw this but figured for our purposes 1 hour is not much different from
a
> 1 day, also I figure the buckets would get more coarse even though we would
like
> to distinguish between shorter times (e.g., 1 sec vs 10 sec vs 1 minute is
> pretty significant). Not totally sure. WDYT?

I see, then UMA_HISTOGRAM_LONG_TIMES would be appropriate. Thank you for the
clarification.

[falken, 2017-02-24 08:32:26]

https://codereview.chromium.org/2706923003/diff/110001/content/browser/servic...
File content/browser/service_worker/service_worker_context_core.cc (right):

https://codereview.chromium.org/2706923003/diff/110001/content/browser/servic...
content/browser/service_worker/service_worker_context_core.cc:763: }
Hm it looks like I should just add lifetime_tracker_ to observer_list_, then we
shouldn't need this extra code.

https://codereview.chromium.org/2706923003/diff/110001/content/browser/servic...
File content/browser/service_worker/service_worker_lifetime_tracker.cc (right):

https://codereview.chromium.org/2706923003/diff/110001/content/browser/servic...
content/browser/service_worker/service_worker_lifetime_tracker.cc:34:
DCHECK(!base::ContainsKey(running_workers_, version_id));
I'm hitting this DCHECK in unit tests, but more generally there is no strong
guarantee that StopTiming is called for every StartTiming. For example in
SWVersion dtor, we do a last gasp StopWorker() on EWInstance but the SWVersion
doesn't stick around to listen for the OnStopped event.

So this still needs refinement. If we don't get a StopTiming, the UMA gets
unreliable.

[falken, 2017-02-27 05:58:19]

The CQ bit was checked by falken@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-02-27 05:58:33]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-02-27 07:20:21]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-02-27 07:20:22]

Dry run: This issue passed the CQ dry run.

[falken, 2017-02-27 07:47:12]

updated. I tried making the tracking based on ServiceWorkerContextObserver but
that turns out complex because Observers outlive the ContextCore and must be
created before it. I moved the tracking to be based on EmbeddedWorkerRegistry
which is closer to the starting and stopping of workers and should have taken
care of the hole where a worker gets destructed before it's stopped.

[falken, 2017-02-28 08:01:12]

ping :)

[nhiroki, 2017-02-28 08:28:11]

On 2017/02/28 08:01:12, falken wrote:
> ping :)

Sorry, I missed this. Now reviewing...

[nhiroki, 2017-02-28 08:50:08]

lgtm with nits

https://codereview.chromium.org/2706923003/diff/150001/content/browser/servic...
File content/browser/service_worker/service_worker_lifetime_tracker.h (right):

https://codereview.chromium.org/2706923003/diff/150001/content/browser/servic...
content/browser/service_worker/service_worker_lifetime_tracker.h:29: void
StartTiming(int64_t version_id);
Can you replace version_id with embedded_worker_id because
EmbeddedWorkerRegistry passes it?

https://codereview.chromium.org/2706923003/diff/150001/content/browser/servic...
File content/browser/service_worker/service_worker_version.h (right):

https://codereview.chromium.org/2706923003/diff/150001/content/browser/servic...
content/browser/service_worker/service_worker_version.h:137: virtual void
OnDevToolsAttached(ServiceWorkerVersion* version) {}
Maybe is this no longer necessary?

[falken, 2017-03-16 05:44:49]

Description was changed from

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.
* ServiceWorker.StillRunningTime
  - Recorded every 5 minutes. If a service worker has been
running for over 5 minutes, that worker's running time is
recorded (wall time).

StillRunningTime is needed to catch workers that never stop,
if they exist.

Ideally we'd like to know why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but there's some complexity there
so we're starting simple.

BUG=683047
==========

to

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.

Ideally we'd additionally like to know 1) about SW's that
never stop, and 2) why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but there's some complexity
there so we're starting simple.

BUG=683047
==========

[falken, 2017-03-16 05:54:51]

The CQ bit was checked by falken@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2017-03-16 05:55:06]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[falken, 2017-03-16 05:57:02]

ptal

I removed the StillRunningTime because testing locally revealed it would give
really hard to understand results: a worker that's running for a day would
record a histogram count every 5 minutes. StillRunningTime needs more
refinement.

Runtime only is simpler to deal with, and its results should inform how we want
to design StillRunningTime later.

I also widened the histograms because it would have been too narrow with the
default values (as you rightfully pointed out in a previous review comment).
Added comments to explain.

[commit-bot: I haz the power, 2017-03-16 06:29:18]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2017-03-16 06:29:19]

Dry run: Try jobs failed on following builders:
  cast_shell_linux on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/cast_shell_linu...)

[nhiroki, 2017-03-16 07:12:23]

lgtm

[falken, 2017-03-16 07:29:07]

falken@chromium.org changed reviewers:
+ jwd@chromium.org

[falken, 2017-03-16 07:29:08]

jwd: can you review histograms? Notably, this is using a HISTOGRAM_CUSTOM_TIMES
macro to better fit the expected range of values being measured.

[jwd, 2017-03-16 16:30:17]

lgtm

[falken, 2017-03-17 01:25:14]

falken@chromium.org changed reviewers:
+ kinuko@chromium.org

[falken, 2017-03-17 01:25:15]

+kinuko for content/browser/BUILD.gn

[kinuko, 2017-03-17 01:28:47]

lgtm

[falken, 2017-03-17 01:31:13]

The CQ bit was checked by falken@chromium.org

[commit-bot: I haz the power, 2017-03-17 01:31:41]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2017-03-17 03:05:37]

CQ is committing da patch.

Bot data: {"patchset_id": 210001, "attempt_start_ts": 1489714273636940,
"parent_rev": "094b10ca74c592e19b077905c9ef3ab33fdac38b", "commit_rev":
"f93cb21f636207e7f0573bf99681bfce4951e0f7"}

[commit-bot: I haz the power, 2017-03-17 03:07:12]

Description was changed from

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.

Ideally we'd additionally like to know 1) about SW's that
never stop, and 2) why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but there's some complexity
there so we're starting simple.

BUG=683047
==========

to

==========
Add UMA for how long service workers run for.

We don't have any UMA for how long a SW stays alive, so this
is a step toward fixing that. This adds UMA:
* ServiceWorker.Runtime
  - How long the worker ran for (wall time). Recorded when
a service worker stops.

Ideally we'd additionally like to know 1) about SW's that
never stop, and 2) why a SW stays alive particularly
if it's for a long time, and also be able to distinguish
valid use from abusive use, but there's some complexity
there so we're starting simple.

BUG=683047

Review-Url: https://codereview.chromium.org/2706923003
Cr-Commit-Position: refs/heads/master@{#457669}
Committed:
https://chromium.googlesource.com/chromium/src/+/f93cb21f636207e7f0573bf99681...
==========

[commit-bot: I haz the power, 2017-03-17 03:07:13]

Committed patchset #12 (id:210001) as
https://chromium.googlesource.com/chromium/src/+/f93cb21f636207e7f0573bf99681...