Add ServiceWorker timing information on the popup panel in DevTools's Network tab (2/2)

content/browser/service_worker/service_worker_url_request_job.cc

 // Copyright 2014 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_url_request_job.h"
 
 #include <map>
 #include <string>
 #include <vector>
 
 #include "base/bind.h"
 #include "base/guid.h"
 #include "base/strings/stringprintf.h"
+#include "base/time/time.h"
 #include "content/browser/service_worker/service_worker_fetch_dispatcher.h"
 #include "content/browser/service_worker/service_worker_provider_host.h"
 #include "content/common/resource_request_body.h"
 #include "content/common/service_worker/service_worker_types.h"
 #include "content/public/browser/blob_handle.h"
 #include "content/public/browser/resource_request_info.h"
 #include "content/public/common/page_transition_types.h"
 #include "net/http/http_request_headers.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_response_info.h"
@@ skipping 57 matching lines @@
 bool ServiceWorkerURLRequestJob::GetMimeType(std::string* mime_type) const {
   if (!http_info())
     return false;
   return http_info()->headers->GetMimeType(mime_type);
 }
 
 void ServiceWorkerURLRequestJob::GetResponseInfo(net::HttpResponseInfo* info) {
   if (!http_info())
     return;
   *info = *http_info();
+  info->response_time = response_time_;
+}
+
+void ServiceWorkerURLRequestJob::GetLoadTimingInfo(
+    net::LoadTimingInfo* load_timing_info) const {
+  *load_timing_info = load_timing_info_;
 }
 
 int ServiceWorkerURLRequestJob::GetResponseCode() const {
   if (!http_info())
     return -1;
   return http_info()->headers->response_code();
 }
 
 void ServiceWorkerURLRequestJob::SetExtraRequestHeaders(
     const net::HttpRequestHeaders& headers) {
@@ skipping 51 matching lines @@
 }
 
 void ServiceWorkerURLRequestJob::OnBeforeNetworkStart(net::URLRequest* request,
                                                       bool* defer) {
   NOTREACHED();
 }
 
 void ServiceWorkerURLRequestJob::OnResponseStarted(net::URLRequest* request) {
   // TODO(falken): Add Content-Length, Content-Type if they were not provided in
   // the ServiceWorkerResponse.
+  response_time_ = base::Time::Now();
   CommitResponseHeader();
 }
 
 void ServiceWorkerURLRequestJob::OnReadCompleted(net::URLRequest* request,
                                                  int bytes_read) {
   SetStatus(request->status());
   if (!request->status().is_success()) {
     NotifyDone(request->status());
     return;
   }
   NotifyReadComplete(bytes_read);
   if (bytes_read == 0)
     NotifyDone(request->status());
 }
 
 const net::HttpResponseInfo* ServiceWorkerURLRequestJob::http_info() const {
   if (!http_response_info_)
     return NULL;
   if (range_response_info_)
     return range_response_info_.get();
   return http_response_info_.get();
 }
 
 void ServiceWorkerURLRequestJob::GetExtraResponseInfo(
     bool* was_fetched_via_service_worker,
-    GURL* original_url_via_service_worker) const {
+    GURL* original_url_via_service_worker,
+    base::TimeTicks* fetch_start_time,
+    base::TimeTicks* fetch_ready_time,
+    base::TimeTicks* fetch_end_time) const {
   if (response_type_ != FORWARD_TO_SERVICE_WORKER) {
     *was_fetched_via_service_worker = false;
     *original_url_via_service_worker = GURL();
     return;
   }
   *was_fetched_via_service_worker = true;
   *original_url_via_service_worker = response_url_;
+  *fetch_start_time = fetch_start_time_;
+  *fetch_ready_time = fetch_ready_time_;
+  *fetch_end_time = fetch_end_time_;
 }
 
 
 ServiceWorkerURLRequestJob::~ServiceWorkerURLRequestJob() {
 }
 
 void ServiceWorkerURLRequestJob::MaybeStartRequest() {
   if (is_started_ && response_type_ != NOT_DETERMINED) {
     // Start asynchronously.
     base::MessageLoop::current()->PostTask(
@@ skipping 21 matching lines @@
       DCHECK(!fetch_dispatcher_);
       // Send a fetch event to the ServiceWorker associated to the
       // provider_host.
       fetch_dispatcher_.reset(new ServiceWorkerFetchDispatcher(
           CreateFetchRequest(),
           provider_host_->active_version(),
           base::Bind(&ServiceWorkerURLRequestJob::DidPrepareFetchEvent,
                      weak_factory_.GetWeakPtr()),
           base::Bind(&ServiceWorkerURLRequestJob::DidDispatchFetchEvent,
                      weak_factory_.GetWeakPtr())));
+      fetch_start_time_ = base::TimeTicks::Now();
+      load_timing_info_.send_start = fetch_start_time_;
       fetch_dispatcher_->Run();
       return;
   }
 
   NOTREACHED();
 }
 
 scoped_ptr<ServiceWorkerFetchRequest>
 ServiceWorkerURLRequestJob::CreateFetchRequest() {
   std::string blob_uuid;
@@ skipping 76 matching lines @@
   }
 
   request_body_blob_data_handle_ =
       blob_storage_context_->AddFinishedBlob(blob_data.get());
   *blob_uuid = uuid;
   *blob_size = total_size;
   return true;
 }
 
 void ServiceWorkerURLRequestJob::DidPrepareFetchEvent() {
-  // TODO(shimazu): Set the timestamp to measure the time to launch SW
-  // This is related to this (http://crbug.com/401389)
+  fetch_ready_time_ = base::TimeTicks::Now();

[michaeln, 2014/09/05 21:23:52]

lgtm 2 

fetch_ready_time might be more analogous to send_end than fetch_end_time?

 }
 
 void ServiceWorkerURLRequestJob::DidDispatchFetchEvent(
     ServiceWorkerStatusCode status,
     ServiceWorkerFetchEventResult fetch_result,
     const ServiceWorkerResponse& response) {
   fetch_dispatcher_.reset();
 
   // Check if we're not orphaned.
   if (!request())
@@ skipping 13 matching lines @@
   if (fetch_result == SERVICE_WORKER_FETCH_EVENT_RESULT_FALLBACK) {
     // Change the response type and restart the request to fallback to
     // the network.
     response_type_ = FALLBACK_TO_NETWORK;
     NotifyRestartRequired();
     return;
   }
 
   // We should have a response now.
   DCHECK_EQ(SERVICE_WORKER_FETCH_EVENT_RESULT_RESPONSE, fetch_result);
-
+  fetch_end_time_ = base::TimeTicks::Now();
+  load_timing_info_.send_end = fetch_end_time_;

[mmenke, 2014/09/05 14:22:34]

Will fetch_end_time_ always be send_end, or might they be different in the
future?

Just wondering if we need both - if you'll be using load timing information from
the network stack, in the case that requests actually go over the network, then
they'll definitely be different in that case, and we should have both.  If the
long term plan is to always do what you're doing now, then they're redundant. 
Same goes for the start times.

   // Set up a request for reading the blob.
   if (!response.blob_uuid.empty() && blob_storage_context_) {
     scoped_ptr<storage::BlobDataHandle> blob_data_handle =
         blob_storage_context_->GetBlobDataFromUUID(response.blob_uuid);
     if (!blob_data_handle) {
       // The renderer gave us a bad blob UUID.
       DeliverErrorResponse();
       return;
     }
     blob_request_ = storage::BlobProtocolHandler::CreateBlobRequest(
         blob_data_handle.Pass(), request()->context(), this);
     blob_request_->Start();
   }
 
   response_url_ = response.url;
   CreateResponseHeader(
       response.status_code, response.status_text, response.headers);
+  load_timing_info_.receive_headers_end = base::TimeTicks::Now();

[mmenke, 2014/09/05 14:22:34]

Not exactly a huge cost in terms of performance or binary size, but I don't
think we really need another call to TimeTicks::Now() here, unless we're on a
file thread and CreateBlobRequest blocks on file I/O or something.

   if (!blob_request_)
     CommitResponseHeader();
 }
 
 void ServiceWorkerURLRequestJob::CreateResponseHeader(
     int status_code,
     const std::string& status_text,
     const std::map<std::string, std::string>& headers) {
   // TODO(kinuko): If the response has an identifier to on-disk cache entry,
   // pull response header from the disk.
@@ skipping 22 matching lines @@
 void ServiceWorkerURLRequestJob::DeliverErrorResponse() {
   // TODO(falken): Print an error to the console of the ServiceWorker and of
   // the requesting page.
   CreateResponseHeader(500,
                        "Service Worker Response Error",
                        std::map<std::string, std::string>());
   CommitResponseHeader();
 }
 
 }  // namespace content