Performance Profiling

Overview

Performance profiling can be used to find out which parts of your APL code take the most time to execute, or are executed most often, and so helps you to determine which functions to concentrate on when optimising performance. You can view the performance data in a number of different ways, and easily 'drill down' to get more detail on exactly where execution time is spent. You can either use the very easy menu-based profiling described below, or for more detailed control use ⎕PROFILE .

Profiling using the Tools menu

For simple profiling you can enable profiling through the APLX Tools menu. You then run the code to be profiled. When the code completes and APLX returns to desktop calculator mode, the profile is automatically shown in a Profile window.

When you select 'Performance Profiling' from the Tools menu, APLX brings up a dialog which offers you a choice of different methods for measuring the execution time:

Depending on which platform you are using, one or more of the timing methods may not be available. For example, earlier versions of Windows cannot measure the number of CPU cycles used by an application. If the method specified is not available it will be disabled in the dialog. Measuring CPU cycles, if available, usually gives the most accurate results. (See the description of ⎕PROFILE for more details on the different measures.)

Once you click OK on this dialog, profiling is enabled. You then run your APL code (a function, which in turn will typically call many other functions, and can ask for input from the user as part of its operation). As soon as the function finally completes or is interrupted, and APL returns to desk calculator mode, profiling is automatically disabled and the results window will open.

In this example (based on the HELPOBJECTS workspace supplied with APLX in library 10), we have executed a function called RUN which has created various graphics objects in a rotating pattern, and displayed them. On completion, the following window opens:

As you can see, the results are displayed on five tabs. The first tab ("By Line") tells you which individual function lines have taken the most CPU (or elapsed) time, as shown above. They are initially sorted with the one which has taken the most time first, but you can change the sort criteria by clicking on the header of a column.

CPU usage by line

In our example, the function line which has been most CPU-intensive is line 6 of SHAPE.Rotate, i.e. the Rotate method of the SHAPE class. This is highlighted in red in the above picture. As a convenience, the corresponding line of code is shown in the second column; you will see that it is an inner product B+.×MAT (highlighted in green). This line has been called 13,646 times, and accounts for 37.63% of the total execution time, or in absolute terms 7.797 billion CPU cycles (highlighted in blue in the picture). The next two most CPU-intensive lines were lines 7 and 13 of the SHAPE.Draw method, which took a further 10.94% and 10.29% of the total execution time respectively. In other words, nearly 60% of the total execution time was spent in just three lines of the application. Clearly, therefore, if you were wanting to optimise the code, you would see if you can reduce the number of times these critical lines are executed, or write them in a more efficient way.

The critical information is usually in the column shown as 'Self Only'. This relates to the CPU usage for the line itself, excluding any functions called by the line. The next column ('Self+Children') displays the time taken both in the line itself and in any functions called. In our example, line 12 of STAR.GetPolygon has taken 39.34% of the total time, if you include the functions called by it, but only 1.79% was spent in STAR.GetPolygon[12] itself (highlighted in brown). In fact, most of that time was actually spent in the inner product highlighted at the top of the display.

By selecting the 'Graph By Line' tab, you can get an immediate graphical representation of which lines took the most CPU time:

CPU usage by function

As well as looking at individual lines, you can also get an overview of which functions (and methods) took the most time, by selecting the second tab of the results window ('By Function'):

From this display you can 'drill down' within a given function, to find out where the time is spent in that function, by clicking on the twist-down by the function name:

The 'Graph By Function' tab shows the overview by function as a pie chart.

CPU usage by Call Chain

The third way of looking at the data is by call chain. This is best shown by our example:

This shows that, unsurprisingly, 100% of the time was spent in our top-level function RUN and in all the functions called by it. We can now use the twist-downs to drill down into the the hierarchies of calls to see how that time was divided up:

Saving the profiling data as a web page

As well as looking at the data in the APLX window, you can select 'Save As Web Page' from the File menu. This saves a complete report (either as a summary of the most important items only, or of the whole application), as a web page which you can load in any standard browser.