ServiceWorker: Move TRACE_EVENT to avoid early return and mismatching

content/browser/service_worker/service_worker_storage.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/service_worker_storage.h"
 
 #include <string>
 
 #include "base/bind_helpers.h"
 #include "base/debug/trace_event.h"
@@ skipping 234 matching lines @@
                                context,
                                old_storage->database_task_runner_,
                                old_storage->disk_cache_thread_,
                                old_storage->quota_manager_proxy_.get()));
 }
 
 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))) {
     if (state_ != INITIALIZING || !context_) {
       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_);
 
   // See if there are any stored registrations for the origin.
   if (!ContainsKey(registered_origins_, document_url.GetOrigin())) {
     // Look for something currently being installed.
     scoped_refptr<ServiceWorkerRegistration> installing_registration =
         FindInstallingRegistrationForDocument(document_url);
     CompleteFindNow(installing_registration,
                     installing_registration.get()
                         ? 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(
           &FindForDocumentInDB,
           database_.get(),
           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(
     const GURL& scope,
     const FindRegistrationCallback& callback) {
   if (!LazyInitialize(base::Bind(
           &ServiceWorkerStorage::FindRegistrationForPattern,
           weak_factory_.GetWeakPtr(), scope, callback))) {
     if (state_ != INITIALIZING || !context_) {
       CompleteFindSoon(FROM_HERE, scoped_refptr<ServiceWorkerRegistration>(),
@@ skipping 459 matching lines @@
   for (std::vector<base::Closure>::const_iterator it = pending_tasks_.begin();
        it != pending_tasks_.end(); ++it) {
     RunSoon(FROM_HERE, *it);
   }
   pending_tasks_.clear();
 }
 
 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) {
   if (status == ServiceWorkerDatabase::STATUS_OK) {
     ReturnFoundRegistration(callback, data, resources);
     TRACE_EVENT_ASYNC_END1(
         "ServiceWorker",
         "ServiceWorkerStorage::FindRegistrationForDocument",
-        base::Hash(document_url.spec()),
+        callback_id,
         "Status", "OK");
     return;
   }
 
   if (status == ServiceWorkerDatabase::STATUS_ERROR_NOT_FOUND) {
     // Look for something currently being installed.
     scoped_refptr<ServiceWorkerRegistration> installing_registration =
         FindInstallingRegistrationForDocument(document_url);
     callback.Run(installing_registration.get() ? SERVICE_WORKER_OK
                                                : SERVICE_WORKER_ERROR_NOT_FOUND,
                  installing_registration);
     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;
   }
 
   ScheduleDeleteAndStartOver();
   callback.Run(DatabaseStatusToStatusCode(status),
                scoped_refptr<ServiceWorkerRegistration>());
   TRACE_EVENT_ASYNC_END1(
       "ServiceWorker",
       "ServiceWorkerStorage::FindRegistrationForDocument",
-      base::Hash(document_url.spec()),
+      callback_id,
       "Status", status);
 }
 
 void ServiceWorkerStorage::DidFindRegistrationForPattern(
     const GURL& scope,
     const FindRegistrationCallback& callback,
     const ServiceWorkerDatabase::RegistrationData& data,
     const ResourceList& resources,
     ServiceWorkerDatabase::Status status) {
   if (status == ServiceWorkerDatabase::STATUS_OK) {
@@ skipping 603 matching lines @@
     // Give up the corruption recovery until the browser restarts.
     LOG(ERROR) << "Failed to delete the diskcache.";
     callback.Run(SERVICE_WORKER_ERROR_FAILED);
     return;
   }
   DVLOG(1) << "Deleted ServiceWorkerDiskCache successfully.";
   callback.Run(SERVICE_WORKER_OK);
 }
 
 }  // namespace content