Performance Instrumentation: Track execution times for individual filters

Fixes #3941

core/modules/filters.js

@@ -270,7 +270,7 @@ exports.compileFilter = function(filterString) {
 		})());
 	});
 	// Return a function that applies the operations to a source iterator of tiddler titles
-	return $tw.perf.measure("filter",function filterFunction(source,widget) {
+	return $tw.perf.measure("filter: " + filterString,function filterFunction(source,widget) {
 		if(!source) {
 			source = self.each;
 		} else if(typeof source === "object") { // Array or hashmap

core/modules/utils/logger.js

@@ -33,6 +33,13 @@ Logger.prototype.log = function(/* args */) {
 	}
 };
 
+/*
+Log a structure as a table
+*/
+Logger.prototype.table = function(value) {
+	(console.table || console.log)(value);
+};
+
 /*
 Alert a message
 */

core/modules/utils/performance.js

@@ -14,10 +14,15 @@ Performance measurement.
 
 function Performance(enabled) {
 	this.enabled = !!enabled;
-	this.measures = {}; // Hashmap of current values of measurements
+	this.measures = {}; // Hashmap by measurement name of {time:, invocations:}
 	this.logger = new $tw.utils.Logger("performance");
+	this.showGreeting();
 }
 
+Performance.prototype.showGreeting = function() {
+	this.logger("Execute $tw.perf.log(); to see filter execution timings");
+};
+
 /*
 Wrap performance reporting around a top level function
 */
@@ -25,13 +30,9 @@ Performance.prototype.report = function(name,fn) {
 	var self = this;
 	if(this.enabled) {
 		return function() {
-			self.measures = {};
 			var startTime = $tw.utils.timer(),
 				result = fn.apply(this,arguments);
 			self.logger.log(name + ": " + $tw.utils.timer(startTime).toFixed(2) + "ms");
-			for(var m in self.measures) {
-				self.logger.log("+" + m + ": " + self.measures[m].toFixed(2) + "ms");
-			}
 			return result;
 		};
 	} else {
@@ -39,6 +40,29 @@ Performance.prototype.report = function(name,fn) {
 	}
 };
 
+Performance.prototype.log = function() {
+	var self = this,
+		totalTime = 0,
+		orderedMeasures = Object.keys(this.measures).sort(function(a,b) {
+			if(self.measures[a].time > self.measures[b].time) {
+				return -1;
+			} else if (self.measures[a].time < self.measures[b].time) {
+				return + 1;
+			} else {
+				return 0;
+			}
+		});
+	$tw.utils.each(orderedMeasures,function(name) {
+		totalTime += self.measures[name].time;
+	});
+	var results = []
+	$tw.utils.each(orderedMeasures,function(name) {
+		var measure = self.measures[name];
+		results.push({name: name,invocations: measure.invocations, totalTime: measure.time,percentTime: (measure.time / totalTime) * 100})
+	});
+	self.logger.table(results);
+};
+
 /*
 Wrap performance measurements around a subfunction
 */
@@ -47,9 +71,12 @@ Performance.prototype.measure = function(name,fn) {
 	if(this.enabled) {
 		return function() {
 			var startTime = $tw.utils.timer(),
-				result = fn.apply(this,arguments),
-				value = self.measures[name] || 0;
-			self.measures[name] = value + $tw.utils.timer(startTime);
+				result = fn.apply(this,arguments);
+			if(!(name in self.measures)) {
+				self.measures[name] = {time: 0, invocations: 0};
+			}
+			self.measures[name].time += $tw.utils.timer(startTime);
+			self.measures[name].invocations++;
 			return result;
 		};
 	} else {

core/wiki/config/PerformanceInstrumentation.tid

@@ -1,2 +1,2 @@
 title: $:/config/Performance/Instrumentation
-text: no
+text: yes

editions/dynaviewdemo/tiddlers/PerformanceInstrumentation.tid

@@ -1,2 +1,2 @@
 title: $:/config/Performance/Instrumentation
-text: no
+text: yes