[ServiceWorker] Integrate trace events in embedded worker instance

content/browser/service_worker/embedded_worker_instance.cc

Index: content/browser/service_worker/embedded_worker_instance.cc
diff --git a/content/browser/service_worker/embedded_worker_instance.cc b/content/browser/service_worker/embedded_worker_instance.cc
index e130e4b9e8aaef93f9bb5442214731c710d4dc4b..4919648b1aa2e354567134d71b7c00e5ce1d77f6 100644
--- a/content/browser/service_worker/embedded_worker_instance.cc
+++ b/content/browser/service_worker/embedded_worker_instance.cc
@@ -244,14 +244,16 @@ class EmbeddedWorkerInstance::StartTask {
         is_installed_(false),
         started_during_browser_startup_(false),
         weak_factory_(this) {
-    TRACE_EVENT_ASYNC_BEGIN1("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                             this, "Script", script_url.spec());
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start",
+                                      instance_, "Script", script_url.spec());
   }
 
   ~StartTask() {
     DCHECK_CURRENTLY_ON(BrowserThread::IO);
-    TRACE_EVENT_ASYNC_END0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                           this);
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker",
+                                    "EmbeddedWorkerInstance::Start", instance_);
+
     if (!instance_->context_)
       return;
 
@@ -323,9 +325,11 @@ class EmbeddedWorkerInstance::StartTask {
     DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
     if (status != SERVICE_WORKER_OK) {
-      TRACE_EVENT_ASYNC_STEP_PAST1(
-          "ServiceWorker", "EmbeddedWorkerInstance::Start", this,
-          "OnProcessAllocated", "Error", ServiceWorkerStatusToString(status));
+      TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("ServiceWorker", "OnProcessAllocated",
+                                        instance_, "Error",
+                                        ServiceWorkerStatusToString(status));
+      TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnProcessAllocated",
+                                      instance_);
       DCHECK_EQ(ChildProcessHost::kInvalidUniqueID, process_id);
       StatusCallback callback = start_callback_;
       start_callback_.Reset();
@@ -334,9 +338,9 @@ class EmbeddedWorkerInstance::StartTask {
       return;
     }
 
-    TRACE_EVENT_ASYNC_STEP_PAST1(
-        "ServiceWorker", "EmbeddedWorkerInstance::Start", this,
-        "OnProcessAllocated", "Is New Process", is_new_process);
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("ServiceWorker", "OnProcessAllocated",
+                                      instance_, "Is New Process",
+                                      is_new_process);

[shimazu, 2017/04/21 03:05:41]

My explanation was bad, sorry.

We want to track the duration of each step on each StartingPhase:
https://cs.chromium.org/chromium/src/content/browser/service_worker/embedded_...

For example, ASYNC_STEP_PAST(..., "OnProcessAllocated", ...) is equivalent to
'ALLOCATING_PROCESS'. ASYNC_STEP_PAST records the duration from previous call of
ASYNC_STEP_PAST or ASYNC_STEP_BEGIN.
For using NESTABLE_ASYNC, you can call BEGIN at l.306 and END here. In this
case, using the names in StartingPhase might make things clearer.

Please feel free to ask me if you have questions:)

     if (is_installed_)
       ServiceWorkerMetrics::RecordProcessCreated(is_new_process);
 
@@ -373,6 +377,8 @@ class EmbeddedWorkerInstance::StartTask {
                    base::Bind(&StartTask::OnSetupOnUICompleted,
                               weak_factory_.GetWeakPtr(), base::Passed(&params),
                               is_new_process)));
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnProcessAllocated",
+                                    instance_);
   }
 
   void OnSetupOnUICompleted(
@@ -381,9 +387,8 @@ class EmbeddedWorkerInstance::StartTask {
       std::unique_ptr<EmbeddedWorkerInstance::DevToolsProxy> devtools_proxy,
       bool wait_for_debugger) {
     DCHECK_CURRENTLY_ON(BrowserThread::IO);
-    TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker",
-                                 "EmbeddedWorkerInstance::Start", this,
-                                 "OnSetupOnUICompleted");
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnSetupOnUICompleted",
+                                      instance_);
 
     params->worker_devtools_agent_route_id = devtools_proxy->agent_route_id();
     params->wait_for_debugger = wait_for_debugger;
@@ -394,6 +399,8 @@ class EmbeddedWorkerInstance::StartTask {
 
     ServiceWorkerStatusCode status =
         instance_->SendStartWorker(std::move(params));
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnSetupOnUICompleted",
+                                    instance_);
     if (status != SERVICE_WORKER_OK) {
       StatusCallback callback = start_callback_;
       start_callback_.Reset();
@@ -594,9 +601,9 @@ ServiceWorkerStatusCode EmbeddedWorkerInstance::SendStartWorker(
   client_->StartWorker(*params, std::move(pending_dispatcher_request_),
                        std::move(host_ptr_info));
   registry_->BindWorkerToProcess(process_id(), embedded_worker_id());
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               this, "SendStartWorker");
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "SendStartWorker", this);
   OnStartWorkerMessageSent();
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "SendStartWorker", this);
   return SERVICE_WORKER_OK;
 }
 
@@ -615,9 +622,12 @@ void EmbeddedWorkerInstance::OnStartWorkerMessageSent() {
 }
 
 void EmbeddedWorkerInstance::OnReadyForInspection() {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnReadyForInspection");
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnReadyForInspection",
+                                    this);
   if (devtools_proxy_)
     devtools_proxy_->NotifyWorkerReadyForInspection();
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnReadyForInspection",
+                                  this);
 }
 
 void EmbeddedWorkerInstance::OnScriptReadStarted() {
@@ -630,7 +640,6 @@ void EmbeddedWorkerInstance::OnScriptReadFinished() {
 
 void EmbeddedWorkerInstance::OnScriptLoaded() {
   using LoadSource = ServiceWorkerMetrics::LoadSource;
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnScriptLoaded");
 
   if (!inflight_start_task_)
     return;
@@ -643,10 +652,10 @@ void EmbeddedWorkerInstance::OnScriptLoaded() {
   } else {
     source = LoadSource::HTTP_CACHE;
   }
-  TRACE_EVENT_ASYNC_STEP_PAST1(
-      "ServiceWorker", "EmbeddedWorkerInstance::Start",
-      inflight_start_task_.get(), "OnScriptLoaded", "Source",
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
+      "ServiceWorker", "OnScriptLoaded", this, "Source",
       ServiceWorkerMetrics::LoadSourceToString(source));
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnScriptLoaded", this);
 
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
@@ -662,13 +671,14 @@ void EmbeddedWorkerInstance::OnScriptLoaded() {
 void EmbeddedWorkerInstance::OnURLJobCreatedForMainScript() {
   if (!inflight_start_task_)
     return;
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnURLJobCreated");
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnURLJobCreated", this);
+
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
     if (inflight_start_task_->is_installed())
       ServiceWorkerMetrics::RecordTimeToURLJob(duration, start_situation_);
   }
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnURLJobCreated", this);
 }
 
 void EmbeddedWorkerInstance::OnWorkerVersionInstalled() {
@@ -682,7 +692,8 @@ void EmbeddedWorkerInstance::OnWorkerVersionDoomed() {
 }
 
 void EmbeddedWorkerInstance::OnThreadStarted(int thread_id, int provider_id) {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnThreadStarted");
+  if (!inflight_start_task_)
+    return;
   if (!context_)
     return;
 
@@ -694,12 +705,9 @@ void EmbeddedWorkerInstance::OnThreadStarted(int thread_id, int provider_id) {
     return;
   }
 
-  provider_host->SetReadyToSendMessagesToWorker(thread_id);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnThreadStarted", this);
 
-  if (!inflight_start_task_)
-    return;
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnThreadStarted");
+  provider_host->SetReadyToSendMessagesToWorker(thread_id);
 
   starting_phase_ = THREAD_STARTED;
   if (!step_time_.is_null()) {
@@ -711,28 +719,29 @@ void EmbeddedWorkerInstance::OnThreadStarted(int thread_id, int provider_id) {
   thread_id_ = thread_id;
   for (auto& observer : listener_list_)
     observer.OnThreadStarted();
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnThreadStarted", this);
 }
 
 void EmbeddedWorkerInstance::OnScriptLoadFailed() {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnScriptLoadFailed");
   if (!inflight_start_task_)
     return;
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(),
-                               "OnScriptLoadFailed");
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnScriptLoadFailed",
+                                    this);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnScriptLoadFailed", this);
+
   for (auto& observer : listener_list_)
     observer.OnScriptLoadFailed();
 }
 
 void EmbeddedWorkerInstance::OnScriptEvaluated(bool success) {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnScriptEvaluated");
   if (!inflight_start_task_)
     return;
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("ServiceWorker", "OnScriptEvaluated", this,
+                                    "Success", success);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnScriptEvaluated", this);
+
   DCHECK_EQ(EmbeddedWorkerStatus::STARTING, status_);
 
-  TRACE_EVENT_ASYNC_STEP_PAST1("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnScriptEvaluated",
-                               "Success", success);
   starting_phase_ = SCRIPT_EVALUATED;
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
@@ -750,14 +759,16 @@ void EmbeddedWorkerInstance::OnScriptEvaluated(bool success) {
 }
 
 void EmbeddedWorkerInstance::OnStarted() {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnStarted");
   if (!registry_->OnWorkerStarted(process_id(), embedded_worker_id_))
     return;
   // Stop is requested before OnStarted is sent back from the worker.
   if (status_ == EmbeddedWorkerStatus::STOPPING)
     return;
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnStarted", this);
+
   DCHECK(status_ == EmbeddedWorkerStatus::STARTING);
   status_ = EmbeddedWorkerStatus::RUNNING;
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnStarted", this);
   inflight_start_task_.reset();
   for (auto& observer : listener_list_)
     observer.OnStarted();