From e8d1fbba6c109ccbeaedc1b34e47677c0ada7529 Mon Sep 17 00:00:00 2001
From: Jeremy Ruston <jeremy@jermolene.com>
Date: Fri, 10 May 2019 15:56:01 +0100
Subject: [PATCH] Performance Instrumentation: Track execution times for
 individual filters

Fixes #3941
---
 core/modules/filters.js                       |  2 +-
 core/modules/utils/logger.js                  |  7 +++
 core/modules/utils/performance.js             | 43 +++++++++++++++----
 .../config/PerformanceInstrumentation.tid     |  2 +-
 .../tiddlers/PerformanceInstrumentation.tid   |  2 +-
 5 files changed, 45 insertions(+), 11 deletions(-)

diff --git a/core/modules/filters.js b/core/modules/filters.js
index fdad467d2..a1c4d8750 100644
--- a/core/modules/filters.js
+++ b/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
diff --git a/core/modules/utils/logger.js b/core/modules/utils/logger.js
index ee14c5b2b..f194d78b3 100644
--- a/core/modules/utils/logger.js
+++ b/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
 */
diff --git a/core/modules/utils/performance.js b/core/modules/utils/performance.js
index 3e7acfac3..51c8ebcfb 100644
--- a/core/modules/utils/performance.js
+++ b/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 {
diff --git a/core/wiki/config/PerformanceInstrumentation.tid b/core/wiki/config/PerformanceInstrumentation.tid
index ccae6842e..e4220f287 100644
--- a/core/wiki/config/PerformanceInstrumentation.tid
+++ b/core/wiki/config/PerformanceInstrumentation.tid
@@ -1,2 +1,2 @@
 title: $:/config/Performance/Instrumentation
-text: no
+text: yes
diff --git a/editions/dynaviewdemo/tiddlers/PerformanceInstrumentation.tid b/editions/dynaviewdemo/tiddlers/PerformanceInstrumentation.tid
index ccae6842e..e4220f287 100644
--- a/editions/dynaviewdemo/tiddlers/PerformanceInstrumentation.tid
+++ b/editions/dynaviewdemo/tiddlers/PerformanceInstrumentation.tid
@@ -1,2 +1,2 @@
 title: $:/config/Performance/Instrumentation
-text: no
+text: yes