Implement timing metrics for UrlRequest

components/cronet/android/cronet_url_request_adapter.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 "components/cronet/android/cronet_url_request_adapter.h"
 
 #include <limits>
 #include <utility>
 #include <vector>
 
@@ skipping 15 matching lines @@
 #include "net/quic/core/quic_protocol.h"
 #include "net/ssl/ssl_info.h"
 #include "net/url_request/redirect_info.h"
 #include "net/url_request/url_request_context.h"
 
 using base::android::ConvertUTF8ToJavaString;
 using base::android::JavaParamRef;
 
 namespace cronet {
 
+namespace {
+
+// Converts timing metrics stored as TimeTicks into the format expected by the
+// Java layer: ms since Unix epoch, or -1 for null
+int64_t ConvertTime(const base::TimeTicks& ticks,
+                    const base::TimeTicks& start_ticks,
+                    const base::Time& start_time) {
+  if (ticks.is_null() || start_ticks.is_null()) {
+    return -1;
+  }
+  DCHECK(!start_time.is_null());
+  return (start_time + (ticks - start_ticks)).ToJavaTime();
+}
+
+}  // namespace
+
 // Explicitly register static JNI functions.
 bool CronetUrlRequestAdapterRegisterJni(JNIEnv* env) {
   return RegisterNativesImpl(env);
 }
 
 static jlong CreateRequestAdapter(JNIEnv* env,
                                   const JavaParamRef<jobject>& jurl_request,
                                   jlong jurl_request_context_adapter,
                                   const JavaParamRef<jstring>& jurl_string,
                                   jint jpriority,
                                   jboolean jdisable_cache,
-                                  jboolean jdisable_connection_migration) {
+                                  jboolean jdisable_connection_migration,
+                                  jboolean jenable_metrics) {
   CronetURLRequestContextAdapter* context_adapter =
       reinterpret_cast<CronetURLRequestContextAdapter*>(
           jurl_request_context_adapter);
   DCHECK(context_adapter);
 
   GURL url(base::android::ConvertJavaStringToUTF8(env, jurl_string));
 
   VLOG(1) << "New chromium network request_adapter: "
           << url.possibly_invalid_spec();
 
   CronetURLRequestAdapter* adapter = new CronetURLRequestAdapter(
       context_adapter, env, jurl_request, url,
       static_cast<net::RequestPriority>(jpriority), jdisable_cache,
-      jdisable_connection_migration);
+      jdisable_connection_migration, jenable_metrics);
 
   return reinterpret_cast<jlong>(adapter);
 }
 
 CronetURLRequestAdapter::CronetURLRequestAdapter(
     CronetURLRequestContextAdapter* context,
     JNIEnv* env,
     jobject jurl_request,
     const GURL& url,
     net::RequestPriority priority,
     jboolean jdisable_cache,
-    jboolean jdisable_connection_migration)
+    jboolean jdisable_connection_migration,
+    jboolean jenable_metrics)
     : context_(context),
       initial_url_(url),
       initial_priority_(priority),
       initial_method_("GET"),
-      load_flags_(context->default_load_flags()) {
+      load_flags_(context->default_load_flags()),
+      enable_metrics_(jenable_metrics == JNI_TRUE) {
   DCHECK(!context_->IsOnNetworkThread());
   owner_.Reset(env, jurl_request);
   if (jdisable_cache == JNI_TRUE)
     load_flags_ |= net::LOAD_DISABLE_CACHE;
   if (jdisable_connection_migration == JNI_TRUE)
     load_flags_ |= net::LOAD_DISABLE_CONNECTION_MIGRATION;
 }
 
 CronetURLRequestAdapter::~CronetURLRequestAdapter() {
   DCHECK(context_->IsOnNetworkThread());
@@ skipping 134 matching lines @@
   request->ContinueWithCertificate(nullptr, nullptr);
 }
 
 void CronetURLRequestAdapter::OnSSLCertificateError(
     net::URLRequest* request,
     const net::SSLInfo& ssl_info,
     bool fatal) {
   DCHECK(context_->IsOnNetworkThread());
   request->Cancel();
   int net_error = net::MapCertStatusToNetError(ssl_info.cert_status);
+  end_time_ = base::TimeTicks::Now();
   JNIEnv* env = base::android::AttachCurrentThread();
   cronet::Java_CronetUrlRequest_onError(
       env, owner_.obj(), NetErrorToUrlRequestError(net_error), net_error,
       net::QUIC_NO_ERROR,
       ConvertUTF8ToJavaString(env, net::ErrorToString(net_error)).obj(),
       request->GetTotalReceivedBytes());
 }
 
 void CronetURLRequestAdapter::OnResponseStarted(net::URLRequest* request,
                                                 int net_error) {
@@ skipping 22 matching lines @@
 void CronetURLRequestAdapter::OnReadCompleted(net::URLRequest* request,
                                               int bytes_read) {
   DCHECK(context_->IsOnNetworkThread());
 
   if (bytes_read < 0) {
     ReportError(request, bytes_read);
     return;
   }
 
   if (bytes_read == 0) {
+    end_time_ = base::TimeTicks::Now();
     JNIEnv* env = base::android::AttachCurrentThread();
     cronet::Java_CronetUrlRequest_onSucceeded(
         env, owner_.obj(), url_request_->GetTotalReceivedBytes());
   } else {
     JNIEnv* env = base::android::AttachCurrentThread();
     cronet::Java_CronetUrlRequest_onReadCompleted(
         env, owner_.obj(), read_buffer_->byte_buffer(), bytes_read,
         read_buffer_->initial_position(), read_buffer_->initial_limit(),
         request->GetTotalReceivedBytes());
     // Free the read buffer. This lets the Java ByteBuffer be freed, if the
@@ skipping 70 matching lines @@
   int result = url_request_->Read(read_buffer_.get(), buffer_size);
   // If IO is pending, wait for the URLRequest to call OnReadCompleted.
   if (result == net::ERR_IO_PENDING)
     return;
 
   OnReadCompleted(url_request_.get(), result);
 }
 
 void CronetURLRequestAdapter::DestroyOnNetworkThread(bool send_on_canceled) {
   DCHECK(context_->IsOnNetworkThread());
+  JNIEnv* env = base::android::AttachCurrentThread();
   if (send_on_canceled) {
-    JNIEnv* env = base::android::AttachCurrentThread();
+    end_time_ = base::TimeTicks::Now();
     cronet::Java_CronetUrlRequest_onCanceled(env, owner_.obj());
   }
+  MaybeReportMetrics(env);
   delete this;
 }
 
 void CronetURLRequestAdapter::ReportError(net::URLRequest* request,
-                                          int net_error) const {
+                                          int net_error) {
   DCHECK_NE(net::ERR_IO_PENDING, net_error);
   DCHECK_LT(net_error, 0);
   DCHECK_EQ(request, url_request_.get());
 
   net::NetErrorDetails net_error_details;
   url_request_->PopulateNetErrorDetails(&net_error_details);
   VLOG(1) << "Error " << net::ErrorToString(net_error)
           << " on chromium request: " << initial_url_.possibly_invalid_spec();
+  end_time_ = base::TimeTicks::Now();
   JNIEnv* env = base::android::AttachCurrentThread();
   cronet::Java_CronetUrlRequest_onError(
       env, owner_.obj(), NetErrorToUrlRequestError(net_error), net_error,
       net_error_details.quic_connection_error,
       ConvertUTF8ToJavaString(env, net::ErrorToString(net_error)).obj(),
       request->GetTotalReceivedBytes());
 }
 
+void CronetURLRequestAdapter::MaybeReportMetrics(JNIEnv* env) const {

[xunjieli, 2016/10/01 13:43:49]

I don't quite understand the need to populate |end_time_| elsewhere. Since
|end_time_| is only useful if we are reporting metrics. How about having
|end_time_| as a local variable here? I am assuming that we always destroy
CronetURLRequestAdapter, so |end_time_| should be pretty accurate -- only off by
one or two JNI roundtrip.

[mgersh, 2016/10/04 21:14:58]

On my test device it's usually off by 1ms, sometimes 0, sometimes 2. I guess
that's fine. Changed it back.

+  if (!enable_metrics_) {
+    return;
+  }
+  net::LoadTimingInfo metrics;
+  url_request_->GetLoadTimingInfo(&metrics);
+  base::Time start_time = metrics.request_start_time;
+  base::TimeTicks start_ticks = metrics.request_start;
+  Java_CronetUrlRequest_onMetricsCollected(
+      env, owner_.obj(), ConvertTime(start_ticks, start_ticks, start_time),
+      ConvertTime(metrics.connect_timing.dns_start, start_ticks, start_time),
+      ConvertTime(metrics.connect_timing.dns_end, start_ticks, start_time),
+      ConvertTime(metrics.connect_timing.connect_start, start_ticks,
+                  start_time),
+      ConvertTime(metrics.connect_timing.connect_end, start_ticks, start_time),
+      ConvertTime(metrics.connect_timing.ssl_start, start_ticks, start_time),
+      ConvertTime(metrics.connect_timing.ssl_end, start_ticks, start_time),
+      ConvertTime(metrics.send_start, start_ticks, start_time),
+      ConvertTime(metrics.send_end, start_ticks, start_time),
+      ConvertTime(metrics.push_start, start_ticks, start_time),
+      ConvertTime(metrics.push_end, start_ticks, start_time),
+      ConvertTime(metrics.receive_headers_end, start_ticks, start_time),
+      ConvertTime(end_time_, start_ticks, start_time),
+      // TODO(mgersh): report total bytes sent
+      metrics.socket_reused, 0, url_request_->GetTotalReceivedBytes());
+}
+
 net::URLRequest* CronetURLRequestAdapter::GetURLRequestForTesting() {
   return url_request_.get();
 }
 
 }  // namespace cronet