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 26 matching lines @@
 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()) {
   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;
+  enable_metrics_ = (jenable_metrics == JNI_TRUE);
 }
 
 CronetURLRequestAdapter::~CronetURLRequestAdapter() {
   DCHECK(context_->IsOnNetworkThread());
 }
 
 jboolean CronetURLRequestAdapter::SetHttpMethod(
     JNIEnv* env,
     const JavaParamRef<jobject>& jcaller,
     const JavaParamRef<jstring>& jmethod) {
@@ skipping 130 matching lines @@
 }
 
 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);
   JNIEnv* env = base::android::AttachCurrentThread();
+  MaybeReportMetrics(request);
   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) {
   DCHECK(context_->IsOnNetworkThread());
   if (MaybeReportError(request))
@@ skipping 21 matching lines @@
   if (bytes_read != 0) {
     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
     // 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());
   }
 }
 
 void CronetURLRequestAdapter::StartOnNetworkThread() {
   DCHECK(context_->IsOnNetworkThread());
   VLOG(1) << "Starting chromium request: "
           << initial_url_.possibly_invalid_spec().c_str()
@@ skipping 63 matching lines @@
   // If IO is pending, wait for the URLRequest to call OnReadCompleted.
   if (url_request_->status().is_io_pending())
     return;
 
   OnReadCompleted(url_request_.get(), bytes_read);
 }
 
 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());
   }
   delete this;
 }
 
 bool CronetURLRequestAdapter::MaybeReportError(net::URLRequest* request) const {
   DCHECK_NE(net::URLRequestStatus::IO_PENDING, url_request_->status().status());
   DCHECK_EQ(request, url_request_.get());
   if (url_request_->status().is_success())
     return false;
   int net_error = url_request_->status().error();
   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();
+  MaybeReportMetrics(request);
   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());
   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();
 }
 
 }  // namespace cronet