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 cb021c5411e271309e4726888c505be08ce80004..1c6e2aa025242373c6d5d1c1b86644bbeb65fb28 100644
--- a/components/cronet/android/cronet_url_request_adapter.cc
+++ b/components/cronet/android/cronet_url_request_adapter.cc
@@ -44,7 +44,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 +59,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,7 +71,8 @@ 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),
@@ -82,6 +84,7 @@ CronetURLRequestAdapter::CronetURLRequestAdapter(
     load_flags_ |= net::LOAD_DISABLE_CACHE;
   if (jdisable_connection_migration == JNI_TRUE)
     load_flags_ |= net::LOAD_DISABLE_CONNECTION_MIGRATION;
+  enable_metrics_ = (jenable_metrics == JNI_TRUE);
 }
 
 CronetURLRequestAdapter::~CronetURLRequestAdapter() {
@@ -232,6 +235,7 @@ void CronetURLRequestAdapter::OnSSLCertificateError(
   request->Cancel();
   int net_error = net::MapCertStatusToNetError(ssl_info.cert_status);
   JNIEnv* env = base::android::AttachCurrentThread();
+  MaybeReportMetrics(request);
   cronet::Java_CronetUrlRequest_onError(
       env, owner_.obj(), NetErrorToUrlRequestError(net_error), net_error,
       net::QUIC_NO_ERROR,
@@ -273,6 +277,7 @@ void CronetURLRequestAdapter::OnReadCompleted(net::URLRequest* request,
     // embedder releases it, too.
     read_buffer_ = nullptr;
   } else {
+    MaybeReportMetrics(request);
     JNIEnv* env = base::android::AttachCurrentThread();
     cronet::Java_CronetUrlRequest_onSucceeded(
         env, owner_.obj(), url_request_->GetTotalReceivedBytes());
@@ -356,6 +361,7 @@ void CronetURLRequestAdapter::ReadDataOnNetworkThread(
 void CronetURLRequestAdapter::DestroyOnNetworkThread(bool send_on_canceled) {
   DCHECK(context_->IsOnNetworkThread());
   if (send_on_canceled) {
+    MaybeReportMetrics(url_request_.get());
     JNIEnv* env = base::android::AttachCurrentThread();
     cronet::Java_CronetUrlRequest_onCanceled(env, owner_.obj());
   }
@@ -372,6 +378,7 @@ bool CronetURLRequestAdapter::MaybeReportError(net::URLRequest* request) const {
   url_request_->PopulateNetErrorDetails(&net_error_details);
   VLOG(1) << "Error " << net::ErrorToString(net_error)
           << " on chromium request: " << initial_url_.possibly_invalid_spec();
+  MaybeReportMetrics(request);
   JNIEnv* env = base::android::AttachCurrentThread();
   cronet::Java_CronetUrlRequest_onError(
       env, owner_.obj(), NetErrorToUrlRequestError(net_error), net_error,
@@ -381,6 +388,44 @@ bool CronetURLRequestAdapter::MaybeReportError(net::URLRequest* request) const {
   return true;
 }
 
+void CronetURLRequestAdapter::MaybeReportMetrics(
+    net::URLRequest* request) const {
+  if (!enable_metrics_) {
+    return;
+  }
+  net::LoadTimingInfo metrics;
+  request->GetLoadTimingInfo(&metrics);
+  JNIEnv* env = base::android::AttachCurrentThread();

[xunjieli, 2016/09/20 21:53:33]

How about passing |env| as an argument of MaybeReportMetrics() so we don't do
AttachCurrentThread() twice?

[mgersh, 2016/09/30 23:47:14]

Done.

+  base::Time start_time = metrics.request_start_time;
+  base::TimeTicks start_ticks = metrics.request_start;
+  cronet::Java_CronetUrlRequest_onMetricsCollected(

[xunjieli, 2016/09/20 14:32:46]

Can we combine this with onError, onSucceeded, onCanceled? We should try to
minimize number of Java <-> C++ trips unless there is a reason not to do so.

[mgersh, 2016/09/20 20:48:24]

The reason for this was to avoid adding 15 more arguments to each of those,
which would have to be repeated on each one, and would need to be filled in even
when metrics aren't being collected. From
https://docs.google.com/spreadsheets/d/1ulggKOZ7VQ8IytP1hKr-1wvBu70qG2qxKT4vR...,
it looks like time for a JNI call depends on number of arguments and having the
extra arguments on onSucceeded etc. would potentially be just as bad in the case
where there are listeners, and worse in the case where there aren't.

[xunjieli, 2016/09/20 21:53:33]

Acknowledged. That's a good point. 

+      env, owner_.obj(), start_time.ToJavaTime(),
+      ConvertTime(metrics.connect_timing.dns_start, start_time, start_ticks),
+      ConvertTime(metrics.connect_timing.dns_end, start_time, start_ticks),
+      ConvertTime(metrics.connect_timing.connect_start, start_time,
+                  start_ticks),
+      ConvertTime(metrics.connect_timing.connect_end, start_time, start_ticks),
+      ConvertTime(metrics.connect_timing.ssl_start, start_time, start_ticks),
+      ConvertTime(metrics.connect_timing.ssl_end, start_time, start_ticks),
+      ConvertTime(metrics.send_start, start_time, start_ticks),
+      ConvertTime(metrics.send_end, start_time, start_ticks),
+      ConvertTime(metrics.push_start, start_time, start_ticks),
+      ConvertTime(metrics.push_end, start_time, start_ticks),
+      ConvertTime(metrics.receive_headers_end, start_time, start_ticks),
+      ConvertTime(base::TimeTicks::Now(), start_time, start_ticks),
+      metrics.socket_reused, 0, request->GetTotalReceivedBytes());
+}
+
+int64_t CronetURLRequestAdapter::ConvertTime(
+    base::TimeTicks ticks,

[xunjieli, 2016/09/20 14:32:46]

const base::TimeTicks& ?

[mgersh, 2016/09/20 20:48:24]

TimeTicks and Time are stored as a single int64_t and are passed as values in a
bunch of other places, including time.h itself
(https://cs.chromium.org/chromium/src/base/time/time.h?q=time.h&sq=package:chr...).
My understanding was that this makes sense to do with a class this small. Given
that, do you still think it's better as references?

[xunjieli, 2016/09/20 21:53:33]

That's a good point. I was looking at 
https://cs.chromium.org/search/?q=%22const+base::TimeTicks%26%22+file:%5Esrc/...

In general, I prefer passing by references over values for nonprimitive types.
But since the time.h is passing by value, I am not sure what is the best
practice for this particular type. Your call.

[mgersh, 2016/09/30 23:47:14]

Done.

+    base::Time start_time,
+    base::TimeTicks start_ticks) const {
+  if (ticks.is_null()) {
+    return -1;
+  }
+  return (start_time + (ticks - start_ticks)).ToJavaTime();
+}
+
 net::URLRequest* CronetURLRequestAdapter::GetURLRequestForTesting() {
   return url_request_.get();
 }