Profiler Script

[Sam Moffatt]

One of the scripts I use a lot is my profiler. I use it to figure out timing data for how long something takes for my scripts. It’s useful for understanding where your bottlenecks are in code and for figuring out what the true slow downs are.

If you look at the very bottom of the script, there is an example/test for the script so you can see how it works. I use this with a Script Manager form which makes including easy like this:

document.getFormNamed('Script Manager').runScriptNamed('Profiler');

Due to the way the tests are coded, you want to define a variable called PARENT_SCRIPT to prevent the test from firing when being included. Generally I do this in the format of Form Name::Script Name, e.g.:

var PARENT_SCRIPT = 'Boxes::Bulk Add To Box';

Using it is easy once you’ve included it:

profiler.start('Start time');
...
your code that does stuff!
...
profiler.end();

Profiler internally uses a stack so end closes the most recent start. If you do a profiler.dump() you will get back a string with the profiling information formatted with indentation. Here is a copy of the test running as an example:

24/2/20, 9:59:19 pm / Script Manager / Profiler
Caught expected error from dump: Error: Profiler imbalance: started called 1 more times than end.
Uneven profiler.end called (are you missing a start?)
Dump called with index 7 and indent 0
0ms  	Test 1
    0ms  	Test 2
    0ms  	Test 3
        0ms  	Test 4
0ms  	Function start
    0ms  	Complex logic
0ms  	Mismatch

Here’s the full script:

// ========== Profiler Start ========== //
// NAME: Profiler
// VERSION: 1.0.0
/**
 * Profiler module stores timing data.
 */
if (profiler == undefined)

var profiler = (function() {
	let stack = [];
	let entries = [];
	let index = 0;
	let indent = 0;
	let current = undefined;
	return {
		custom: function(start, end, message)
		{
			entries[index] = {'start': start, 'end': end, 'message': message, 'index': index, 'indent': indent};
			index++;
		},
		/**
		 * Start a timer.
		 *
		 * Takes a <code>message</code> and adds it to the internal <code>logdata</code> variable
		 *   and also logs it to the console with a timestamp.
		 */
		start: function(message)
			{
				let now = new Date();
				stack.push({'start': now.getTime(), 'message': message, 'index': index, 'indent': indent});
				index++;
				indent++;
			},

		/**
		 * Log an error
		 *
		 * Takes a <code>message</code> and <code>error</code> object and then formats into an error
		 *   via <code>logMessage</code>.
		 */
		end: function(endCount = 1)
			{
				for (let i = 0; i < endCount; i++)
				{
					let now = new Date();
					let entry = stack.pop();
					if (entry)
					{
						entry['end'] = now.getTime();
						entries[entry.index]= entry;
						indent--;
					}
					else
					{
						console.log('Uneven profiler.end called (are you missing a start?)');
					}
				}
			},

		/**
		 * Get the internal log buffer
		 *
		 * Returns the raw log buffer to output elsewhere.
		 */
		dump: function(autoClose = true)
			{
				let returnValue = [];
				returnValue.push(<code>Dump called with index ${index} and indent ${indent}</code>);
				let dumpIndent = indent;
				
				if (indent > 0)
				{
					if (!autoClose)
					{
						throw Error("Profiler imbalance: started called " + indent + " more times than end.");
					}
					else
					{
						// Close out any mismatched items.
						this.end(indent);
					}
				}
				
				let entry = null;
				for(entry of entries)
				{
					let message = (entry.end - entry.start) + 'ms  \t' + entry.message;
					returnValue.push(message.padStart(message.length + (entry.indent * 4)));
				}
				return returnValue.join('\n');
			},

		/**
		 * Clear the internal state.
		 */
		reset: function()
			{
				stack = [];
				entries = [];
				index = 0;
				indent = 1;
			}
	}
})();

// Testing section. Fake guard for testing.
if (typeof PARENT_SCRIPT === 'undefined')
{
	profiler.start('Test 1');
		profiler.start('Test 2');
		profiler.end();
		profiler.start('Test 3');
			profiler.start('Test 4');
			profiler.end();
		profiler.end();
	profiler.end();
	profiler.start('Function start');
	profiler.start('Complex logic');
	profiler.end(2);
	profiler.start('Mismatch');
	try 
	{
		profiler.dump(false);
	}
	catch (e)
	{
		console.log('Caught expected error from dump: ' + e);
	}
	// Call end one too many times.
	profiler.end(2);
	
	console.log(profiler.dump());
	profiler.reset();
}
// ========== Profiler End ========== //

Latest version of this script is available on GitHub: https://github.com/pasamio/tftools/blob/master/scripts/js/profiler.js

[Author]

Posts