[ServiceWorker] Integrate trace events in embedded worker instance

content/browser/service_worker/embedded_worker_instance.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/browser/service_worker/embedded_worker_instance.h"
 
 #include <utility>
 
 #include "base/bind_helpers.h"
 #include "base/macros.h"
@@ skipping 226 matching lines @@
 
   StartTask(EmbeddedWorkerInstance* instance,
             const GURL& script_url,
             mojom::EmbeddedWorkerInstanceClientRequest request)
       : instance_(instance),
         request_(std::move(request)),
         state_(ProcessAllocationState::NOT_ALLOCATED),
         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;
 
     switch (state_) {
       case ProcessAllocationState::NOT_ALLOCATED:
         // Not necessary to release a process.
         break;
       case ProcessAllocationState::ALLOCATING:
         // Abort half-baked process allocation on the UI thread.
         instance_->context_->process_manager()->ReleaseWorkerProcess(
@@ skipping 51 matching lines @@
 
  private:
   void OnProcessAllocated(std::unique_ptr<EmbeddedWorkerStartParams> params,
                           ServiceWorkerStatusCode status,
                           int process_id,
                           bool is_new_process,
                           const EmbeddedWorkerSettings& settings) {
     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();
       instance_->OnStartFailed(callback, status);
       // |this| may be destroyed.
       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);
 
     ServiceWorkerMetrics::StartSituation start_situation =
         ServiceWorkerMetrics::StartSituation::UNKNOWN;
     if (started_during_browser_startup_)
       start_situation = ServiceWorkerMetrics::StartSituation::DURING_STARTUP;
     else if (is_new_process)
       start_situation = ServiceWorkerMetrics::StartSituation::NEW_PROCESS;
     else
@@ skipping 16 matching lines @@
     const GURL& scope = params->scope;
     GURL script_url(params->script_url);
     BrowserThread::PostTask(
         BrowserThread::UI, FROM_HERE,
         base::Bind(&SetupOnUI, process_id, instance_->context_.get(),
                    instance_->context_, service_worker_version_id, script_url,
                    scope, is_installed_, base::Passed(&request_),
                    base::Bind(&StartTask::OnSetupOnUICompleted,
                               weak_factory_.GetWeakPtr(), base::Passed(&params),
                               is_new_process)));
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "OnProcessAllocated",
+                                    instance_);
   }
 
   void OnSetupOnUICompleted(
       std::unique_ptr<EmbeddedWorkerStartParams> params,
       bool is_new_process,
       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;
 
     // Notify the instance that it is registered to the devtools manager.
     instance_->OnRegisteredToDevToolsManager(
         is_new_process, std::move(devtools_proxy), wait_for_debugger);
 
     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();
       instance_->OnStartFailed(callback, status);
       // |this| may be destroyed.
     }
   }
 
   // |instance_| must outlive |this|.
   EmbeddedWorkerInstance* instance_;
@@ skipping 180 matching lines @@
     return SERVICE_WORKER_ERROR_ABORT;
 
   DCHECK(!instance_host_binding_.is_bound());
   mojom::EmbeddedWorkerInstanceHostAssociatedPtrInfo host_ptr_info;
   instance_host_binding_.Bind(&host_ptr_info);
 
   DCHECK(pending_dispatcher_request_.is_pending());
   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;
 }
 
 void EmbeddedWorkerInstance::OnStartWorkerMessageSent() {
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
     if (inflight_start_task_->is_installed()) {
       ServiceWorkerMetrics::RecordTimeToSendStartWorker(duration,
                                                         start_situation_);
     }
   }
 
   starting_phase_ = SENT_START_WORKER;
   for (auto& observer : listener_list_)
     observer.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() {
   starting_phase_ = SCRIPT_READ_STARTED;
 }
 
 void EmbeddedWorkerInstance::OnScriptReadFinished() {
   starting_phase_ = SCRIPT_READ_FINISHED;
 }
 
 void EmbeddedWorkerInstance::OnScriptLoaded() {
   using LoadSource = ServiceWorkerMetrics::LoadSource;
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnScriptLoaded");
 
   if (!inflight_start_task_)
     return;
   LoadSource source;
   if (network_accessed_for_script_) {
     DCHECK(!inflight_start_task_->is_installed());
     source = LoadSource::NETWORK;
   } else if (inflight_start_task_->is_installed()) {
     source = LoadSource::SERVICE_WORKER_STORAGE;
   } 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();
     ServiceWorkerMetrics::RecordTimeToLoad(duration, source, start_situation_);
   }
 
   starting_phase_ = SCRIPT_LOADED;
   for (auto& observer : listener_list_)
     observer.OnScriptLoaded();
   // |this| may be destroyed by the callback.
 }
 
 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() {
   if (devtools_proxy_)
     devtools_proxy_->NotifyWorkerVersionInstalled();
 }
 
 void EmbeddedWorkerInstance::OnWorkerVersionDoomed() {
   if (devtools_proxy_)
     devtools_proxy_->NotifyWorkerVersionDoomed();
 }
 
 void EmbeddedWorkerInstance::OnThreadStarted(int thread_id, int provider_id) {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnThreadStarted");
+  if (!inflight_start_task_)
+    return;
   if (!context_)
     return;
 
   ServiceWorkerProviderHost* provider_host =
       context_->GetProviderHost(process_id(), provider_id);
   if (!provider_host) {
     bad_message::ReceivedBadMessage(
         process_id(), bad_message::SWDH_WORKER_SCRIPT_LOAD_NO_HOST);
     return;
   }
 
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "OnThreadStarted", this);
+
   provider_host->SetReadyToSendMessagesToWorker(thread_id);
 
-  if (!inflight_start_task_)
-    return;
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnThreadStarted");
-
   starting_phase_ = THREAD_STARTED;
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
     if (inflight_start_task_->is_installed())
       ServiceWorkerMetrics::RecordTimeToStartThread(duration, start_situation_);
   }
 
   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();
     if (success && inflight_start_task_->is_installed())
       ServiceWorkerMetrics::RecordTimeToEvaluateScript(duration,
                                                        start_situation_);
   }
 
   base::WeakPtr<EmbeddedWorkerInstance> weak_this = weak_factory_.GetWeakPtr();
   StartTask::RunStartCallback(
       inflight_start_task_.get(),
       success ? SERVICE_WORKER_OK
               : SERVICE_WORKER_ERROR_SCRIPT_EVALUATE_FAILED);
   // |this| may be destroyed by the callback.
 }
 
 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();
 }
 
 void EmbeddedWorkerInstance::OnStopped() {
   registry_->OnWorkerStopped(process_id(), embedded_worker_id_);
 
   EmbeddedWorkerStatus old_status = status_;
   ReleaseProcess();
@@ skipping 168 matching lines @@
     case SCRIPT_READ_FINISHED:
       return "Script read finished";
     case STARTING_PHASE_MAX_VALUE:
       NOTREACHED();
   }
   NOTREACHED() << phase;
   return std::string();
 }
 
 }  // namespace content