Implement timing metrics for UrlRequest

components/cronet/android/cronet_url_request_adapter.cc

Index: components/cronet/android/cronet_url_request_adapter.cc
diff --git a/components/cronet/android/cronet_url_request_adapter.cc b/components/cronet/android/cronet_url_request_adapter.cc
index 6e79bb5d431f7f296ae374228bbe1d7bfa25fb02..8adf62c58317ee5f859523292a6affd9b10dcbd8 100644
--- a/components/cronet/android/cronet_url_request_adapter.cc
+++ b/components/cronet/android/cronet_url_request_adapter.cc
@@ -33,6 +33,22 @@ 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);
@@ -44,7 +60,8 @@ static jlong CreateRequestAdapter(JNIEnv* env,
                                   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);
@@ -58,7 +75,7 @@ static jlong CreateRequestAdapter(JNIEnv* env,
   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);
 }
@@ -70,12 +87,14 @@ CronetURLRequestAdapter::CronetURLRequestAdapter(
     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)
@@ -230,6 +249,7 @@ void CronetURLRequestAdapter::OnSSLCertificateError(
   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,
@@ -272,6 +292,7 @@ void CronetURLRequestAdapter::OnReadCompleted(net::URLRequest* request,
   }
 
   if (bytes_read == 0) {
+    end_time_ = base::TimeTicks::Now();
     JNIEnv* env = base::android::AttachCurrentThread();
     cronet::Java_CronetUrlRequest_onSucceeded(
         env, owner_.obj(), url_request_->GetTotalReceivedBytes());
@@ -362,15 +383,17 @@ void CronetURLRequestAdapter::ReadDataOnNetworkThread(
 
 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());
@@ -379,6 +402,7 @@ void CronetURLRequestAdapter::ReportError(net::URLRequest* request,
   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,
@@ -387,6 +411,33 @@ void CronetURLRequestAdapter::ReportError(net::URLRequest* request,
       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();
 }