[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 222 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",

[leonhsl(Using Gerrit), 2017/04/19 03:43:43]

I think using StartTask ctor/dtor to control "EmbeddedWorkerInstance::Start"
events begin/end is simple and clear so I'm keeping this practice, otherwise we
need to put events end to several places indicating "Start" failed or succeeded.

[shimazu, 2017/04/19 07:54:35]

Thanks for explanation! It makes sense.

+                                      "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.
@@ skipping 52 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,
+      TRACE_EVENT_NESTABLE_ASYNC_INSTANT2(
+          "ServiceWorker", "EmbeddedWorkerInstance::Start", instance_, "Step",

[shimazu, 2017/04/19 07:54:35]

Each INSTANT can have different name as long as you set the same ID. Could you
use "OnProcessAllocated" instead of "EmbeddedWorkerInstance::Start" in this
line?

Additionally, I've now tested this patch and realized that
NESTABLE_ASYNC_INSTANT doesn't look good, sorry!
Could you use BEGIN/END for specifying the duration?

[leonhsl(Using Gerrit), 2017/04/19 10:40:23]

I'm not quite sure about this, instead of NESTABLE_ASYNC_INSTANT, we should do
as following?
TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(xxx, "OnProcessAllocated", xxx);
TRACE_EVENT_NESTABLE_ASYNC_END1(xxx, "OnProcessAllocated", xxx);

[shimazu, 2017/04/20 04:51:46]

Yes, exactly. According to the CL which introduces NESTABLE_ASYNC, we should
aware when each step finishes. 
https://crrev.com/039bf813

[leonhsl(Using Gerrit), 2017/04/21 02:46:29]

Done.

           "OnProcessAllocated", "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,
+    TRACE_EVENT_NESTABLE_ASYNC_INSTANT2(
+        "ServiceWorker", "EmbeddedWorkerInstance::Start", instance_, "Step",
         "OnProcessAllocated", "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;
@@ skipping 24 matching lines @@
                    base::Bind(&StartTask::OnSetupOnUICompleted,
                               weak_factory_.GetWeakPtr(), base::Passed(&params),
                               is_new_process)));
   }
 
   void OnSetupOnUICompleted(std::unique_ptr<EmbeddedWorkerStartParams> params,
                             bool is_new_process,
                             int worker_devtools_agent_route_id,
                             bool wait_for_debugger) {
     DCHECK_CURRENTLY_ON(BrowserThread::IO);
-    TRACE_EVENT_ASYNC_STEP_PAST0("ServiceWorker",
-                                 "EmbeddedWorkerInstance::Start", this,
-                                 "OnSetupOnUICompleted");
+    TRACE_EVENT_NESTABLE_ASYNC_INSTANT1(
+        "ServiceWorker", "EmbeddedWorkerInstance::Start", instance_, "Step",
+        "OnSetupOnUICompleted");
 
     // Notify the instance that it is registered to the devtools manager.
     instance_->OnRegisteredToDevToolsManager(
         is_new_process, worker_devtools_agent_route_id, wait_for_debugger);
 
     params->worker_devtools_agent_route_id = worker_devtools_agent_route_id;
     params->wait_for_debugger = wait_for_debugger;
 
     ServiceWorkerStatusCode status =
         instance_->SendStartWorker(std::move(params));
@@ skipping 191 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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "SendStartWorker");
   OnStartWorkerMessageSent();
   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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "OnReadyForInspection");
   if (devtools_proxy_)
     devtools_proxy_->NotifyWorkerReadyForInspection();
 }
 
 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_INSTANT2(
+      "ServiceWorker", "EmbeddedWorkerInstance::Start", this, "Step",
+      "OnScriptLoaded", "Source",
       ServiceWorkerMetrics::LoadSourceToString(source));
 
   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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "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;
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "OnThreadStarted");
+
   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;
   }
 
   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();
 }
 
 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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "OnScriptLoadFailed");
+
   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_INSTANT2(
+      "ServiceWorker", "EmbeddedWorkerInstance::Start", this, "Step",
+      "OnScriptEvaluated", "Success", success);
+
   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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "OnStarted");
+
   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 170 matching lines @@
     case SCRIPT_READ_FINISHED:
       return "Script read finished";
     case STARTING_PHASE_MAX_VALUE:
       NOTREACHED();
   }
   NOTREACHED() << phase;
   return std::string();
 }
 
 }  // namespace content