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 {

[mmenke, 2014/09/04 14:53:51]

Note:  This should either be inlined in the header, or not named http_info.  No
need to worry about it in this CL, but it does violate the style guide.

   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();
       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();
 }
 
 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();
   // 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/04 14:53:51]

Currently, either all of send_start/send_end/receive_headers_end are set, or
none of them are (Requests served out of the cache set them to time the were
requested from the cache).

Per spec at
https://dvcs.w3.org/hg/webperf/raw-file/tip/specs/NavigationTiming/Overview.html,
requestStart (i.e. send_start) "must return the time immediately before the user
agent starts requesting the current document from the server, or from relevant
application caches or from local resources.", which doesn't really give much
room for it to be null.

[shimazu, 2014/09/05 04:18:48]

Thanks, I didn't know the spec.
I set the send_start/send_end to load_timing_info.

   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