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

[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();
 }
 
 }  // namespace cronet