ServiceWorker: Move TRACE_EVENT to avoid early return and mismatching

content/browser/service_worker/service_worker_storage.cc

Index: content/browser/service_worker/service_worker_storage.cc
diff --git a/content/browser/service_worker/service_worker_storage.cc b/content/browser/service_worker/service_worker_storage.cc
index 54eacd657f51bf4593d953a1f8bdf61a97cf6656..fa2ebe4cd277c5fb25efd7c829ab30418a4e50ed 100644
--- a/content/browser/service_worker/service_worker_storage.cc
+++ b/content/browser/service_worker/service_worker_storage.cc
@@ -252,11 +252,6 @@ void ServiceWorkerStorage::FindRegistrationForDocument(
     const GURL& document_url,
     const FindRegistrationCallback& callback) {
   DCHECK(!document_url.has_ref());
-  TRACE_EVENT_ASYNC_BEGIN1(
-      "ServiceWorker",
-      "ServiceWorkerStorage::FindRegistrationForDocument",
-      base::Hash(document_url.spec()),
-      "URL", document_url.spec());
   if (!LazyInitialize(base::Bind(
           &ServiceWorkerStorage::FindRegistrationForDocument,
           weak_factory_.GetWeakPtr(), document_url, callback))) {
@@ -264,6 +259,10 @@ void ServiceWorkerStorage::FindRegistrationForDocument(
       CompleteFindNow(scoped_refptr<ServiceWorkerRegistration>(),
                       SERVICE_WORKER_ERROR_FAILED, callback);
     }
+    TRACE_EVENT1(
+        "ServiceWorker",
+        "ServiceWorkerStorage::FindRegistrationForDocument:LazyInitialize",
+        "URL", document_url.spec());

[nhiroki, 2014/10/14 02:03:26]

Why don't you add TRACE_EVENT_ASYNC_XXX in LazyInitialize() instead? (I think
you don't have to add it in this CL though)

[shimazu, 2014/10/14 04:10:47]

I think LazyInitialize have to be tracked in order to clarify the start point of
this procedure. But if ASYNC_BEGIN was put in here instead, where to insert
ASYNC_END seems a little problem, so I put TRACE_EVENT here.
What do you think?

[nhiroki, 2014/10/14 05:01:13]

I see. If you'd like to track it, how about doing like this?

void SWS::FindRegistrationForDocument(...) {
  TRACE_EVENT_ASYNC_BEGIN(...);
  if (!LazyInitialize()) {
    if (state_ != INITIALIZING || !context_) {
      TRACE_EVENT_ASYNC_END(..., "Status", "FAILED");    
    } else {
      TRACE_EVENT_ASYNC_END(..., "Status", "LazyInitialize");
    }
    return;
  }

  if (!ContainsKey(...)) {
    TRACE_EVENT_ASYNC_END(..., "Status", installing_registration.get() ? "OK" :
"NOT_FOUND");
  }

  database_task_runner_->PostTask(...);
}

[nhiroki, 2014/10/14 06:09:50]

Or, if you'd like to record it as a single event (which does not have a
begin-end range), you might be able to use TRACE_EVENT_INSTANT.

[shimazu, 2014/10/14 09:07:02]

Done.

     return;
   }
   DCHECK_EQ(INITIALIZED, state_);
@@ -278,9 +277,21 @@ void ServiceWorkerStorage::FindRegistrationForDocument(
                         ? SERVICE_WORKER_OK
                         : SERVICE_WORKER_ERROR_NOT_FOUND,
                     callback);
+    TRACE_EVENT1(
+        "ServiceWorker",
+        "ServiceWorkerStorage::FindRegistrationForDocument:NotContainsKey",

[nhiroki, 2014/10/14 02:03:26]

nit: s/Contains/Contain

I think this wouldn't help to measure performance because synchronous
TRACE_EVENT works for the current scope and we'll immediately return at the next
line. Wdyt?

[shimazu, 2014/10/14 04:10:47]

I think there is no meaning in terms of performance, too, but I insert this in
order to track calls of FindRegistrationForDocument.

[nhiroki, 2014/10/14 05:01:13]

Please see the previous comment.

[shimazu, 2014/10/14 09:07:02]

Done.

+        "URL", document_url.spec());
     return;
   }
 
+  // To connect this TRACE_EVENT with the callback, TimeTicks is used for
+  // callback id.
+  int callback_id = base::TimeTicks::Now().ToInternalValue();

[nhiroki, 2014/10/14 02:03:26]

|callback_id| should be int64 because ToInternalValue() returns int64 value.

[shimazu, 2014/10/14 04:10:47]

Done.

+  TRACE_EVENT_ASYNC_BEGIN1(
+      "ServiceWorker",
+      "ServiceWorkerStorage::FindRegistrationForDocument",
+      callback_id,
+      "URL", document_url.spec());
   database_task_runner_->PostTask(
       FROM_HERE,
       base::Bind(
@@ -289,7 +300,10 @@ void ServiceWorkerStorage::FindRegistrationForDocument(
           base::MessageLoopProxy::current(),
           document_url,
           base::Bind(&ServiceWorkerStorage::DidFindRegistrationForDocument,
-                     weak_factory_.GetWeakPtr(), document_url, callback)));
+                     weak_factory_.GetWeakPtr(),
+                     document_url,
+                     callback,
+                     callback_id)));
 }
 
 void ServiceWorkerStorage::FindRegistrationForPattern(
@@ -769,6 +783,7 @@ void ServiceWorkerStorage::DidReadInitialData(
 void ServiceWorkerStorage::DidFindRegistrationForDocument(
     const GURL& document_url,
     const FindRegistrationCallback& callback,
+    int callback_id,

[nhiroki, 2014/10/14 02:03:26]

ditto.

[shimazu, 2014/10/14 04:10:47]

Done.

     const ServiceWorkerDatabase::RegistrationData& data,
     const ResourceList& resources,
     ServiceWorkerDatabase::Status status) {
@@ -777,7 +792,7 @@ void ServiceWorkerStorage::DidFindRegistrationForDocument(
     TRACE_EVENT_ASYNC_END1(
         "ServiceWorker",
         "ServiceWorkerStorage::FindRegistrationForDocument",
-        base::Hash(document_url.spec()),
+        callback_id,
         "Status", "OK");
     return;
   }
@@ -792,7 +807,7 @@ void ServiceWorkerStorage::DidFindRegistrationForDocument(
     TRACE_EVENT_ASYNC_END1(
         "ServiceWorker",
         "ServiceWorkerStorage::FindRegistrationForDocument",
-        base::Hash(document_url.spec()),
+        callback_id,
         "Status", status);

[nhiroki, 2014/10/14 05:01:13]

(Not related to this CL, but we are here...)

1.) This seems to show "Status: NOT_FOUND" if |installing_registration.get()|
returns a valid registration.

2.) How about adding stringify function for ServiceWorkerDatabase::Status?
|status| will be printed as a number and we couldn't quickly understand what the
status means.

[shimazu, 2014/10/14 09:07:02]

I'll create a different patch about this.

     return;
   }
@@ -803,7 +818,7 @@ void ServiceWorkerStorage::DidFindRegistrationForDocument(
   TRACE_EVENT_ASYNC_END1(
       "ServiceWorker",
       "ServiceWorkerStorage::FindRegistrationForDocument",
-      base::Hash(document_url.spec()),
+      callback_id,
       "Status", status);
 }