[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 93aaf34f42abaaa282680702e999b9091afaefdf..2eda94ee26b411f615938659ff066988fd59a0a2 100644
--- a/content/browser/service_worker/embedded_worker_instance.cc
+++ b/content/browser/service_worker/embedded_worker_instance.cc
@@ -240,14 +240,15 @@ 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",

[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;
@@ -320,8 +321,8 @@ class EmbeddedWorkerInstance::StartTask {
     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_;
@@ -331,8 +332,8 @@ class EmbeddedWorkerInstance::StartTask {
       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);
@@ -377,9 +378,9 @@ class EmbeddedWorkerInstance::StartTask {
                             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(
@@ -591,8 +592,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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "SendStartWorker");
   OnStartWorkerMessageSent();
   return SERVICE_WORKER_OK;
 }
@@ -612,7 +614,9 @@ void EmbeddedWorkerInstance::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();
 }
@@ -628,8 +632,6 @@ void EmbeddedWorkerInstance::OnScriptReadFinished() {
 void EmbeddedWorkerInstance::OnScriptLoaded() {
   using LoadSource = ServiceWorkerMetrics::LoadSource;
 
-  TRACE_EVENT0("ServiceWorker", "EmbeddedWorkerInstance::OnScriptLoaded");
-
   if (!inflight_start_task_)
     return;
   LoadSource source;
@@ -641,9 +643,9 @@ 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_INSTANT2(
+      "ServiceWorker", "EmbeddedWorkerInstance::Start", this, "Step",
+      "OnScriptLoaded", "Source",
       ServiceWorkerMetrics::LoadSourceToString(source));
 
   if (!step_time_.is_null()) {
@@ -660,8 +662,10 @@ 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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "OnURLJobCreated");
+
   if (!step_time_.is_null()) {
     base::TimeDelta duration = UpdateStepTime();
     if (inflight_start_task_->is_installed())
@@ -680,7 +684,12 @@ void EmbeddedWorkerInstance::OnWorkerVersionDoomed() {
 }
 
 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;
 
@@ -694,11 +703,6 @@ void EmbeddedWorkerInstance::OnThreadStarted(int thread_id, int provider_id) {
 
   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();
@@ -712,25 +716,25 @@ void EmbeddedWorkerInstance::OnThreadStarted(int thread_id, int provider_id) {
 }
 
 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();
@@ -748,12 +752,15 @@ 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_INSTANT1("ServiceWorker",
+                                      "EmbeddedWorkerInstance::Start", this,
+                                      "Step", "OnStarted");
+
   DCHECK(status_ == EmbeddedWorkerStatus::STARTING);
   status_ = EmbeddedWorkerStatus::RUNNING;
   inflight_start_task_.reset();