Service Worker: Add metrics and timeout for starting a Service Worker.

Service Worker: Add metrics and timeout for starting a Service Worker.

There are some reports of SW getting wedged in the "STARTING" state.
This CL adds metrics to understand the issue and a timeout for
aborting start so that retrying might succeed.

The timeout is 5 minutes (same as the limit for events proposed in
crbug.com/372436). We already have a timeout for 30 seconds of script
evaluation, so this new timeout covers possible failures like getting
stuck trying to allocate a process or waiting for an ack from the
renderer.

5 minutes may be too harsh for users on slow connections, so future
work on some sort of exponential backoff or varying the limit for new
vs installed workers may be possible. An existing issue is the 30
second timeout for script evaluation includes importScripts(),
which could potentially take a long time downloading scripts.

BUG=448003
Committed: https://crrev.com/292e84ac2c4a0b0074d5ece1eabfebec7fed1ebb
Cr-Commit-Position: refs/heads/master@{#319262}

[falken, 2015-02-27 12:06:34]

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

[falken, 2015-02-27 12:06:35]

PTAL. Depends on tiny issue https://codereview.chromium.org/964483004/

[kinuko, 2015-03-02 03:19:33]

Looking good. Having version.cc overloaded with more times concerns me a bit,
but for now we can deal with them..

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
File content/browser/service_worker/embedded_worker_instance.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/embedded_worker_instance.cc:222:
weak_factory_(this) {
initializing starting_phase_ here?

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/embedded_worker_instance.cc:474: case
SCRIPT_DOWNLOAD:
nit: This one looks slightly inconsistent from others...
SCRIPT_DOWNLOADING? DOWNLOAD_SCRIPT?

Also for the ones that use imperative forms using -ing form might be more
understandable? (Just wondering, up to you)

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/service_worker_version.cc:394:
ScheduleStartWorkerTimeout();
when we come here running_status() == STOPPED should be always true?

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/service_worker_version.cc:1529:
start_worker_timeout_timer_.Reset();
Hm, why do we reset but not stop the timer here?

https://codereview.chromium.org/962543005/diff/40001/content/common/service_w...
File content/common/service_worker/service_worker_status_code.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/common/service_w...
content/common/service_worker/service_worker_status_code.cc:43: return "The
ServiceWorker timed out.";
nit: not remember why, but it looks we don't seem to add period in this method
(so probably we should not do so here or add periods to all)

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
File content/renderer/service_worker/embedded_worker_context_client.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:227:
weak_factory_.GetWeakPtr()));
Did you need to move this method? Could you explain a bit?

[falken, 2015-03-02 04:19:17]

Thanks PTAL.

> Having version.cc overloaded with more times concerns me a bit,
but for now we can deal with them..

Hrm, my next patch was going to add a timer for event timeouts. I'll see if I
can start coalescing timers.

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
File content/browser/service_worker/embedded_worker_instance.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/embedded_worker_instance.cc:222:
weak_factory_(this) {
On 2015/03/02 03:19:33, kinuko wrote:
> initializing starting_phase_ here?

Done.

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/embedded_worker_instance.cc:474: case
SCRIPT_DOWNLOAD:
On 2015/03/02 03:19:33, kinuko wrote:
> nit: This one looks slightly inconsistent from others...
> SCRIPT_DOWNLOADING? DOWNLOAD_SCRIPT?
> 
> Also for the ones that use imperative forms using -ing form might be more
> understandable? (Just wondering, up to you)

Adjusted the names a bit, how's this?

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/service_worker_version.cc:394:
ScheduleStartWorkerTimeout();
On 2015/03/02 03:19:33, kinuko wrote:
> when we come here running_status() == STOPPED should be always true?

Not necessarily, you could call StopWorker(); StartWorker(); so running_status
is STOPPING.

We shouldn't have status STARTING though I think.

https://codereview.chromium.org/962543005/diff/40001/content/browser/service_...
content/browser/service_worker/service_worker_version.cc:1529:
start_worker_timeout_timer_.Reset();
On 2015/03/02 03:19:33, kinuko wrote:
> Hm, why do we reset but not stop the timer here?

Changed to stop here and restart the timer in SetDevToolsAttached.

https://codereview.chromium.org/962543005/diff/40001/content/common/service_w...
File content/common/service_worker/service_worker_status_code.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/common/service_w...
content/common/service_worker/service_worker_status_code.cc:43: return "The
ServiceWorker timed out.";
On 2015/03/02 03:19:33, kinuko wrote:
> nit: not remember why, but it looks we don't seem to add period in this method
> (so probably we should not do so here or add periods to all)

to minimize patch, removed the period

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
File content/renderer/service_worker/embedded_worker_context_client.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:227:
weak_factory_.GetWeakPtr()));
On 2015/03/02 03:19:33, kinuko wrote:
> Did you need to move this method? Could you explain a bit?

It's just a cleanup. It was pretty confusing to reason about the message order
with the current code. Now it should be more clear the order is ScriptLoaded,
ScriptEvaluated, WorkerStarted.

[kinuko, 2015-03-02 06:13:19]

lgtm

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
File content/renderer/service_worker/embedded_worker_context_client.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:227:
weak_factory_.GetWeakPtr()));
On 2015/03/02 04:19:17, falken wrote:
> On 2015/03/02 03:19:33, kinuko wrote:
> > Did you need to move this method? Could you explain a bit?
> 
> It's just a cleanup. It was pretty confusing to reason about the message order
> with the current code. Now it should be more clear the order is ScriptLoaded,
> ScriptEvaluated, WorkerStarted.

I see. We probably don't need to call the SendWorkerStarted asynchronously in
the new code?

https://codereview.chromium.org/962543005/diff/80001/content/browser/service_...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/80001/content/browser/service_...
content/browser/service_worker/service_worker_version.cc:316:
base::TimeDelta::FromSeconds(5)) {
nit: use constant here?

https://codereview.chromium.org/962543005/diff/80001/content/browser/service_...
File content/browser/service_worker/service_worker_version.h (right):

https://codereview.chromium.org/962543005/diff/80001/content/browser/service_...
content/browser/service_worker/service_worker_version.h:427: // metrics about
startup.
Nice informative comments.

[falken, 2015-03-02 06:33:16]

Thanks.

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
File content/renderer/service_worker/embedded_worker_context_client.cc (right):

https://codereview.chromium.org/962543005/diff/40001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:227:
weak_factory_.GetWeakPtr()));
On 2015/03/02 06:13:19, kinuko wrote:
> On 2015/03/02 04:19:17, falken wrote:
> > On 2015/03/02 03:19:33, kinuko wrote:
> > > Did you need to move this method? Could you explain a bit?
> > 
> > It's just a cleanup. It was pretty confusing to reason about the message
order
> > with the current code. Now it should be more clear the order is
ScriptLoaded,
> > ScriptEvaluated, WorkerStarted.
> 
> I see. We probably don't need to call the SendWorkerStarted asynchronously in
> the new code?

Yes I think the only reason we'd send async is if something happens
synchronously after evaluate() that we want to make sure finishes, which
probably isn't the case. I think WorkerScriptEvaluated and WorkerStarted could
probably be combined to the same message.

https://codereview.chromium.org/962543005/diff/80001/content/browser/service_...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/80001/content/browser/service_...
content/browser/service_worker/service_worker_version.cc:316:
base::TimeDelta::FromSeconds(5)) {
On 2015/03/02 06:13:19, kinuko wrote:
> nit: use constant here?

Done.

[falken, 2015-03-02 06:36:21]

falken@chromium.org changed reviewers:
+ asvitkine@chromium.org, peter@chromium.org

[falken, 2015-03-02 06:36:22]

asvitkine: histograms. I also have a question, is it possible for the histogram
enums to change later (new values added or old values deleted)? I guess in some
cases you would just have some transition period of weird data?

peter: notifications and push_messaging

[Peter Beverloo, 2015-03-02 14:23:38]

push and notifications lgtm % nit

https://codereview.chromium.org/962543005/diff/100001/content/browser/push_me...
File content/browser/push_messaging/push_messaging_message_filter.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/push_me...
content/browser/push_messaging/push_messaging_message_filter.cc:555: case
SERVICE_WORKER_ERROR_TIMEOUT:
nit: Please add a TODO for us to handle SERVICE_WORKER_ERROR_TIMEOUT more
gracefully, if this is also going to be used for the 30-second execution
timeout. It's a bit harsh to unregister a developer's push registration if their
JavaScript executes for >30s.

I'll add a task for us to handle this on the Push side.

[Peter Beverloo, 2015-03-02 14:26:02]

https://codereview.chromium.org/962543005/diff/100001/content/browser/push_me...
File content/browser/push_messaging/push_messaging_message_filter.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/push_me...
content/browser/push_messaging/push_messaging_message_filter.cc:555: case
SERVICE_WORKER_ERROR_TIMEOUT:
On 2015/03/02 14:23:37, Peter Beverloo wrote:
> nit: Please add a TODO for us to handle SERVICE_WORKER_ERROR_TIMEOUT more
> gracefully, if this is also going to be used for the 30-second execution
> timeout. It's a bit harsh to unregister a developer's push registration if
their
> JavaScript executes for >30s.
> 
> I'll add a task for us to handle this on the Push side.

Scrap that, I was reading the wrong function :-). lgtm!

[falken, 2015-03-02 14:44:03]

https://codereview.chromium.org/962543005/diff/100001/content/browser/push_me...
File content/browser/push_messaging/push_messaging_message_filter.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/push_me...
content/browser/push_messaging/push_messaging_message_filter.cc:555: case
SERVICE_WORKER_ERROR_TIMEOUT:
On 2015/03/02 14:26:01, Peter Beverloo wrote:
> On 2015/03/02 14:23:37, Peter Beverloo wrote:
> > nit: Please add a TODO for us to handle SERVICE_WORKER_ERROR_TIMEOUT more
> > gracefully, if this is also going to be used for the 30-second execution
> > timeout. It's a bit harsh to unregister a developer's push registration if
> their
> > JavaScript executes for >30s.
> > 
> > I'll add a task for us to handle this on the Push side.
> 
> Scrap that, I was reading the wrong function :-). lgtm!

OK :) I just want to confirm this is OK... currently the 30 second timeout will
stop a service worker that's busy executing JS. If this function was a callback
registered to the ServiceWorkerVersion at that time, the current implementation
will call it with SERVICE_WORKER_ERROR_FAILED (see
ServiceWorkerVersion::OnStopped).

I guess if this callback isn't for an operation that blocks on the worker doing
JavaScript, then the timeout shouldn't be an issue.

Also, in future patches, I'm planning to change the error code for 30-second
timeout to SERVICE_WORKER_ERROR_TIMEOUT to reflect the reason the worker was
stopped.

[Alexei Svitkine (slow), 2015-03-02 16:30:13]

asvitkine@chromium.org changed reviewers:
+ rkaplow@chromium.org

[Alexei Svitkine (slow), 2015-03-02 16:30:13]

+rkaplow, could you do an initial histograms review?

[rkaplow, 2015-03-03 15:58:41]

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:9: #include
"base/metrics/histogram.h"
histogram_macros.h

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:99: const int
kDestructedStartingWorkerTimeoutThreshold = 5;  // 5 secs.
add Sec in const name?

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:1560:
UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorkerVersion.StartWorkerTime",
this histogram will measure up to 3minutes. Considering your timeout is set to 5
minutes, do you expect a lot of entries to exceed 3min?
I would say if you think >=~1% of values would exceed 3 minutes, then I would
use a longer scope. Otherwise this is ok.

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
File content/browser/service_worker/service_worker_version.h (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.h:423: //
ScheduleStartWorkerTimeout is called when attempting to the start the
to* start

[falken, 2015-03-03 16:23:58]

Thanks for the review, just a comment for now to minimize time zone RTT.

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:1560:
UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorkerVersion.StartWorkerTime",
On 2015/03/03 15:58:41, rkaplow wrote:
> this histogram will measure up to 3minutes. Considering your timeout is set to
5
> minutes, do you expect a lot of entries to exceed 3min?
> I would say if you think >=~1% of values would exceed 3 minutes, then I would
> use a longer scope. Otherwise this is ok.

No, I expect it to be very rare that a SW takes 3+ minutes to successfully start
up.

... but I'm curious, is the scope something that is adjustable later? Also what
if the histogram enum values change (like if starting phases are added or
removed)?

[rkaplow, 2015-03-03 16:30:15]

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:1560:
UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorkerVersion.StartWorkerTime",
On 2015/03/03 16:23:58, falken wrote:
> On 2015/03/03 15:58:41, rkaplow wrote:
> > this histogram will measure up to 3minutes. Considering your timeout is set
to
> 5
> > minutes, do you expect a lot of entries to exceed 3min?
> > I would say if you think >=~1% of values would exceed 3 minutes, then I
would
> > use a longer scope. Otherwise this is ok.
> 
> No, I expect it to be very rare that a SW takes 3+ minutes to successfully
start
> up.
Then looks good.
> 
> ... but I'm curious, is the scope something that is adjustable later? Also
what
> if the histogram enum values change (like if starting phases are added or
> removed)?

The scope is not really adjustable later, as if you naively increased it without
changing the name of the histogram, the resulting data would be very messy, as
it would be getting from two different data sources (with different bucket
ranges).
Which isn't to say there's nothing to do. You would just add a second histogram
called  ServiceWorkerVersion.StartWorkerTimeLong, and eventually you would
obsolete the old one. This is totally fine and happens not infrequently. It is
nice to not have to bother with that and get it right the first time, though.

No issue with adding new enum entries. You wouldn't really ever remove the old
one since very old clients may still report them.

[falken, 2015-03-04 04:16:35]

Thanks, updated.

I guess that means we have to be careful not to change the order or remove
entries of our enums. I've added a comment to the enums used for histograms
accordingly.

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:9: #include
"base/metrics/histogram.h"
On 2015/03/03 15:58:41, rkaplow wrote:
> histogram_macros.h

Done.

https://codereview.chromium.org/962543005/diff/100001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:99: const int
kDestructedStartingWorkerTimeoutThreshold = 5;  // 5 secs.
On 2015/03/03 15:58:41, rkaplow wrote:
> add Sec in const name?

Done. I feel like there's a more pithy name possible... oh well.

[rkaplow, 2015-03-04 15:34:36]

lgtm

[falken, 2015-03-04 15:38:18]

Thanks! avstikine: can you review as OWNER please?

[falken, 2015-03-04 15:39:39]

On 2015/03/04 15:38:18, falken wrote:
> Thanks! avstikine: can you review as OWNER please?

err... asvitkine (sorry about that!)

[Alexei Svitkine (slow), 2015-03-04 15:46:38]

https://codereview.chromium.org/962543005/diff/140001/content/browser/service...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/140001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:1569: std::string
message = "ServiceWorker startup timed out. ";
Normally, we don't hardcode user-visible strings in the source code and instead
use resources - which can be localized.

Is it intentional to have these not use this system? If so, you should probably
add a comment.

https://codereview.chromium.org/962543005/diff/140001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/962543005/diff/140001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:33451: +<histogram
name="ServiceWorkerVersion.StartWorkerStatus"
Nit: Could you avoid introducing a new top-level prefix?

Since there's already a ServiceWorker.* prefix, I suggest changing these to
ServiceWorker.Version.*.

Although it's also not clear to me what ServiceWorkerVersion.StartWorkerStatus
has to do with the service worker version. Should it just be
ServiceWorker.StartWorkerStatus or actually even better
ServiceWorker.StartWorker.Status? Same for the others.

[falken, 2015-03-05 08:33:12]

Thanks, updated.

https://codereview.chromium.org/962543005/diff/140001/content/browser/service...
File content/browser/service_worker/service_worker_version.cc (right):

https://codereview.chromium.org/962543005/diff/140001/content/browser/service...
content/browser/service_worker/service_worker_version.cc:1569: std::string
message = "ServiceWorker startup timed out. ";
On 2015/03/04 15:46:38, Alexei Svitkine wrote:
> Normally, we don't hardcode user-visible strings in the source code and
instead
> use resources - which can be localized.
> 
> Is it intentional to have these not use this system? If so, you should
probably
> add a comment.

This is really like a JavaScript exception's message string, it's meant for
developers not users and only seen in DevTools. I've added a comment.

https://codereview.chromium.org/962543005/diff/140001/tools/metrics/histogram...
File tools/metrics/histograms/histograms.xml (right):

https://codereview.chromium.org/962543005/diff/140001/tools/metrics/histogram...
tools/metrics/histograms/histograms.xml:33451: +<histogram
name="ServiceWorkerVersion.StartWorkerStatus"
On 2015/03/04 15:46:38, Alexei Svitkine wrote:
> Nit: Could you avoid introducing a new top-level prefix?
> 
> Since there's already a ServiceWorker.* prefix, I suggest changing these to
> ServiceWorker.Version.*.
> 
> Although it's also not clear to me what ServiceWorkerVersion.StartWorkerStatus
> has to do with the service worker version. Should it just be
> ServiceWorker.StartWorkerStatus or actually even better
> ServiceWorker.StartWorker.Status? Same for the others.

Ah I didn't realize a new top-level prefix was a big deal, I just took the class
name. ServiceWorker.StartWorker.*" sgtm. Done.

[Alexei Svitkine (slow), 2015-03-05 15:45:49]

lgtm

[falken, 2015-03-05 15:52:36]

The CQ bit was checked by falken@chromium.org

[falken, 2015-03-05 15:52:36]

The patchset sent to the CQ was uploaded after l-g-t-m from kinuko@chromium.org,
peter@chromium.org, rkaplow@chromium.org
Link to the patchset: https://codereview.chromium.org/962543005/#ps200001
(title: "sync again")

[commit-bot: I haz the power, 2015-03-05 15:53:03]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/962543005/200001

[commit-bot: I haz the power, 2015-03-05 16:54:32]

Committed patchset #11 (id:200001)

[commit-bot: I haz the power, 2015-03-05 16:55:38]

Patchset 11 (id:??) landed as
https://crrev.com/292e84ac2c4a0b0074d5ece1eabfebec7fed1ebb
Cr-Commit-Position: refs/heads/master@{#319262}