There are plenty of good reasons for wanting to record accurately-timed events in an app which you use. You may need records so that you can bill clients according to time spent on certain activities. You might be investigating a bug or error in a script. This article explores an easy way of instrumenting documents in Tinderbox and Storyspace to record and analyse user actions in great detail.

This scenario supposes that you have authored a Tinderbox or Storyspace document, and want to test it with users. You want to examine which notes (or writing spaces) the user visits, in which order, and how long they dwell on each. It is simple to do this, using two free tools available from here, together with a spreadsheet or other app to analyse the results.

What you need

• macOS Sierra, preferably the current version. This uses log features which are not available on El Capitan or earlier.
• Consolation version 2, the latest release, from the Downloads item in the menu above. This does not work with version 1.
• Blowhole, the latest release, from the Downloads item in the menu above.
• Storyspace and/or Tinderbox. I have tested this with Storyspace 3.3 and Tinderbox 7.0.1. Previous versions may also work.
• Microsoft Excel, Apple’s Numbers, or another app capable of importing CSV files.
• My Fall of Icarus document, available here: FallOfIcarus2 or you can create your own using this tutorial.

To run the full demonstration, including browsing the document and data analysis, should take less than an hour from scratch.

Setting up

First install Blowhole using the Installer package supplied. If you have problems with that, you can manually install it from Terminal’s command line, in /usr/local/bin. You’ll need root privileges to do that, so the command will be prefaced by sudo. Blowhole has a simple text readme file which explains what it does. It can only be run from the command line, or in scripts calling it as a command, and has no other user interface.

Move Consolation to the folder in which you keep apps, normally the main Applications folder.

Principles

The example document is an old tutorial project from this blog, which looks at paintings telling the story of Daedalus and Icarus from Ovid’s Metamorphoses. You can use any Storyspace or Tinderbox document in which you can run a macOS terminal command using a script such as
runCommand("/usr/local/bin/blowhole -s "+$myID)
where $myID is an attribute with a numeric value. You could alternatively hard-code numbers, such as in
runCommand("/usr/local/bin/blowhole -s 42")

macOS Sierra incorporates a new and very high-performance log system which can record entries with a resolution of a nanosecond, and an accuracy of around 10 microseconds. It is also used to coping with very high volumes of traffic: it is usual for thousands of entries to be made in the log every minute. Adding a few of your own is not going to affect macOS in the slightest.

Blowhole is a simple command tool which does one job when it is run: it writes an entry into Sierra’s new log. Your Tinderbox/Storyspace document can thus make custom log entries automatically, using a script.

Although Sierra’s new log is enormously capable and powerful, retrieving entries from it has been very difficult. Over the last few weeks I have developed a free tool, Consolation, which does just that. What is more, it can now process log entries into a form which can be imported into many apps such as spreadsheets, in which you can analyse those entries.

Instrumenting a Tinderbox/Storyspace document

Every note (writing space) in Tinderbox/Storyspace has a unique integer ID which is accessible as the read-only attribute $ID. However it is a large number, and somewhere between that and the log it gets mutilated, so it is better to label the notes that you want to track with a smaller number of your own. This is easily done by creating a user attribute which I have called somewhat unimaginatively $myID.

This is best done in the prototype of the notes which you want to track, making that a key attribute for that prototype. In my case, I have set it for the prototype for notes containing text, and that for paintings. Ensure that this attribute is a number, and make it sequential: Tinderbox/Storyspace will then automatically assign a unique number to each note made from those prototypes.

The next task is to build in a script which will call Blowhole to write a note’s number out to the log at an appropriate moment. In Storyspace, this is simple: again setting this for each prototype to be tracked, add an OnVisit action reading
runCommand("/usr/local/bin/blowhole -s "+$myID)

Although Tinderbox does not expose this attribute in the same way, you can still set the $OnVisit attribute with that script, and it is still honoured and run when the note is selected.

Now each note with a $myID value and that OnVisit script will trigger the script, which calls Blowhole to make an entry in the log whenever you select or enter it.

You could equally write a different number to the log for a different purpose: provided that you pass an integer value in the same way, Blowhole should write that into the log whenever that script is run.

Testing it out

Having saved your document, or using the Fall of Icarus hypertext provided, it is time to test the system out. In Tinderbox or Storyspace, open that document, making a note of the clock time on your computer when you do so. You will use that later to narrow the period over which you will extract log entries.

Now browse the document, and work through it at a steady pace, as if using it normally. Once you have finished, close the document, and open Consolation.

When Consolation starts up, it usually does so without opening any windows. Use the New command in the File menu to open a new window.

Set the controls up similarly to this:

• On the top line Filter, select the radio button for pattern (below). This sets the app to filter log entries according to the predicate which you are going to set up in the line below those three radio buttons.
• On the next line with popup menus, set the first popup to subsystem, leave the next at ==, and type in co.eclecticlight.blowhole in the text box as shown. This will select only those log entries which come from Blowhole, as determined by its app signature.
• Further down, on the line Style, ensure that the default settings are set, with the radio button set to syslog, and the box to include info messages is checked (ticked).
• Further down again, on the line Period, set the number next to that to 0 (zero) and press the Tab or Return key to confirm that (if you don’t, the change from 2 will not be recognised).
• On that same line, edit the Start time to slightly before that when you started testing the document out. Ensure you enter it in HH:MM:SS format, using the 24-hour clock. The End time is set automatically when you open the window, and should therefore be well after you finished using the document.

Check those settings against those above, and click the Run command button. After a brief pause, the bottom two text areas should contain output text. The first (on grey) shows the command which Consolation submitted, and is here for interest only. The bottom scrolling panel should show the log entries during your short test, in a format similar to that shown above.

The log format used here is concise but not sufficiently detailed for further analysis. To export the log extract for another app to use, you must change the Style setting from syslog to json. Do that now, and without altering any of the other controls, click the Run command button again.

The bottom scrolling text panel should now be filled with more copious entries in standard JSON format, which is harder to read. However, the button to the right of the Run command button will now have changed from N/A to Export. To export your log extract in CSV format, click that button.

The contents of the bottom text panel are transformed to the lines of CSV data ready to import into Excel or whatever. Save these to a text file using the Save command in the File menu.

The final step is to import that text file into Microsoft Excel, or whatever you are going to use for data analysis. Here I will take you through the steps for import into Excel, which shows the principles involved. If you want to import the data into Apple’s Numbers, you must rename the text file with the extension .csv instead of .text for it to recognise its content properly, although that makes little difference to Excel.

Open Excel, let it open a new blank spreadsheet, and use the Import command in the File menu to select and open the text file saved from Consolation. Excel will then step you through its Import Wizard. In most of this, you can leave the options set to the defaults, but there are two important steps which are slightly different.

The file exported by Consolation is traditional CSV, which separates the values using a comma delimiter. When Excel offers to use Tab delimiters, uncheck the Tab option and check the Comma.

The other non-default option is to ensure that Excel imports the timestamp column as Text and not General. If it tries the latter, it is likely to get a little too smart for itself, and make a mess of converting those time values into times.

The data exported from the logs are very extensive, and most of the columns are of no interest to you. I have here deleted all the others, leaving just the datestamp, timestamp, machTimestamp, and eventMessage.

The first two of these should be self-evident. The very large integers given in machTimestamp are system ticks, which are in nanoseconds – there are a billion (thousand million) for every second. Dividing them by 10^9 converts to decimal seconds. The eventMessage is the number which Tinderbox/Storyspace wrote to the log, in my case the value of $myID. It is then easy to work out, for example, how long you spent reading or looking at each of the notes, according to the note numbers.

How precise are the times given?

There is inevitably a small time lag between your selecting a new note, and the time of that action being entered into the log. One way to get an estimate of that is to call the script invoking Blowhole repeatedly, and to work out the time that each call takes, as that should account for most of the lag.

Using this script, I got Storyspace to write five consecutive log entries for one visit. Typically, the lag time between those calls ranged from 0.04 to 0.1 second, with most around 0.04 to 0.05 seconds. So you should expect the log times to be accurate to better than 0.1 second. Unless you are trying to measure response or reaction times, I think those are quite sufficient for anything that you might want to use this system for.

Blowhole also has a command option for it to write a series of log entries out as quickly as possible. Testing on this iMac shows that the fastest response times are less than 15 microseconds, and typically around 2-3 microseconds: Sierra’s new logs are very quick in use indeed!

Further information

Consolation does a great deal more with your logs, and its documentation explains some of the other things that you can do with it.

Currently, Blowhole can only write integer numbers to the log, because of limitations in the new log system and a bug (not in Blowhole) which prevents it from passing arbitrary strings of text. When those are fixed, it should be able to write much more informative entries too.

Rights

Consolation and Blowhole are free to use, and free to distribute for non-commercial purposes. You are also welcome to use them in commercial environments for testing, etc. However if you wish to supply either or both as part of a commercial arrangement (one in which you are paid), please contact me first.

I hope that you find them useful.