Add performance measurement features

This is an experimental module to help us measure the performance of
the refresh cycle and the filter mechanism. Not intended to replace the
performance measurement features in browser developer tools, just to
make it easier to automate performance checks cross-browser.

The immediate purpose is to help in refactoring the filter mechanism.
The recent change to encapsulate the wiki store “tiddlers” object has
hurt the performance of filters, and it’s going to be helpful to have
decent measurements while refactoring that code.

I’m still not convinced that this stuff should be in the core, and may
well end up removing it after the present refactoring cycle.

core/modules/filters.js

@@ -218,14 +218,14 @@ exports.compileFilter = function(filterString) {
 		})());
 	});
 	// Return a function that applies the operations to a source array/hashmap of tiddler titles
-	return function(source,currTiddlerTitle) {
+	return $tw.perf.measure("filter",function filterFunction(source,currTiddlerTitle) {
 		source = source || self.getAllTitles();
 		var results = [];
 		$tw.utils.each(operationFunctions,function(operationFunction) {
 			operationFunction(results,source,currTiddlerTitle);
 		});
 		return results;
-	};
+	});
 };
 
 })();

core/modules/startup.js

@@ -12,6 +12,9 @@ This is the main application logic for both the client and server
 /*global $tw: false */
 "use strict";
 
+// Set to `true` to enable performance instrumentation
+var PERFORMANCE_INSTRUMENTATION = false;
+
 var widget = require("$:/core/modules/widgets/widget.js");
 
 exports.startup = function() {
@@ -32,6 +35,8 @@ exports.startup = function() {
 	$tw.modules.applyMethods("wikimethod",$tw.Wiki.prototype);
 	$tw.modules.applyMethods("tiddlerdeserializer",$tw.Wiki.tiddlerDeserializerModules);
 	$tw.macros = $tw.modules.getModulesByTypeAsHashmap("macro");
+	// Set up the performance framework
+	$tw.perf = new $tw.Performance(PERFORMANCE_INSTRUMENTATION);
 	// Set up the parsers
 	$tw.wiki.initParsers();
 	// Set up the command modules
@@ -199,22 +204,24 @@ exports.startup = function() {
 		$tw.styleElement = document.createElement("style");
 		$tw.styleElement.innerHTML = $tw.styleContainer.textContent;
 		document.head.insertBefore($tw.styleElement,document.head.firstChild);
-		$tw.wiki.addEventListener("change",function(changes) {
+		$tw.wiki.addEventListener("change",$tw.perf.report("styleRefresh",function(changes) {
 			if($tw.styleWidgetNode.refresh(changes,$tw.styleContainer,null)) {
 				$tw.styleElement.innerHTML = $tw.styleContainer.textContent;
 			}
-		});
+		}));
 		// Display the PageMacros, which includes the PageTemplate
 		var templateTitle = "$:/core/ui/PageMacros",
 			parser = $tw.wiki.parseTiddler(templateTitle);
-		$tw.pageWidgetNode = $tw.wiki.makeWidget(parser,{document: document, parentWidget: $tw.rootWidget});
-		$tw.pageContainer = document.createElement("div");
-		$tw.utils.addClass($tw.pageContainer,"tw-page-container");
-		document.body.insertBefore($tw.pageContainer,document.body.firstChild);
-		$tw.pageWidgetNode.render($tw.pageContainer,null);
-		$tw.wiki.addEventListener("change",function(changes) {
+		$tw.perf.report("mainRender",function() {
+			$tw.pageWidgetNode = $tw.wiki.makeWidget(parser,{document: document, parentWidget: $tw.rootWidget});
+			$tw.pageContainer = document.createElement("div");
+			$tw.utils.addClass($tw.pageContainer,"tw-page-container");
+			document.body.insertBefore($tw.pageContainer,document.body.firstChild);
+			$tw.pageWidgetNode.render($tw.pageContainer,null);
+		})();
+		$tw.wiki.addEventListener("change",$tw.perf.report("mainRefresh",function(changes) {
 			$tw.pageWidgetNode.refresh(changes,$tw.pageContainer,null);
-		});
+		}));
 		// Fix up the link between the root widget and the page container
 		$tw.rootWidget.domNodes = [$tw.pageContainer];
 		$tw.rootWidget.children = [$tw.pageWidgetNode];

core/modules/utils/performance.js

@@ -0,0 +1,62 @@
+/*\
+title: $:/core/modules/utils/performance.js
+type: application/javascript
+module-type: global
+
+Performance measurement.
+
+\*/
+(function(){
+
+/*jslint node: true, browser: true */
+/*global $tw: false */
+"use strict";
+
+function Performance(enabled) {
+	this.enabled = !!enabled;
+	this.measures = {}; // Hashmap of current values of measurements
+	this.logger = new $tw.utils.Logger("performance");
+}
+
+/*
+Wrap performance reporting around a top level function
+*/
+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) + "ms");
+			for(var m in self.measures) {
+				self.logger.log("+" + m + ": " + self.measures[m] + "ms");
+			}
+			return result;
+		};
+	} else {
+		return fn;
+	}
+};
+
+/*
+Wrap performance measurements around a subfunction
+*/
+Performance.prototype.measure = function(name,fn) {
+	var self = this;
+	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);
+			return result;
+		};
+	} else {
+		return fn;
+	}
+};
+
+exports.Performance = Performance;
+
+})();