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());

[xunjieli, 2016/09/22 18:05:15]

This will be invoked after the Java destroyRequestAdapter() which calls
mRequestContext.reportFinished().  It looks like we will not have the Metrics
info at the time when we try to update CronetUrlRequestContext if request fails
or is canceled.

How about removing all invocations of MaybeReportMetrics() in this file, and
only leave one here in DestroyOnNetworkThread()? if (enable_metrics_) then call
Java_CronetUrlRequest_onMetricsCollected which will then do
mRequestContext.reportFinished()?

We should add a test where the request is canceled or fails after request
headers, and make sure we have the correct load timing info.

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

Wow, yeah, thanks for catching that. Wrote a test. Unfortunately, my attempt at
implementing your suggested fix caused all the tests to become flaky. The
version I uploaded mostly fixes it, but not 100% (I saw a failure on requestEnd
not being before endTime), and the "Thread.sleep(1000)" everywhere is ugly. Do
you have better ideas about how to fix it?

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

Instead of doing "Thread.sleep(1000)," how about waiting until a number of
UrlRequestFinishedInfo has been observed?
Something like:
https://codereview.chromium.org/2360813003/diff/40001/components/cronet/andro...
?

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

Done, thanks for the help.

     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();
+  base::Time start_time = metrics.request_start_time;
+  base::TimeTicks start_ticks = metrics.request_start;

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

Are we sure that |start_ticks| is not null? 
If so, can we add a DCHECK here to check both start_time and start_ticks are
(!is_null())?

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

Good catch. I checked and it's very unlikely but possible for them (both, never
just one or the other) to be null if cancel() is called immediately after
start(). Added some checks.

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

Acknowledged.

+  cronet::Java_CronetUrlRequest_onMetricsCollected(

[xunjieli, 2016/09/22 18:28:58]

nit: "cronet::" is not necessary.

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

Done.

+      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());

[xunjieli, 2016/09/22 18:28:59]

Can we add a TODO here to support GetTotalSentBytes()?

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

Done.

+}
+
+int64_t CronetURLRequestAdapter::ConvertTime(

[xunjieli, 2016/09/22 18:28:59]

This can be a non-member function in the anonymous namespace.

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

Done.

+    base::TimeTicks ticks,
+    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();
 }