Add API for new Cronet metrics

This API is not yet connected to anything in the net stack. Most of
these new metrics will be plumbed through from net::LoadTimingInfo, and
a few from other places.

Includes a unit test for the big mess of longs/Dates in
RequestFinishedInfo.Metrics, but no other tests yet because nothing
works yet.

Leaves the old APIs in place for now, since those actually work.

BUG=629194

Review-Url: https://codereview.chromium.org/2220023002
Cr-Commit-Position: refs/heads/master@{#419185}

components/cronet/android/BUILD.gn

@@ -332,6 +332,7 @@ android_library("cronet_java") {
     "java/src/org/chromium/net/impl/ChromiumUrlRequestFactory.java",
     "java/src/org/chromium/net/impl/CronetBidirectionalStream.java",
     "java/src/org/chromium/net/impl/CronetLibraryLoader.java",
+    "java/src/org/chromium/net/impl/CronetMetrics.java",
     "java/src/org/chromium/net/impl/CronetUploadDataStream.java",
     "java/src/org/chromium/net/impl/CronetUrlRequest.java",
     "java/src/org/chromium/net/impl/CronetUrlRequestContext.java",

components/cronet/android/api/src/org/chromium/net/RequestFinishedInfo.java

@@ -4,9 +4,13 @@
 
 package org.chromium.net;
 
+import android.support.annotation.IntDef;
 import android.support.annotation.Nullable;
 
+import java.lang.annotation.Retention;
+import java.lang.annotation.RetentionPolicy;
 import java.util.Collection;
+import java.util.Date;
 import java.util.concurrent.Executor;
 
 /**
@@ -47,78 +51,245 @@ public final class RequestFinishedInfo {
     }
 
     /**
-     * Metrics collected for a single request.
+     * Metrics collected for a single request. Most of these metrics are timestamps for events
+     * during the lifetime of the request, which can be used to build a detailed timeline for
+     * investigating performance.
+     *
+     * Events happen in this order:
+     * <ol>
+     * <li>{@link #getRequestStart request start}</li>
+     * <li>{@link #getDnsStart DNS start}</li>
+     * <li>{@link #getDnsEnd DNS end}</li>
+     * <li>{@link #getConnectStart connect start}</li>
+     * <li>{@link #getSslStart SSL start}</li>
+     * <li>{@link #getSslEnd SSL end}</li>
+     * <li>{@link #getConnectEnd connect end}</li>
+     * <li>{@link #getSendingStart sending start}</li>
+     * <li>{@link #getSendingEnd sending end}</li>
+     * <li>{@link #getResponseStart response start}</li>
+     * <li>{@link #getResponseEnd response end}</li>
+     * </ol>
+     *
+     * Start times are reported as the time when a request started blocking on event, not when the
+     * event actually occurred, with the exception of push start and end. If a metric is not
+     * meaningful or not available, including cases when a request finished before reaching that
+     * stage, start and end times will be {@code null}. If no time was spent blocking on an event,
+     * start and end will be the same time.
+     *
+     * If the system clock is adjusted during the request, some of the {@link java.util.Date} values
+     * might not match it. Timestamps are recorded using a clock that is guaranteed not to run
+     * backwards. All timestamps are correct relative to the system clock at the time of request
+     * start, and taking the difference between two timestamps will give the correct difference
+     * between the events. In order to preserve this property, timestamps for events other than
+     * request start are not guaranteed to match the system clock at the times they represent.
+     *
+     * Most timing metrics are taken from
+     * <a
+     * href="https://cs.chromium.org/chromium/src/net/base/load_timing_info.h">LoadTimingInfo</a>,
+     * which holds the information for <a href="http://w3c.github.io/navigation-timing/"></a> and
+     * <a href="https://www.w3.org/TR/resource-timing/"></a>.
      *
      * {@hide} as it's a prototype.
      */
-    public static class Metrics {
+    public abstract static class Metrics {
+        /**
+         * Returns time when the request started.
+         * @return {@link java.util.Date} representing when the native request actually started.
+         * This timestamp will match the system clock at the time it represents.
+         */
+        @Nullable
+        public abstract Date getRequestStart();
+
+        /**
+         * Returns time when DNS lookup started. This and {@link #getDnsEnd} will return non-null
+         * values regardless of whether the result came from a DNS server or the local cache.
+         * @return {@link java.util.Date} representing when DNS lookup started. {@code null} if the
+         * socket was reused (see {@link #getSocketReused}).
+         */
         @Nullable
-        private final Long mTtfbMs;
+        public abstract Date getDnsStart();
+
+        /**
+         * Returns time when DNS lookup finished. This and {@link #getDnsStart} will return non-null
+         * values regardless of whether the result came from a DNS server or the local cache.
+         * @return {@link java.util.Date} representing when DNS lookup finished. {@code null} if the
+         * socket was reused (see {@link #getSocketReused}).
+         */
         @Nullable
-        private final Long mTotalTimeMs;
+        public abstract Date getDnsEnd();
+
+        /**
+         * Returns time when connection establishment started.
+         * @return {@link java.util.Date} representing when connection establishment started,
+         * typically when DNS resolution finishes. {@code null} if the socket was reused (see
+         * {@link #getSocketReused}).
+         */
         @Nullable
-        private final Long mSentBytesCount;
+        public abstract Date getConnectStart();
+
+        /**
+         * Returns time when connection establishment finished.
+         * @return {@link java.util.Date} representing when connection establishment finished,
+         * after TCP connection is established and, if using HTTPS, SSL handshake is completed.
+         * For QUIC 0-RTT, this represents the time of handshake confirmation and might happen
+         * later than {@link #getSendingStart}.
+         * {@code null} if the socket was reused (see {@link #getSocketReused}).
+         */
         @Nullable
-        private final Long mReceivedBytesCount;
+        public abstract Date getConnectEnd();
 
-        public Metrics(@Nullable Long ttfbMs, @Nullable Long totalTimeMs,
-                @Nullable Long sentBytesCount, @Nullable Long receivedBytesCount) {
-            mTtfbMs = ttfbMs;
-            mTotalTimeMs = totalTimeMs;
-            mSentBytesCount = sentBytesCount;
-            mReceivedBytesCount = receivedBytesCount;
-        }
+        /**
+         * Returns time when SSL handshake started. For QUIC, this will be the same time as
+         * {@link #getConnectStart}.
+         * @return {@link java.util.Date} representing when SSL handshake started. {@code null} if
+         * SSL is not used or if the socket was reused (see {@link #getSocketReused}).
+         */
+        @Nullable
+        public abstract Date getSslStart();
+
+        /**
+         * Returns time when SSL handshake finished. For QUIC, this will be the same time as
+         * {@link #getConnectEnd}.
+         * @return {@link java.util.Date} representing when SSL handshake finished. {@code null} if
+         * SSL is not used or if the socket was reused (see {@link #getSocketReused}).
+         */
+        @Nullable
+        public abstract Date getSslEnd();
+
+        /**
+         * Returns time when sending the request started.
+         * @return {@link java.util.Date} representing when sending HTTP request headers started.
+         */
+        @Nullable
+        public abstract Date getSendingStart();
+
+        /**
+         * Returns time when sending the request finished.
+         * @return {@link java.util.Date} representing when sending HTTP request body finished.
+         * (Sending request body happens after sending request headers.)
+         */
+        @Nullable
+        public abstract Date getSendingEnd();
+
+        /**
+         * Returns time when first byte of HTTP/2 server push was received.
+         * @return {@link java.util.Date} representing when the first byte of an HTTP/2 server push
+         * was received. {@code null} if server push is not used.
+         */
+        @Nullable
+        public abstract Date getPushStart();
+
+        /**
+         * Returns time when last byte of HTTP/2 server push was received.
+         * @return {@link java.util.Date} representing when the last byte of an HTTP/2 server push
+         * was received. {@code null} if server push is not used.
+         */
+        @Nullable
+        public abstract Date getPushEnd();
+
+        /**
+         * Returns time when the end of the response headers was received.
+         * @return {@link java.util.Date} representing when the end of the response headers was
+         * received.
+         */
+        @Nullable
+        public abstract Date getResponseStart();
+
+        /**
+         * Returns time when last byte of response was received.
+         * @return {@link java.util.Date} representing when the last byte of the response was
+         * received.
+         */
+        @Nullable
+        public abstract Date getResponseEnd();
+
+        /**
+         * Returns whether the socket was reused from a previous request. In HTTP/2 or QUIC, if
+         * streams are multiplexed in a single connection, returns {@code true} for all streams
+         * after the first.
+         * @return whether this request reused a socket from a previous request. When {@code true},
+         * DNS, connection, and SSL times will be {@code null}.
+         */
+        @Nullable
+        public abstract boolean getSocketReused();
 
         /**
          * Returns milliseconds between request initiation and first byte of response headers,
-         * or null if not collected.
+         * or {@code null} if not collected.
+         * TODO(mgersh): Remove once new API works http://crbug.com/629194
+         * {@hide}
          */
         @Nullable
-        public Long getTtfbMs() {
-            return mTtfbMs;
-        }
+        public abstract Long getTtfbMs();
 
         /**
          * Returns milliseconds between request initiation and finish,
-         * including a failure or cancellation, or null if not collected.
+         * including a failure or cancellation, or {@code null} if not collected.
+         * TODO(mgersh): Remove once new API works http://crbug.com/629194
+         * {@hide}
          */
         @Nullable
-        public Long getTotalTimeMs() {
-            return mTotalTimeMs;
-        }
+        public abstract Long getTotalTimeMs();
 
         /**
-         * Returns total bytes sent over the network transport layer, or null if not collected.
+         * Returns total bytes sent over the network transport layer, or {@code null} if not
+         * collected.
          */
         @Nullable
-        public Long getSentBytesCount() {
-            return mSentBytesCount;
-        }
+        public abstract Long getSentBytesCount();
 
         /**
-         * Returns total bytes received over the network transport layer, or null if not collected.
+         * Returns total bytes received over the network transport layer, or {@code null} if not
+         * collected.
          */
         @Nullable
-        public Long getReceivedBytesCount() {
-            return mReceivedBytesCount;
-        }
+        public abstract Long getReceivedBytesCount();
     }
 
     private final String mUrl;
     private final Collection<Object> mAnnotations;
     private final Metrics mMetrics;
+
+    /** @hide */
+    @IntDef({SUCCEEDED, FAILED, CANCELED})
+    @Retention(RetentionPolicy.SOURCE)
+    public @interface FinishedReason {}
+
+    /**
+     * Reason value indicating that the request succeeded. Returned from {@link #getFinishedReason}.
+     */
+    public static final int SUCCEEDED = 0;
+    /**
+     * Reason value indicating that the request failed or returned an error. Returned from
+     * {@link #getFinishedReason}.
+     */
+    public static final int FAILED = 1;
+    /**
+     * Reason value indicating that the request was canceled. Returned from
+     * {@link #getFinishedReason}.
+     */
+    public static final int CANCELED = 2;
+
+    @FinishedReason
+    private final int mFinishedReason;
+
     @Nullable
     private final UrlResponseInfo mResponseInfo;
+    @Nullable
+    private final UrlRequestException mException;
 
     /**
      * @hide only used by internal implementation.
      */
     public RequestFinishedInfo(String url, Collection<Object> annotations, Metrics metrics,
-            @Nullable UrlResponseInfo responseInfo) {
+            @FinishedReason int finishedReason, @Nullable UrlResponseInfo responseInfo,
+            @Nullable UrlRequestException exception) {
         mUrl = url;
         mAnnotations = annotations;
         mMetrics = metrics;
+        mFinishedReason = finishedReason;
         mResponseInfo = responseInfo;
+        mException = exception;
     }
 
     /** Returns the request's original URL. */
@@ -132,6 +303,7 @@ public final class RequestFinishedInfo {
     }
 
     // TODO(klm): Collect and return a chain of Metrics objects for redirect responses.
+    // TODO(mgersh): Update this javadoc when new metrics are fully implemented
     /**
      * Returns metrics collected for this request.
      *
@@ -148,6 +320,15 @@ public final class RequestFinishedInfo {
         return mMetrics;
     }
 
+    /**
+     * Returns the reason why the request finished.
+     * @return one of {@link #SUCCEEDED}, {@link #FAILED}, or {@link #CANCELED}
+     */
+    @FinishedReason
+    public int getFinishedReason() {
+        return mFinishedReason;
+    }
+
     /**
      * Returns a {@link UrlResponseInfo} for the request, if its response had started.
      * @return {@link UrlResponseInfo} for the request, if its response had started.
@@ -156,4 +337,15 @@ public final class RequestFinishedInfo {
     public UrlResponseInfo getResponseInfo() {
         return mResponseInfo;
     }
+
+    /**
+     * If the request failed, returns the same {@link UrlRequestException} provided to
+     * {@link UrlRequest.Callback#onFailed}.
+     *
+     * @return the request's {@link UrlRequestException}, if the request failed
+     */
+    @Nullable
+    public UrlRequestException getException() {
+        return mException;
+    }
 }

components/cronet/android/java/src/org/chromium/net/impl/CronetMetrics.java

+// Copyright 2016 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.
+
+package org.chromium.net.impl;
+
+import android.support.annotation.Nullable;
+
+import org.chromium.base.VisibleForTesting;
+import org.chromium.net.RequestFinishedInfo;
+
+import java.util.Date;
+
+/**
+ * Implementation of {@link RequestFinishedInfo.Metrics}.
+ */
+@VisibleForTesting
+public final class CronetMetrics extends RequestFinishedInfo.Metrics {
+    private final long mRequestStartMs;
+    private final long mDnsStartMs;
+    private final long mDnsEndMs;
+    private final long mConnectStartMs;
+    private final long mConnectEndMs;
+    private final long mSslStartMs;
+    private final long mSslEndMs;
+    private final long mSendingStartMs;
+    private final long mSendingEndMs;
+    private final long mPushStartMs;
+    private final long mPushEndMs;
+    private final long mResponseStartMs;
+    private final long mResponseEndMs;
+    private final boolean mSocketReused;
+
+    // TODO(mgersh): Delete after the switch to the new API http://crbug.com/629194
+    @Nullable
+    private final Long mTtfbMs;
+    // TODO(mgersh): Delete after the switch to the new API http://crbug.com/629194
+    @Nullable
+    private final Long mTotalTimeMs;
+    @Nullable
+    private final Long mSentBytesCount;
+    @Nullable
+    private final Long mReceivedBytesCount;
+
+    @Nullable
+    private static Date toDate(long timestamp) {
+        if (timestamp != -1) {
+            return new Date(timestamp);
+        }
+        return null;
+    }
+
+    private static boolean checkOrder(long start, long end) {
+        // If end doesn't exist, start can be anything, including also not existing
+        // If end exists, start must also exist and be before end
+        return (end >= start && start != -1) || end == -1;
+    }
+
+    /**
+     * Old-style constructor
+     * TODO(mgersh): Delete after the switch to the new API http://crbug.com/629194
+     */
+    public CronetMetrics(@Nullable Long ttfbMs, @Nullable Long totalTimeMs,
+            @Nullable Long sentBytesCount, @Nullable Long receivedBytesCount) {
+        mTtfbMs = ttfbMs;
+        mTotalTimeMs = totalTimeMs;
+        mSentBytesCount = sentBytesCount;
+        mReceivedBytesCount = receivedBytesCount;
+
+        // Everything else is -1 (translates to null) for now
+        mRequestStartMs = -1;
+        mDnsStartMs = -1;
+        mDnsEndMs = -1;
+        mConnectStartMs = -1;
+        mConnectEndMs = -1;
+        mSslStartMs = -1;
+        mSslEndMs = -1;
+        mSendingStartMs = -1;
+        mSendingEndMs = -1;
+        mPushStartMs = -1;
+        mPushEndMs = -1;
+        mResponseStartMs = -1;
+        mResponseEndMs = -1;
+        mSocketReused = false;
+    }
+
+    /**
+     * New-style constructor
+     */
+    public CronetMetrics(long requestStartMs, long dnsStartMs, long dnsEndMs, long connectStartMs,
+            long connectEndMs, long sslStartMs, long sslEndMs, long sendingStartMs,
+            long sendingEndMs, long pushStartMs, long pushEndMs, long responseStartMs,
+            long responseEndMs, boolean socketReused, long sentBytesCount,
+            long receivedBytesCount) {
+        // Check that no end times are before corresponding start times,
+        // or exist when start time doesn't.
+        assert checkOrder(dnsStartMs, dnsEndMs);
+        assert checkOrder(connectStartMs, connectEndMs);
+        assert checkOrder(sslStartMs, sslEndMs);
+        assert checkOrder(sendingStartMs, sendingEndMs);
+        assert checkOrder(pushStartMs, pushEndMs);
+        assert checkOrder(responseStartMs, responseEndMs);
+        // Spot-check some of the other orderings
+        assert dnsStartMs >= requestStartMs || dnsStartMs == -1;
+        assert sendingStartMs >= requestStartMs || sendingStartMs == -1;
+        assert sslStartMs >= connectStartMs || sslStartMs == -1;
+        assert responseStartMs >= sendingStartMs || responseStartMs == -1;
+        mRequestStartMs = requestStartMs;
+        mDnsStartMs = dnsStartMs;
+        mDnsEndMs = dnsEndMs;
+        mConnectStartMs = connectStartMs;
+        mConnectEndMs = connectEndMs;
+        mSslStartMs = sslStartMs;
+        mSslEndMs = sslEndMs;
+        mSendingStartMs = sendingStartMs;
+        mSendingEndMs = sendingEndMs;
+        mPushStartMs = pushStartMs;
+        mPushEndMs = pushEndMs;
+        mResponseStartMs = responseStartMs;
+        mResponseEndMs = responseEndMs;
+        mSocketReused = socketReused;
+        mSentBytesCount = sentBytesCount;
+        mReceivedBytesCount = receivedBytesCount;
+
+        // Don't care about these anymore
+        mTtfbMs = null;
+        mTotalTimeMs = null;
+    }
+
+    @Nullable
+    public Date getRequestStart() {
+        return toDate(mRequestStartMs);
+    }
+
+    @Nullable
+    public Date getDnsStart() {
+        return toDate(mDnsStartMs);
+    }
+
+    @Nullable
+    public Date getDnsEnd() {
+        return toDate(mDnsEndMs);
+    }
+
+    @Nullable
+    public Date getConnectStart() {
+        return toDate(mConnectStartMs);
+    }
+
+    @Nullable
+    public Date getConnectEnd() {
+        return toDate(mConnectEndMs);
+    }
+
+    @Nullable
+    public Date getSslStart() {
+        return toDate(mSslStartMs);
+    }
+
+    @Nullable
+    public Date getSslEnd() {
+        return toDate(mSslEndMs);
+    }
+
+    @Nullable
+    public Date getSendingStart() {
+        return toDate(mSendingStartMs);
+    }
+
+    @Nullable
+    public Date getSendingEnd() {
+        return toDate(mSendingEndMs);
+    }
+
+    @Nullable
+    public Date getPushStart() {
+        return toDate(mPushStartMs);
+    }
+
+    @Nullable
+    public Date getPushEnd() {
+        return toDate(mPushEndMs);
+    }
+
+    @Nullable
+    public Date getResponseStart() {
+        return toDate(mResponseStartMs);
+    }
+
+    @Nullable
+    public Date getResponseEnd() {
+        return toDate(mResponseEndMs);
+    }
+
+    @Nullable
+    public boolean getSocketReused() {
+        return mSocketReused;
+    }
+
+    @Nullable
+    public Long getTtfbMs() {
+        return mTtfbMs;
+    }
+
+    @Nullable
+    public Long getTotalTimeMs() {
+        return mTotalTimeMs;
+    }
+
+    @Nullable
+    public Long getSentBytesCount() {
+        return mSentBytesCount;
+    }
+
+    @Nullable
+    public Long getReceivedBytesCount() {
+        return mReceivedBytesCount;
+    }
+}

components/cronet/android/java/src/org/chromium/net/impl/CronetUrlRequest.java

@@ -49,7 +49,7 @@ import javax.annotation.concurrent.GuardedBy;
 @VisibleForTesting
 public final class CronetUrlRequest implements UrlRequest {
     private static final RequestFinishedInfo.Metrics EMPTY_METRICS =
-            new RequestFinishedInfo.Metrics(null, null, null, null);
+            new CronetMetrics(null, null, null, null);
     private final boolean mAllowDirectExecutor;
 
     /* Native adapter object, owned by UrlRequest. */
@@ -700,10 +700,11 @@ public final class CronetUrlRequest implements UrlRequest {
     }
 
     RequestFinishedInfo getRequestFinishedInfo() {
+        // TODO(mgersh): fill in real values for finishedReason and exception
         return new RequestFinishedInfo(mInitialUrl, mRequestAnnotations,
                 (mRequestMetricsAccumulator != null ? mRequestMetricsAccumulator.getRequestMetrics()
                                                     : EMPTY_METRICS),
-                mResponseInfo);
+                RequestFinishedInfo.SUCCEEDED, mResponseInfo, null);
     }
 
     private final class UrlRequestMetricsAccumulator {
@@ -715,7 +716,7 @@ public final class CronetUrlRequest implements UrlRequest {
         private Long mTotalTimeMs;
 
         private RequestFinishedInfo.Metrics getRequestMetrics() {
-            return new RequestFinishedInfo.Metrics(mTtfbMs, mTotalTimeMs,
+            return new CronetMetrics(mTtfbMs, mTotalTimeMs,
                     null, // TODO(klm): Compute sentBytesCount.
                     (mResponseInfo != null ? mResponseInfo.getReceivedBytesCount() : 0));
         }

components/cronet/android/test/javatests/src/org/chromium/net/RequestFinishedInfoTest.java

@@ -9,9 +9,11 @@ import static org.chromium.base.CollectionUtil.newHashSet;
 import android.test.suitebuilder.annotation.SmallTest;
 
 import org.chromium.base.test.util.Feature;
+import org.chromium.net.impl.CronetMetrics;
 import org.chromium.net.test.EmbeddedTestServer;
 
 import java.util.ArrayList;
+import java.util.Date;
 import java.util.HashSet;
 import java.util.LinkedList;
 import java.util.List;
@@ -259,4 +261,45 @@ public class RequestFinishedInfoTest extends CronetTestBase {
                 requestFinishedListener.mRequestInfo);
         mTestFramework.mCronetEngine.shutdown();
     }
+
+    @SmallTest
+    @Feature({"Cronet"})
+    public void testMetricsGetters() throws Exception {
+        long requestStart = 1;
+        long dnsStart = 2;
+        long dnsEnd = -1;
+        long connectStart = 4;
+        long connectEnd = 5;
+        long sslStart = 6;
+        long sslEnd = 7;
+        long sendingStart = 8;
+        long sendingEnd = 9;
+        long pushStart = 10;
+        long pushEnd = 11;
+        long responseStart = 12;
+        long responseEnd = 13;
+        boolean socketReused = true;
+        long sentBytesCount = 14;
+        long receivedBytesCount = 15;
+        // Make sure nothing gets reordered inside the Metrics class
+        RequestFinishedInfo.Metrics metrics = new CronetMetrics(requestStart, dnsStart, dnsEnd,
+                connectStart, connectEnd, sslStart, sslEnd, sendingStart, sendingEnd, pushStart,
+                pushEnd, responseStart, responseEnd, socketReused, sentBytesCount,
+                receivedBytesCount);
+        assertEquals(new Date(requestStart), metrics.getRequestStart());
+        // -1 timestamp should translate to null
+        assertNull(metrics.getDnsEnd());
+        assertEquals(new Date(dnsStart), metrics.getDnsStart());
+        assertEquals(new Date(connectStart), metrics.getConnectStart());
+        assertEquals(new Date(connectEnd), metrics.getConnectEnd());
+        assertEquals(new Date(sslStart), metrics.getSslStart());
+        assertEquals(new Date(sslEnd), metrics.getSslEnd());
+        assertEquals(new Date(pushStart), metrics.getPushStart());
+        assertEquals(new Date(pushEnd), metrics.getPushEnd());
+        assertEquals(new Date(responseStart), metrics.getResponseStart());
+        assertEquals(new Date(responseEnd), metrics.getResponseEnd());
+        assertEquals(socketReused, metrics.getSocketReused());
+        assertEquals(sentBytesCount, (long) metrics.getSentBytesCount());
+        assertEquals(receivedBytesCount, (long) metrics.getReceivedBytesCount());
+    }
 }