Report RPC timings

When a RPC to a REST API endpoint with an anonymized URL info is timed,
also report that timing information through gr-reporting.

Because RPC timings are already logged with richer information that what
is reported, gr-reporting's report method gets an option to avoid
logging the report itself.

Change-Id: Ib5efbb72a6c97d8156f774e7baac9d19aa96d639

polygerrit-ui/app/elements/core/gr-reporting/gr-reporting.js

@@ -20,7 +20,8 @@
   // Latency reporting constants.
   const TIMING = {
     TYPE: 'timing-report',
-    CATEGORY: 'UI Latency',
+    CATEGORY_UI_LATENCY: 'UI Latency',
+    CATEGORY_RPC: 'RPC Timing',
     // Reported events - alphabetize below.
     APP_STARTED: 'App Started',
     PAGE_LOADED: 'Page Loaded',
@@ -170,7 +171,16 @@
       report.apply(this, args);
     },
 
-    defaultReporter(type, category, eventName, eventValue) {
+    /**
+     * The default reporter reports events immediately.
+     * @param {string} type
+     * @param {string} category
+     * @param {string} eventName
+     * @param {string|number} eventValue
+     * @param {boolean|undefined} opt_noLog If true, the event will not be
+     *     logged to the JS console.
+     */
+    defaultReporter(type, category, eventName, eventValue, opt_noLog) {
       const detail = {
         type,
         category,
@@ -178,6 +188,7 @@
         value: eventValue,
       };
       document.dispatchEvent(new CustomEvent(type, {detail}));
+      if (opt_noLog) { return; }
       if (type === ERROR.TYPE) {
         console.error(eventValue.error || eventName);
       } else {
@@ -186,7 +197,17 @@
       }
     },
 
-    cachingReporter(type, category, eventName, eventValue) {
+    /**
+     * The caching reporter will queue reports until plugins have loaded, and
+     * log events immediately if they're reported after plugins have loaded.
+     * @param {string} type
+     * @param {string} category
+     * @param {string} eventName
+     * @param {string|number} eventValue
+     * @param {boolean|undefined} opt_noLog If true, the event will not be
+     *     logged to the JS console.
+     */
+    cachingReporter(type, category, eventName, eventValue, opt_noLog) {
       if (type === ERROR.TYPE) {
         console.error(eventValue.error || eventName);
       }
@@ -196,9 +217,9 @@
             this.reporter(...args);
           }
         }
-        this.reporter(type, category, eventName, eventValue);
+        this.reporter(type, category, eventName, eventValue, opt_noLog);
       } else {
-        pending.push([type, category, eventName, eventValue]);
+        pending.push([type, category, eventName, eventValue, opt_noLog]);
       }
     },
 
@@ -208,8 +229,8 @@
     appStarted(hidden) {
       const startTime =
           new Date().getTime() - this.performanceTiming.navigationStart;
-      this.reporter(
-          TIMING.TYPE, TIMING.CATEGORY, TIMING.APP_STARTED, startTime);
+      this.reporter(TIMING.TYPE, TIMING.CATEGORY_UI_LATENCY,
+          TIMING.APP_STARTED, startTime);
       if (hidden) {
         this.reporter(PAGE_VISIBILITY.TYPE, PAGE_VISIBILITY.CATEGORY,
             PAGE_VISIBILITY.STARTED_HIDDEN);
@@ -226,8 +247,8 @@
       } else {
         const loadTime = this.performanceTiming.loadEventEnd -
             this.performanceTiming.navigationStart;
-        this.reporter(
-            TIMING.TYPE, TIMING.CATEGORY, TIMING.PAGE_LOADED, loadTime);
+        this.reporter(TIMING.TYPE, TIMING.CATEGORY_UI_LATENCY,
+            TIMING.PAGE_LOADED, loadTime);
       }
     },
 
@@ -344,7 +365,8 @@
      * @param {number} time The time to report as an integer of milliseconds.
      */
     _reportTiming(name, time) {
-      this.reporter(TIMING.TYPE, TIMING.CATEGORY, name, Math.round(time));
+      this.reporter(TIMING.TYPE, TIMING.CATEGORY_UI_LATENCY, name,
+          Math.round(time));
     },
 
     /**
@@ -395,6 +417,16 @@
       return timer.reset();
     },
 
+    /**
+     * Log timing information for an RPC.
+     * @param {string} anonymizedUrl The URL of the RPC with tokens obfuscated.
+     * @param {number} elapsed The time elapsed of the RPC.
+     */
+    reportRpcTiming(anonymizedUrl, elapsed) {
+      this.reporter(TIMING.TYPE, TIMING.CATEGORY_RPC, 'RPC-' + anonymizedUrl,
+          elapsed, true);
+    },
+
     reportInteraction(eventName, opt_msg) {
       this.reporter(INTERACTION_TYPE, this.category, eventName, opt_msg);
     },

polygerrit-ui/app/elements/core/gr-reporting/gr-reporting_test.html

@@ -264,7 +264,7 @@ limitations under the License.
         sandbox.stub(element, 'now').returns(42);
         element.pluginsLoaded();
         assert.isTrue(element.defaultReporter.calledWithExactly(
-            'timing-report', 'UI Latency', 'PluginsLoaded', 42
+            'timing-report', 'UI Latency', 'PluginsLoaded', 42, undefined
         ));
       });
 

polygerrit-ui/app/elements/gr-app.js

@@ -99,6 +99,7 @@
       'page-error': '_handlePageError',
       'title-change': '_handleTitleChange',
       'location-change': '_handleLocationChange',
+      'rpc-log': '_handleRpcLog',
     },
 
     observers: [
@@ -332,5 +333,15 @@
       console.log(`Please file bugs and feedback at: ${this._feedbackUrl}`);
       console.groupEnd();
     },
+
+    /**
+     * Intercept RPC log events emitted by REST API interfaces.
+     * Note: the REST API interface cannot use gr-reporting directly because
+     * that would create a cyclic dependency.
+     */
+    _handleRpcLog(e) {
+      this.$.reporting.reportRpcTiming(e.detail.anonymizedUrl,
+          e.detail.elapsed);
+    },
   });
 })();

polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface.js

@@ -163,6 +163,12 @@
      * @event auth-error
      */
 
+    /**
+     * Fired after an RPC completes.
+     *
+     * @event rpc-log
+     */
+
     properties: {
       _cache: {
         type: Object,
@@ -236,6 +242,10 @@
         elapsed + 'ms',
         req.anonymizedUrl || req.url,
       ].join(' '));
+      if (req.anonymizedUrl) {
+        this.fire('rpc-log',
+            {status, method, elapsed, anonymizedUrl: req.anonymizedUrl});
+      }
     },
 
     /**

polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface_test.html

@@ -1392,5 +1392,18 @@ limitations under the License.
         assert.isFalse(response.text.called);
       });
     });
+
+    test('_logCall only reports requests with anonymized URLss', () => {
+      sandbox.stub(Date, 'now').returns(200);
+      const handler = sinon.stub();
+      element.addEventListener('rpc-log', handler);
+
+      element._logCall({url: 'url'}, 100, 200);
+      assert.isFalse(handler.called);
+
+      element._logCall({url: 'url', anonymizedUrl: 'not url'}, 100, 200);
+      flushAsynchronousOperations();
+      assert.isTrue(handler.calledOnce);
+    });
   });
 </script>