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
diff --git a/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting.js b/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting.js
index e601b93..3e886d5 100644
--- a/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting.js
+++ b/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);
},
diff --git a/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting_test.html b/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting_test.html
index e78f49fb..8b85074 100644
--- a/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting_test.html
+++ b/polygerrit-ui/app/elements/core/gr-reporting/gr-reporting_test.html
@@ -264,7 +264,7 @@
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
));
});
diff --git a/polygerrit-ui/app/elements/gr-app.js b/polygerrit-ui/app/elements/gr-app.js
index 7acb680..b4aec99 100644
--- a/polygerrit-ui/app/elements/gr-app.js
+++ b/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);
+ },
});
})();
diff --git a/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface.js b/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface.js
index 3f25834..fa1ad11 100644
--- a/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface.js
+++ b/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});
+ }
},
/**
diff --git a/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface_test.html b/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface_test.html
index 0d25509..193d306 100644
--- a/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface_test.html
+++ b/polygerrit-ui/app/elements/shared/gr-rest-api-interface/gr-rest-api-interface_test.html
@@ -1392,5 +1392,18 @@
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>
