Bug 1244227 - Properly report throttled network timing. r=Honza draft
authorTom Tromey <tom@tromey.com>
Thu, 04 Feb 2016 06:40:25 -0700
changeset 396355 89ff34f8f432795a53a34aa875d0c06f79f79e15
parent 396354 fd4646cda4b497358e05e7e64c7c43ddda8e9d85
child 396356 e2c942b6feb1cd9ce5a37d700518b99047cb1cde
push id24964
push userbmo:ttromey@mozilla.com
push dateWed, 03 Aug 2016 17:20:57 +0000
reviewersHonza
bugs1244227
milestone51.0a1
Bug 1244227 - Properly report throttled network timing. r=Honza MozReview-Commit-ID: BCJLSRGS0vE
devtools/shared/webconsole/network-monitor.js
devtools/shared/webconsole/throttle.js
--- a/devtools/shared/webconsole/network-monitor.js
+++ b/devtools/shared/webconsole/network-monitor.js
@@ -575,18 +575,16 @@ NetworkResponseListener.prototype = {
 
     this.receivedData = "";
 
     this.httpActivity.owner.addResponseContent(
       response,
       this.httpActivity.discardResponseBody
     );
 
-    this.httpActivity.channel = null;
-    this.httpActivity.owner = null;
     this.httpActivity = null;
     this.sink = null;
     this.inputStream = null;
     this.converter = null;
     this.request = null;
     this.owner = null;
   },
 
@@ -692,16 +690,23 @@ NetworkMonitor.prototype = {
     0x804b000b: "STATUS_RESOLVED",
     0x804b0007: "STATUS_CONNECTING_TO",
     0x804b0004: "STATUS_CONNECTED_TO",
     0x804b0005: "STATUS_SENDING_TO",
     0x804b000a: "STATUS_WAITING_FOR",
     0x804b0006: "STATUS_RECEIVING_FROM"
   },
 
+  httpDownloadActivities: [
+    gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_START,
+    gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_HEADER,
+    gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_COMPLETE,
+    gActivityDistributor.ACTIVITY_SUBTYPE_TRANSACTION_CLOSE
+  ],
+
   // Network response bodies are piped through a buffer of the given size (in
   // bytes).
   responsePipeSegmentSize: null,
 
   owner: null,
 
   /**
    * Whether to save the bodies of network requests and responses.
@@ -871,22 +876,67 @@ NetworkMonitor.prototype = {
    * @param nsIHttpChannel aSubject
    * @returns void
    */
   _httpModifyExaminer: function (subject) {
     let throttler = this._getThrottler();
     if (throttler) {
       let channel = subject.QueryInterface(Ci.nsIHttpChannel);
       if (matchRequest(channel, this.filters)) {
+        // Read any request body here, before it is throttled.
+        let httpActivity = this.createOrGetActivityObject(channel);
+        this._onRequestBodySent(httpActivity);
         throttler.manageUpload(channel);
       }
     }
   },
 
   /**
+   * A helper function for observeActivity.  This does whatever work
+   * is required by a particular http activity event.  Arguments are
+   * the same as for observeActivity.
+   */
+  _dispatchActivity: function (httpActivity, channel, activityType,
+                               activitySubtype, timestamp, extraSizeData,
+                               extraStringData) {
+    let transCodes = this.httpTransactionCodes;
+
+    // Store the time information for this activity subtype.
+    if (activitySubtype in transCodes) {
+      let stage = transCodes[activitySubtype];
+      if (stage in httpActivity.timings) {
+        httpActivity.timings[stage].last = timestamp;
+      } else {
+        httpActivity.timings[stage] = {
+          first: timestamp,
+          last: timestamp,
+        };
+      }
+    }
+
+    switch (activitySubtype) {
+      case gActivityDistributor.ACTIVITY_SUBTYPE_REQUEST_BODY_SENT:
+        this._onRequestBodySent(httpActivity);
+        if (httpActivity.sentBody !== null) {
+          httpActivity.owner.addRequestPostData({ text: httpActivity.sentBody });
+          httpActivity.sentBody = null;
+        }
+        break;
+      case gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_HEADER:
+        this._onResponseHeader(httpActivity, extraStringData);
+        break;
+      case gActivityDistributor.ACTIVITY_SUBTYPE_TRANSACTION_CLOSE:
+        this._onTransactionClose(httpActivity);
+        break;
+      default:
+        break;
+    }
+  },
+
+  /**
    * Begin observing HTTP traffic that originates inside the current tab.
    *
    * @see https://developer.mozilla.org/en/XPCOM_Interface_Reference/nsIHttpActivityObserver
    *
    * @param nsIHttpChannel channel
    * @param number activityType
    * @param number activitySubtype
    * @param number timestamp
@@ -912,69 +962,44 @@ NetworkMonitor.prototype = {
     if (activitySubtype ==
         gActivityDistributor.ACTIVITY_SUBTYPE_REQUEST_HEADER) {
       this._onRequestHeader(channel, timestamp, extraStringData);
       return;
     }
 
     // Iterate over all currently ongoing requests. If channel can't
     // be found within them, then exit this function.
-    let httpActivity = null;
-    for (let id in this.openRequests) {
-      let item = this.openRequests[id];
-      if (item.channel === channel) {
-        httpActivity = item;
-        break;
-      }
-    }
-
+    let httpActivity = this._findActivityObject(channel);
     if (!httpActivity) {
       return;
     }
 
-    let transCodes = this.httpTransactionCodes;
-
-    // Store the time information for this activity subtype.
-    if (activitySubtype in transCodes) {
-      let stage = transCodes[activitySubtype];
-      if (stage in httpActivity.timings) {
-        httpActivity.timings[stage].last = timestamp;
-      } else {
-        httpActivity.timings[stage] = {
-          first: timestamp,
-          last: timestamp,
-        };
-      }
-    }
-
-    switch (activitySubtype) {
-      case gActivityDistributor.ACTIVITY_SUBTYPE_REQUEST_BODY_SENT:
-        this._onRequestBodySent(httpActivity);
-        break;
-      case gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_HEADER:
-        this._onResponseHeader(httpActivity, extraStringData);
-        break;
-      case gActivityDistributor.ACTIVITY_SUBTYPE_TRANSACTION_CLOSE:
-        this._onTransactionClose(httpActivity);
-        break;
-      default:
-        break;
+    // If we're throttling, we must not report events as they arrive
+    // from platform, but instead let the throttler emit the events
+    // after some time has elapsed.
+    if (httpActivity.downloadThrottle &&
+        this.httpDownloadActivities.indexOf(activitySubtype) >= 0) {
+      let callback = this._dispatchActivity.bind(this);
+      httpActivity.downloadThrottle
+        .addActivityCallback(callback, httpActivity, channel, activityType,
+                             activitySubtype, timestamp, extraSizeData,
+                             extraStringData);
+    } else {
+      this._dispatchActivity(httpActivity, channel, activityType,
+                             activitySubtype, timestamp, extraSizeData,
+                             extraStringData);
     }
   }),
 
   /**
    *
    */
   _createNetworkEvent: function (channel, { timestamp, extraStringData,
                                            fromCache, fromServiceWorker }) {
-    let win = NetworkHelper.getWindowForRequest(channel);
-    let httpActivity = this.createActivityObject(channel);
-
-    // see _onRequestBodySent()
-    httpActivity.charset = win ? win.document.characterSet : null;
+    let httpActivity = this.createOrGetActivityObject(channel);
 
     channel.QueryInterface(Ci.nsIPrivateBrowsingChannel);
     httpActivity.private = channel.isChannelPrivate;
 
     if (timestamp) {
       httpActivity.timings.REQUEST_HEADER = {
         first: timestamp,
         last: timestamp
@@ -1051,17 +1076,16 @@ NetworkMonitor.prototype = {
 
     httpActivity.owner = this.owner.onNetworkEvent(event, channel);
 
     this._setupResponseListener(httpActivity, fromCache);
 
     httpActivity.owner.addRequestHeaders(headers, extraStringData);
     httpActivity.owner.addRequestCookies(cookies);
 
-    this.openRequests[httpActivity.id] = httpActivity;
     return httpActivity;
   },
 
   /**
    * Handler for ACTIVITY_SUBTYPE_REQUEST_HEADER. When a request starts the
    * headers are sent to the server. This method creates the |httpActivity|
    * object where we store the request and response information that is
    * collected through its lifetime.
@@ -1076,46 +1100,76 @@ NetworkMonitor.prototype = {
     if (!matchRequest(channel, this.filters)) {
       return;
     }
 
     this._createNetworkEvent(channel, { timestamp, extraStringData });
   },
 
   /**
-   * Create the empty HTTP activity object. This object is used for storing all
-   * the request and response information.
+   * Find an HTTP activity object for the channel.
+   *
+   * @param nsIHttpChannel channel
+   *        The HTTP channel whose activity object we want to find.
+   * @return object
+   *        The HTTP activity object, or null if it is not found.
+   */
+  _findActivityObject: function (channel) {
+    for (let id in this.openRequests) {
+      let item = this.openRequests[id];
+      if (item.channel === channel) {
+        return item;
+      }
+    }
+    return null;
+  },
+
+  /**
+   * Find an existing HTTP activity object, or create a new one. This
+   * object is used for storing all the request and response
+   * information.
    *
    * This is a HAR-like object. Conformance to the spec is not guaranteed at
    * this point.
    *
    * @see http://www.softwareishard.com/blog/har-12-spec
    * @param nsIHttpChannel channel
    *        The HTTP channel for which the HTTP activity object is created.
    * @return object
    *         The new HTTP activity object.
    */
-  createActivityObject: function (channel) {
-    return {
-      id: gSequenceId(),
-      channel: channel,
-      // see _onRequestHeader()
-      charset: null,
-      url: channel.URI.spec,
-      // needed for host specific security info
-      hostname: channel.URI.host,
-      discardRequestBody: !this.saveRequestAndResponseBodies,
-      discardResponseBody: !this.saveRequestAndResponseBodies,
-      // internal timing information, see observeActivity()
-      timings: {},
-      // see _onResponseHeader()
-      responseStatus: null,
-      // the activity owner which is notified when changes happen
-      owner: null,
-    };
+  createOrGetActivityObject: function (channel) {
+    let httpActivity = this._findActivityObject(channel);
+    if (!httpActivity) {
+      let win = NetworkHelper.getWindowForRequest(channel);
+      let charset = win ? win.document.characterSet : null;
+
+      httpActivity = {
+        id: gSequenceId(),
+        channel: channel,
+        // see _onRequestBodySent()
+        charset: charset,
+        sentBody: null,
+        url: channel.URI.spec,
+        // needed for host specific security info
+        hostname: channel.URI.host,
+        discardRequestBody: !this.saveRequestAndResponseBodies,
+        discardResponseBody: !this.saveRequestAndResponseBodies,
+        // internal timing information, see observeActivity()
+        timings: {},
+        // see _onResponseHeader()
+        responseStatus: null,
+        // the activity owner which is notified when changes happen
+        owner: null,
+      };
+
+      this.openRequests[httpActivity.id] = httpActivity;
+    }
+
+    return httpActivity;
   },
 
   /**
    * Setup the network response listener for the given HTTP activity. The
    * NetworkResponseListener is responsible for storing the response body.
    *
    * @private
    * @param object httpActivity
@@ -1161,40 +1215,42 @@ NetworkMonitor.prototype = {
    * Handler for ACTIVITY_SUBTYPE_REQUEST_BODY_SENT. The request body is logged
    * here.
    *
    * @private
    * @param object httpActivity
    *        The HTTP activity object we are working with.
    */
   _onRequestBodySent: function (httpActivity) {
-    if (httpActivity.discardRequestBody) {
+    // Return early if we don't need the request body, or if we've
+    // already found it.
+    if (httpActivity.discardRequestBody || httpActivity.sentBody !== null) {
       return;
     }
 
     let sentBody = NetworkHelper.readPostTextFromRequest(httpActivity.channel,
                                                          httpActivity.charset);
 
-    if (!sentBody && this.window &&
+    if (sentBody !== null && this.window &&
         httpActivity.url == this.window.location.href) {
       // If the request URL is the same as the current page URL, then
       // we can try to get the posted text from the page directly.
       // This check is necessary as otherwise the
       //   NetworkHelper.readPostTextFromPageViaWebNav()
       // function is called for image requests as well but these
       // are not web pages and as such don't store the posted text
       // in the cache of the webpage.
       let webNav = this.window.QueryInterface(Ci.nsIInterfaceRequestor)
                    .getInterface(Ci.nsIWebNavigation);
       sentBody = NetworkHelper
                  .readPostTextFromPageViaWebNav(webNav, httpActivity.charset);
     }
 
-    if (sentBody) {
-      httpActivity.owner.addRequestPostData({ text: sentBody });
+    if (sentBody !== null) {
+      httpActivity.sentBody = sentBody;
     }
   },
 
   /**
    * Handler for ACTIVITY_SUBTYPE_RESPONSE_HEADER. This method stores
    * information about the response headers.
    *
    * @private
@@ -1309,22 +1365,20 @@ NetworkMonitor.prototype = {
                            timings.STATUS_CONNECTING_TO.first;
     } else if (timings.STATUS_SENDING_TO) {
       harTimings.connect = timings.STATUS_SENDING_TO.first -
                            timings.REQUEST_HEADER.first;
     } else {
       harTimings.connect = -1;
     }
 
-    if ((timings.STATUS_WAITING_FOR || timings.STATUS_RECEIVING_FROM) &&
-        (timings.STATUS_CONNECTED_TO || timings.STATUS_SENDING_TO)) {
-      harTimings.send = (timings.STATUS_WAITING_FOR ||
-                         timings.STATUS_RECEIVING_FROM).first -
-                        (timings.STATUS_CONNECTED_TO ||
-                         timings.STATUS_SENDING_TO).last;
+    if (timings.STATUS_SENDING_TO) {
+      harTimings.send = timings.STATUS_SENDING_TO.last - timings.STATUS_SENDING_TO.first;
+    } else if (timings.REQUEST_HEADER && timings.REQUEST_BODY_SENT) {
+      harTimings.send = timings.REQUEST_BODY_SENT.last - timings.REQUEST_HEADER.first;
     } else {
       harTimings.send = -1;
     }
 
     if (timings.RESPONSE_START) {
       harTimings.wait = timings.RESPONSE_START.first -
                         (timings.REQUEST_BODY_SENT ||
                          timings.STATUS_SENDING_TO).last;
--- a/devtools/shared/webconsole/throttle.js
+++ b/devtools/shared/webconsole/throttle.js
@@ -8,16 +8,20 @@
 
 const {CC, Ci, Cu, Cc} = require("chrome");
 
 const ArrayBufferInputStream = CC("@mozilla.org/io/arraybuffer-input-stream;1",
                                   "nsIArrayBufferInputStream");
 const BinaryInputStream = CC("@mozilla.org/binaryinputstream;1",
                              "nsIBinaryInputStream", "setInputStream");
 
+loader.lazyServiceGetter(this, "gActivityDistributor",
+                         "@mozilla.org/network/http-activity-distributor;1",
+                         "nsIHttpActivityDistributor");
+
 const {XPCOMUtils} = require("resource://gre/modules/XPCOMUtils.jsm");
 const {setTimeout} = Cu.import("resource://gre/modules/Timer.jsm", {});
 
 /**
  * Construct a new nsIStreamListener that buffers data and provides a
  * method to notify another listener when data is available.  This is
  * used to throttle network data on a per-channel basis.
  *
@@ -27,16 +31,18 @@ const {setTimeout} = Cu.import("resource
  * @param {NetworkThrottleQueue} queue the NetworkThrottleQueue to
  *        which status changes should be reported
  */
 function NetworkThrottleListener(queue) {
   this.queue = queue;
   this.pendingData = [];
   this.pendingException = null;
   this.offset = 0;
+  this.responseStarted = false;
+  this.activities = {};
 }
 
 NetworkThrottleListener.prototype = {
   QueryInterface:
     XPCOMUtils.generateQI([Ci.nsIStreamListener, Ci.nsIInterfaceRequestor,
                            Ci.nsISupports]),
 
   /**
@@ -128,26 +134,94 @@ NetworkThrottleListener.prototype = {
     if (bytesPermitted === count) {
       this.pendingData.shift();
       done = true;
     } else {
       this.pendingData[0].count -= bytesPermitted;
     }
 
     this.offset += bytesPermitted;
+    // Maybe our state has changed enough to emit an event.
+    this.maybeEmitEvents();
+
     return {length: bytesPermitted, done};
   },
 
   /**
    * Return the number of pending data requests available for this
    * listener.
    */
   pendingCount: function () {
     return this.pendingData.length;
   },
+
+  /**
+   * This is called when an http activity event is delivered.  This
+   * object delays the event until the appropriate moment.
+   */
+  addActivityCallback: function (callback, httpActivity, channel, activityType,
+                                 activitySubtype, timestamp, extraSizeData,
+                                 extraStringData) {
+    let datum = {callback, httpActivity, channel, activityType,
+                 activitySubtype, extraSizeData,
+                 extraStringData};
+    this.activities[activitySubtype] = datum;
+
+    if (activitySubtype ===
+        gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_COMPLETE) {
+      this.totalSize = extraSizeData;
+    }
+
+    this.maybeEmitEvents();
+  },
+
+  /**
+   * This is called for a download throttler when the latency timeout
+   * has ended.
+   */
+  responseStart: function () {
+    this.responseStarted = true;
+    this.maybeEmitEvents();
+  },
+
+  /**
+   * Check our internal state and emit any http activity events as
+   * needed.  Note that we wait until both our internal state has
+   * changed and we've received the real http activity event from
+   * platform.  This approach ensures we can both pass on the correct
+   * data from the original event, and update the reported time to be
+   * consistent with the delay we're introducing.
+   */
+  maybeEmitEvents: function () {
+    if (this.responseStarted) {
+      this.maybeEmit(gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_START);
+      this.maybeEmit(gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_HEADER);
+    }
+
+    if (this.totalSize !== undefined && this.offset >= this.totalSize) {
+      this.maybeEmit(gActivityDistributor.ACTIVITY_SUBTYPE_RESPONSE_COMPLETE);
+      this.maybeEmit(gActivityDistributor.ACTIVITY_SUBTYPE_TRANSACTION_CLOSE);
+    }
+  },
+
+  /**
+   * Emit an event for |code|, if the appropriate entry in
+   * |activities| is defined.
+   */
+  maybeEmit: function (code) {
+    if (this.activities[code] !== undefined) {
+      let {callback, httpActivity, channel, activityType,
+           activitySubtype, extraSizeData,
+           extraStringData} = this.activities[code];
+      let now = Date.now() * 1000;
+      callback(httpActivity, channel, activityType, activitySubtype,
+               now, extraSizeData, extraStringData);
+      this.activities[code] = undefined;
+    }
+  },
 };
 
 /**
  * Construct a new queue that can be used to throttle the network for
  * a group of related network requests.
  *
  * meanBPS {Number} Mean bytes per second.
  * maxBPS {Number} Maximum bytes per second.
@@ -178,16 +252,17 @@ NetworkThrottleQueue.prototype = {
   },
 
   /**
    * A helper function that lets the indicating listener start sending
    * data.  This is called after the initial round trip time for the
    * listener has elapsed.
    */
   allowDataFrom: function (throttleListener) {
+    throttleListener.responseStart();
     this.pendingRequests.delete(throttleListener);
     const count = throttleListener.pendingCount();
     for (let i = 0; i < count; ++i) {
       this.downloadQueue.push(throttleListener);
     }
     this.pump();
   },