[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 21 matching lines @@
     state_ = ProcessAllocationState::ALLOCATING;
     start_callback_ = callback;
     is_installed_ = params->is_installed;
 
     if (!GetContentClient()->browser()->IsBrowserStartupComplete())
       started_during_browser_startup_ = true;
 
     GURL scope(params->scope);
     GURL script_url(params->script_url);
 
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "ALLOCATING_PROCESS",
+                                      instance_);
     bool can_use_existing_process =
         instance_->context_->GetVersionFailureCount(
             params->service_worker_version_id) < kMaxSameProcessFailureCount;
     instance_->context_->process_manager()->AllocateWorkerProcess(
         instance_->embedded_worker_id_, scope, script_url,
         can_use_existing_process,
         base::Bind(&StartTask::OnProcessAllocated, weak_factory_.GetWeakPtr(),
                    base::Passed(&params)));
   }
 
@@ skipping 10 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_END1("ServiceWorker", "ALLOCATING_PROCESS",
+                                      instance_, "Error",
+                                      ServiceWorkerStatusToString(status));
       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_END1("ServiceWorker", "ALLOCATING_PROCESS",
+                                    instance_, "Is New Process",
+                                    is_new_process);
     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
       start_situation = ServiceWorkerMetrics::StartSituation::EXISTING_PROCESS;
 
     // Notify the instance that a process is allocated.
     state_ = ProcessAllocationState::ALLOCATED;
     instance_->OnProcessAllocated(
         base::MakeUnique<WorkerProcessHandle>(instance_->context_,
                                               instance_->embedded_worker_id(),
                                               process_id, is_new_process),
         start_situation);
 
     // TODO(bengr): Support changes to this setting while the worker
     // is running.
     params->settings.data_saver_enabled = settings.data_saver_enabled;
 
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker",
+                                      "REGISTERING_TO_DEVTOOLS", instance_);
     // Register the instance to DevToolsManager on UI thread.
     const int64_t service_worker_version_id = params->service_worker_version_id;
     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)));
   }
 
   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");
-
     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);
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "REGISTERING_TO_DEVTOOLS",
+                                    instance_);
 
     ServiceWorkerStatusCode status =
         instance_->SendStartWorker(std::move(params));
     if (status != SERVICE_WORKER_OK) {
       StatusCallback callback = start_callback_;
       start_callback_.Reset();
       instance_->OnStartFailed(callback, status);
       // |this| may be destroyed.
     }
   }
@@ skipping 183 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");
   OnStartWorkerMessageSent();
+  // Once the start worker message is recieved, renderer side will prepare a
+  // shadow page for getting worker script.
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "PREPARING_SCRIPT_LOAD",
+                                    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");
   if (devtools_proxy_)
     devtools_proxy_->NotifyWorkerReadyForInspection();
 }
 
 void EmbeddedWorkerInstance::OnScriptReadStarted() {
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "SCRIPT_READING_CACHE",
+                                    this);
   starting_phase_ = SCRIPT_READ_STARTED;
 }
 
 void EmbeddedWorkerInstance::OnScriptReadFinished() {
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "SCRIPT_READING_CACHE",
+                                  this);
   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",
+  // starting_phase_ may be SCRIPT_READ_FINISHED in case of reading from cache.

[shimazu, 2017/04/25 01:34:50]

nit: an extra space

[leonhsl(Using Gerrit), 2017/04/25 02:34:06]

Done.

+  if (starting_phase_ == SCRIPT_DOWNLOADING) {
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "SCRIPT_DOWNLOADING",
+                                    this);
+  }
+  TRACE_EVENT_NESTABLE_ASYNC_END1(
+      "ServiceWorker", "SCRIPT_LOADING", this, "Source",
       ServiceWorkerMetrics::LoadSourceToString(source));
 
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
     ServiceWorkerMetrics::RecordTimeToLoad(duration, source, start_situation_);
   }
 
+  // Renderer side has started to launch the worker thread.
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "LAUNCHING_WORKER_THREAD",
+                                    this);
   starting_phase_ = SCRIPT_LOADED;
   for (auto& observer : listener_list_)
     observer.OnScriptLoaded();
   // |this| may be destroyed by the callback.
 }
 
 void EmbeddedWorkerInstance::OnURLJobCreatedForMainScript() {

[leonhsl(Using Gerrit), 2017/04/24 08:23:58]

I found that this function is always called when trying to get a worker script,
then either OnNetworkAccessedForScriptLoad() or OnScriptReadStarted() will be
called, the former means downloading the script via network and the latter means
reading from cache.

[shimazu, 2017/04/25 01:34:50]

Yeah, looks good.

+  // Indicates that the shadow page has been created in renderer side and starts
+  // to get the worker script.
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "PREPARING_SCRIPT_LOAD",
+                                  this);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "SCRIPT_LOADING", this);
   if (!inflight_start_task_)
     return;
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnURLJobCreated");
+
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
     if (inflight_start_task_->is_installed())
       ServiceWorkerMetrics::RecordTimeToURLJob(duration, start_situation_);
   }
 }
 
 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_)

[shimazu, 2017/04/25 01:34:50]

It's not necessary to separate these two if clauses. 

if (!context_ || !inflight_start_task) 
  return;

[leonhsl(Using Gerrit), 2017/04/25 02:34:06]

Done.

     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;
   }
 
   provider_host->SetReadyToSendMessagesToWorker(thread_id);
 
-  if (!inflight_start_task_)
-    return;
-  TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnThreadStarted");
-
+  TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "LAUNCHING_WORKER_THREAD",
+                                  this);
+  // Renderer side has started to evaluate the loaded worker script.
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "EVALUATING_SCRIPT", this);
   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();
 }
 
 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");
+
+  // starting_phase_ may be SCRIPT_READ_FINISHED in case of reading from cache.
+  if (starting_phase_ == SCRIPT_DOWNLOADING) {
+    TRACE_EVENT_NESTABLE_ASYNC_END0("ServiceWorker", "SCRIPT_DOWNLOADING",
+                                    this);
+  }
+  TRACE_EVENT_NESTABLE_ASYNC_END1("ServiceWorker", "SCRIPT_LOADING", this,
+                                  "Error", "Script load failed.");
+
   for (auto& observer : listener_list_)
     observer.OnScriptLoadFailed();
 }
 
 void EmbeddedWorkerInstance::OnScriptEvaluated(bool success) {
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnScriptEvaluated");
   if (!inflight_start_task_)
     return;
+
   DCHECK_EQ(EmbeddedWorkerStatus::STARTING, status_);
 
-  TRACE_EVENT_ASYNC_STEP_PAST1("ServiceWorker", "EmbeddedWorkerInstance::Start",
-                               inflight_start_task_.get(), "OnScriptEvaluated",
-                               "Success", success);
+  // Renderer side has completed evaluating the loaded worker script.
+  TRACE_EVENT_NESTABLE_ASYNC_END1("ServiceWorker", "EVALUATING_SCRIPT", this,
+                                  "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_);
   }
 
+  if (success) {
+    // Renderer side has started the final preparations to complete the start
+    // process.
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker",
+                                      "WAITING_FOR_START_COMPLETE", this);
+  }
   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_END0("ServiceWorker", "WAITING_FOR_START_COMPLETE",
+                                  this);
   DCHECK(status_ == EmbeddedWorkerStatus::STARTING);
   status_ = EmbeddedWorkerStatus::RUNNING;
   inflight_start_task_.reset();
   for (auto& observer : listener_list_)
     observer.OnStarted();
 }
 
 void EmbeddedWorkerInstance::OnStopped() {
   registry_->OnWorkerStopped(process_id(), embedded_worker_id_);
 
@@ skipping 75 matching lines @@
   listener_list_.RemoveObserver(listener);
 }
 
 void EmbeddedWorkerInstance::SetDevToolsAttached(bool attached) {
   devtools_attached_ = attached;
   if (attached)
     registry_->OnDevToolsAttached(embedded_worker_id_);
 }
 
 void EmbeddedWorkerInstance::OnNetworkAccessedForScriptLoad() {
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("ServiceWorker", "SCRIPT_DOWNLOADING",
+                                    this);
   starting_phase_ = SCRIPT_DOWNLOADING;
   network_accessed_for_script_ = true;
 }
 
 void EmbeddedWorkerInstance::ReleaseProcess() {
   // Abort an inflight start task.
   inflight_start_task_.reset();
 
   client_.reset();
   instance_host_binding_.Close();
@@ skipping 75 matching lines @@
     case SCRIPT_READ_FINISHED:
       return "Script read finished";
     case STARTING_PHASE_MAX_VALUE:
       NOTREACHED();
   }
   NOTREACHED() << phase;
   return std::string();
 }
 
 }  // namespace content