Profiling in the Lively Kernel

In addition to being able to change its code and that of its applications on the fly, the Lively Kernel is able to take measurements on its operation and present the results in meaningful ways. This can aid greatly in understanding program logic and in improving performance of the Lively Kernel and its applications.

In order to engage this facility, it is necessary first to "enable profiling". This process wraps every method in the system with another method that builds a simulation of the execution stack, and instruments it with exact tallies as well as millisecond tick counts. The entire system can run with the wrappers in place, sending traceCall and traceReturn messages to the object named currentContext if not null.

Profiling from the user interface

There are two main ways to use the profiling facility once it is enabled. One is to trigger an activity from the user interface, the other is to do so programmatically. After enabling, a few new items will appear in the Tools menu. Two of these will arm profiling to start with the next mouseUp or mouseDown event. When the event, and any actions triggered by it, have completed, a printout of the collected statistics will be opened in a window on the screen. This process can be performed repeatedly until a "disable profiling" command restores the normal program structure.

Profiling programmatically

Profiling can also be initiated programmatically. For example, after enabling, you could execute:

• lively.lang.Execution.trace( RunArray?.test.curry([3, 1, 4, 1, 5, 9]), {threshold: 0} );

The first parameter is a function to be traced, and the optional second parameter controls various aspect of the trace process. See below for an explanation of these options.

As another example, one could inspect the Clock, and in its inspector execute:

• lively.lang.Execution.trace( this.setHands.bind(this) , {repeat: 10} );

Profiling options

The supported properties in the profiling options specification include the following. Note that the value following is the default if the property or the entire option is omitted.

property	value	default	effect
repeat:	number	1	executes the supplied function the given number of times before reporting statistics
threshold:	number	*	will suppress printout of any method invocation with ticks less than the given number
printToConsole:	boolean	false	if true, statistics will be printed to the console instead of in a window
sortBy:	"tally" or "ticks"	"ticks"	determines the order in which statistics are printed

Note (*) that the default threshold is 0 when sorting by ticks, and 1/100 of the total tick count when sorting by ticks.

In order to specify options when profiling from the user interface, install them in the hand with a statement of the form

• WorldMorph?.current().firstHand().profilingOptions = { sortBy: "tally" };

Reading the Profile Listing

The first profile report is fairly self-explanatory: it represents the entire execution graph during the profiling process. Each node in th graph is listed with the exact number of executions, and the number of millisecond ticks counts that elapsed between entry and exit of each method. Note that this is not an exact measure of time, since the millisecond clock progresses in discrete "ticks" but, over a reasonable sample, the values will be fairly representative.

Two pieces of information are difficult to infer from the execution graph: total time spent in methods that are called from many places, and the amount of time spent in the method itself, and not in those methods called from it. These statistics are presented in the leaf node summary that appears as the second part of the report. Here the tallies on each method are the totals for all invocations, and the tick counts are the those that occurred during execution of the method body itself.

Cautionary note

Always disable profiling when you are done. The method-wrapping process can interfere with other reflective features in the Lively Kernel and can lead to confusing results. Programming with JavaScript is already confusing enough, right?