Reduce client logger overhead (#960)

* Add a benchmark suite for the client logger

We do a lot of logging in the browser, so it's worth measuring overhead.

* Lower client logger overhead

* Lower classification overhead

* Tuple batching

* No transport short circuit

* Lazy args init

packages/react-server/core/__bench__/loggingClient.js

@@ -0,0 +1,50 @@
+import {Suite} from "benchmark";
+import logging from "../logging/client";
+
+const n = 1000;
+
+let enclosedDeferred;
+
+class NoopTransport {
+	constructor() {
+		this.name = 'noop';
+		this.level = 'info';
+	}
+
+	log(level, msg, meta, callback) {
+		if (meta === n || meta.ms === n) {
+			enclosedDeferred.resolve();
+		}
+		callback(null, true);
+	}
+}
+
+class NoopTimeTransport extends NoopTransport {
+	constructor() {
+		super();
+		this.level = 'fast';
+	}
+}
+
+const noTransportLogger   = logging.getLogger({name: "noTransports"});
+const noopTransportLogger = logging.getLogger({name: "noopTransport"});
+
+noopTransportLogger.add(NoopTransport)
+noopTransportLogger.timeLogger.add(NoopTimeTransport)
+
+function run(logger, method) {
+	return function(deferred) {
+		enclosedDeferred = deferred;
+		for (var i = 1; i <= n; i++) {
+			logger[method]("test", i);
+		}
+	}
+}
+
+new Suite()
+	.add("info no transports",  run(noTransportLogger,   'info'))
+	.add("info noop transport", run(noopTransportLogger, 'info'), { defer: true })
+	.add("time no transports",  run(noTransportLogger,   'time'))
+	.add("time noop transport", run(noopTransportLogger, 'time'), { defer: true })
+	.on('cycle', (v) => console.log(v.target.name + "\t" + v.target.stats.mean))
+	.run()

packages/react-server/core/logging/client.js

@@ -40,6 +40,27 @@ var monochrome = typeof _console.log == "object";
 // We'll use a noop.
 var noop = () => {};
 
+var transportQueue = [];
+
+var transportTimer;
+
+function runTransports() {
+	var batch = transportQueue;
+	transportQueue = [];
+	transportTimer = null;
+	for (var i = 0; i < batch.length; i++) {
+		const [transport, level, msg, meta] = batch[i];
+		transport.log(level, msg, meta, noop);
+	}
+}
+
+function scheduleTransport(tuple) {
+	transportQueue.push(tuple);
+	if (!transportTimer) {
+		transportTimer = setTimeout(runTransports, 0);
+	}
+}
+
 var makeLogger = function(group, opts){
 	var config = common.config[group]
 
@@ -49,19 +70,21 @@ var makeLogger = function(group, opts){
 		level: config.baseLevel,
 		log: function(level, msg, meta){
 
+			if (this.transports.length) {
+				this.transports.forEach(transport => {
+					if (config.levels[level] > config.levels[transport.level]) return;
+					scheduleTransport([transport, level, msg, meta]);
+				});
+			}
+
+			if (config.levels[level] > config.levels[this.level]) return;
+
 			// We want an array of arguments to apply to
 			// `console.log` so we don't trail an `undefined` when
 			// `meta` isn't passed.
 			var args = [msg];
 			if (meta !== void 0) args.push(meta);
 
-			this.transports.forEach(transport => {
-				if (config.levels[level] > config.levels[transport.level]) return;
-				setTimeout(transport.log.bind(transport, level, msg, meta, noop), 0);
-			});
-
-			if (config.levels[level] > config.levels[this.level]) return;
-
 			clog(level).apply(
 				_console,
 				(monochrome?[`${level}: [${opts.name}]`]:[
@@ -84,8 +107,8 @@ var makeLogger = function(group, opts){
 		// note that this has to be an ES-5 style function and cannot be an arrow function
 		// because arguments doesn't bind to the arrow function's arguments; it would bind
 		// to makeLogger's arguments.
-		logger[level] = function(){
-			logger.log.apply(logger, [level].concat([].slice.call(arguments)));
+		logger[level] = function(a, b, c){
+			logger.log(level, a, b, c);
 		}
 	});
 

packages/react-server/core/logging/stats.js

@@ -100,29 +100,49 @@ function wrapLogger(getLoggerForConfig, opts) {
 
 // This is used for classifying `time` and `gauge` values.
 function makeThresholdsSieve(options, defaults) {
+
+	if (!options) options = {};
+
+	// Pre-apply defaults.
+	Object.keys(defaults).forEach(key => options[key] || (options[key] = defaults[key]));
+
 	return (key, overrides) => {
-		// Sure would be nice to have Array.prototype.find here.
-		if ((overrides||{})[key] !== void 0) return overrides[key];
-		if ((options  ||{})[key] !== void 0) return options  [key];
-		return defaults[key];
+		if (overrides && overrides[key] !== void 0) return overrides[key];
+		return options[key];
 	}
 }
 
 function makeTimeClassifier(opts) {
 	var thresholds = makeThresholdsSieve(opts.timing, DEFAULT_TIME_THRESHOLDS);
+	var fast = thresholds('fast');
+	var fine = thresholds('fine');
 	return (ms, o) => {
-		if (ms <= thresholds('fast', o)) return 'fast';
-		else if (ms <= thresholds('fine', o)) return 'fine';
-		else                                  return 'slow';
+		if (o) {
+			if      (ms <= thresholds('fast', o)) return 'fast';
+			else if (ms <= thresholds('fine', o)) return 'fine';
+			else                                  return 'slow';
+		} else {
+			if      (ms <= fast) return 'fast';
+			else if (ms <= fine) return 'fine';
+			else                 return 'slow';
+		}
 	}
 }
 
 function makeGaugeClassifier(opts) {
 	var thresholds = makeThresholdsSieve(opts.gauge, DEFAULT_GAUGE_THRESHOLDS);
+	var lo = thresholds('lo');
+	var hi = thresholds('hi');
 	return (val, o) => {
-		if (val <= thresholds('lo', o)) return 'lo';
-		else if (val >= thresholds('hi', o)) return 'hi';
-		else                                 return 'ok';
+		if (o) {
+			if      (val <= thresholds('lo', o)) return 'lo';
+			else if (val >= thresholds('hi', o)) return 'hi';
+			else                                 return 'ok';
+		} else {
+			if      (val <= lo) return 'lo';
+			else if (val >= hi) return 'hi';
+			else                return 'ok';
+		}
 	}
 
 }