ServiceWorker: Insert TRACE_EVENT to watch a breakdown of the ServiceWorker's performance on chome:…

ServiceWorker: Insert TRACE_EVENT to watch a breakdown of the ServiceWorker's performance on chome://tracing

Add TRACE_EVENT into each IPC message receiver and some important procedure (register, unregister and fetch).

BUG=401389
TEST=N/A

Committed: https://crrev.com/a606afb489ec211fff1e2fb0445d77fdeb24a99d
Cr-Commit-Position: refs/heads/master@{#293696}

[shimazu, 2014-09-04 07:04:57]

shimazu@chromium.org changed reviewers:
+ horo@chromium.org

[shimazu, 2014-09-04 07:04:57]

Please review kindly.

[horo, 2014-09-05 03:54:39]

https://codereview.chromium.org/538913002/diff/1/content/browser/service_work...
File content/browser/service_worker/service_worker_write_to_cache_job.cc
(right):

https://codereview.chromium.org/538913002/diff/1/content/browser/service_work...
content/browser/service_worker/service_worker_write_to_cache_job.cc:49:
"ServiceWorkerWriteToCacheJob::Start -> "
As we talked offline, I think using " -> " looks strange.

https://codereview.chromium.org/538913002/diff/1/content/browser/service_work...
content/browser/service_worker/service_worker_write_to_cache_job.cc:225:
TRACE_EVENT2("ServiceWorker",
Use ASYNC_STEP_INTO or ASYNC_STEP_PAST.

[shimazu, 2014-09-05 07:03:02]

ASYNC messages are changed, and ASYNC_STEP_INTOn is used instead of some
ASYNC_BEGIN/ASYNC_END event.
Could you review again?

https://codereview.chromium.org/538913002/diff/1/content/browser/service_work...
File content/browser/service_worker/service_worker_write_to_cache_job.cc
(right):

https://codereview.chromium.org/538913002/diff/1/content/browser/service_work...
content/browser/service_worker/service_worker_write_to_cache_job.cc:49:
"ServiceWorkerWriteToCacheJob::Start -> "
On 2014/09/05 03:54:38, horo wrote:
> As we talked offline, I think using " -> " looks strange.

Done.

https://codereview.chromium.org/538913002/diff/1/content/browser/service_work...
content/browser/service_worker/service_worker_write_to_cache_job.cc:225:
TRACE_EVENT2("ServiceWorker",
On 2014/09/05 03:54:38, horo wrote:
> Use ASYNC_STEP_INTO or ASYNC_STEP_PAST.

Done.

[horo, 2014-09-05 11:02:33]

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
File content/browser/service_worker/service_worker_controllee_request_handler.cc
(right):

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:121:
"ServiceWorkerControlleeRequestHandler::PrepareForMainResource -> "
ServiceWorkerControlleeRequestHandler::PrepareForMainResource

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:147:
"ServiceWorkerControlleeRequestHandler::PrepareForMainResource -> "
ditto

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:178:
"ServiceWorkerControlleeRequestHandler::"
ditto

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:192:
"PrepareForMainResource->DidLookupRegistrationForMainResource",
ditto

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:205:
"PrepareForMainResource->DidLookupRegistrationForMainResource",
ditto

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
File content/browser/service_worker/service_worker_storage.cc (right):

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_storage.cc:258:
base::Hash(document_url.spec()),
I think we can use the pointer of callback as ID.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
File content/child/service_worker/service_worker_dispatcher.cc (right):

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:257:
TRACE_EVENT0("ServiceWorker",
TRACE_EVENT_ASYNC_STEP is better.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:283:
TRACE_EVENT0("ServiceWorker",
TRACE_EVENT_ASYNC_STEP is better.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:301:
TRACE_EVENT0("ServiceWorker",
TRACE_EVENT_ASYNC_STEP

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:313: }
TRACE_EVENT_ASYNC_END

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:320:
TRACE_EVENT0("ServiceWorker",
TRACE_EVENT_ASYNC_STEP

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:332: }
TRACE_EVENT_ASYNC_END

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

https://codereview.chromium.org/538913002/diff/20001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:107: "Major
component are the load time of SW script "
I think we don't need this info.

https://codereview.chromium.org/538913002/diff/20001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:195: "Info",
"Major component is the execution time of SW script.");
I think we don't need this info.

https://codereview.chromium.org/538913002/diff/20001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:351:
"EmbeddedWorkerContextClient",
EmbeddedWorkerContextClien will keep alive after this point.
So I think "StartingWorkerContext" is better.

[shimazu, 2014-09-08 07:04:46]

I incorporated the reviews, so please review again.

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
File content/browser/service_worker/service_worker_controllee_request_handler.cc
(right):

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:121:
"ServiceWorkerControlleeRequestHandler::PrepareForMainResource -> "
On 2014/09/05 11:02:32, horo wrote:
> ServiceWorkerControlleeRequestHandler::PrepareForMainResource

Done.

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:147:
"ServiceWorkerControlleeRequestHandler::PrepareForMainResource -> "
On 2014/09/05 11:02:32, horo wrote:
> ditto

Done.

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:178:
"ServiceWorkerControlleeRequestHandler::"
On 2014/09/05 11:02:32, horo wrote:
> ditto 

Done.

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:192:
"PrepareForMainResource->DidLookupRegistrationForMainResource",
On 2014/09/05 11:02:32, horo wrote:
> ditto 

Done.

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_controllee_request_handler.cc:205:
"PrepareForMainResource->DidLookupRegistrationForMainResource",
On 2014/09/05 11:02:32, horo wrote:
> ditto 

Done.

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
File content/browser/service_worker/service_worker_storage.cc (right):

https://codereview.chromium.org/538913002/diff/20001/content/browser/service_...
content/browser/service_worker/service_worker_storage.cc:258:
base::Hash(document_url.spec()),
On 2014/09/05 11:02:32, horo wrote:
> I think we can use the pointer of callback as ID.

I think so, too.
But the pointer is different between in FindRegistrationForDocument and in
DidFindRegistrationForDocument. I don't know the internal implementation of
base::Bind well, so I used the document_url.spec() as better solution.
Do you have any idea of this?

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
File content/child/service_worker/service_worker_dispatcher.cc (right):

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:257:
TRACE_EVENT0("ServiceWorker",
On 2014/09/05 11:02:32, horo wrote:
> TRACE_EVENT_ASYNC_STEP is better.

Done.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:283:
TRACE_EVENT0("ServiceWorker",
On 2014/09/05 11:02:32, horo wrote:
> TRACE_EVENT_ASYNC_STEP is better.

Done.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:301:
TRACE_EVENT0("ServiceWorker",
On 2014/09/05 11:02:32, horo wrote:
> TRACE_EVENT_ASYNC_STEP

Done.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:313: }
On 2014/09/05 11:02:32, horo wrote:
> TRACE_EVENT_ASYNC_END

Done.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:320:
TRACE_EVENT0("ServiceWorker",
On 2014/09/05 11:02:32, horo wrote:
> TRACE_EVENT_ASYNC_STEP

Done.

https://codereview.chromium.org/538913002/diff/20001/content/child/service_wo...
content/child/service_worker/service_worker_dispatcher.cc:332: }
On 2014/09/05 11:02:32, horo wrote:
> TRACE_EVENT_ASYNC_END

Done.

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

https://codereview.chromium.org/538913002/diff/20001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:107: "Major
component are the load time of SW script "
On 2014/09/05 11:02:32, horo wrote:
> I think we don't need this info.

Done.

https://codereview.chromium.org/538913002/diff/20001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:195: "Info",
"Major component is the execution time of SW script.");
On 2014/09/05 11:02:32, horo wrote:
> I think we don't need this info.

Done.

https://codereview.chromium.org/538913002/diff/20001/content/renderer/service...
content/renderer/service_worker/embedded_worker_context_client.cc:351:
"EmbeddedWorkerContextClient",
On 2014/09/05 11:02:32, horo wrote:
> EmbeddedWorkerContextClien will keep alive after this point.
> So I think "StartingWorkerContext" is better.

I think this should contain the class name for understandability and
searchability because the appearance on the chrome:tracing is "NAME:STEP"
format. But if someone add the more ASYNC trace flow, this name is conflicting.
So I changed the name to "Class::Event" format:
"EmbeddedWorkerContextClient::StartingWorkerContext" in this case.

[horo, 2014-09-08 07:50:22]

lgtm with nit.

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

https://codereview.chromium.org/538913002/diff/40001/content/browser/service_...
content/browser/service_worker/service_worker_register_job.cc:9: #include
"base/debug/trace_event.h"
remove this

[shimazu, 2014-09-08 08:37:54]

The CQ bit was checked by shimazu@chromium.org

[commit-bot: I haz the power, 2014-09-08 08:39:12]

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

[commit-bot: I haz the power, 2014-09-08 09:41:31]

Committed patchset #4 (id:60001) as 3b8a53a397738cdbc8699e1ea0e2a9a9c049dea5

[commit-bot: I haz the power, 2014-09-10 03:45:24]

Patchset 4 (id:??) landed as
https://crrev.com/a606afb489ec211fff1e2fb0445d77fdeb24a99d
Cr-Commit-Position: refs/heads/master@{#293696}