Profile - Program Profiler
by Lewis G.Kirby

Is your Basic program not as fast as you would like? Want to tweak it to get that little bit of extra speed but don't know which part to attack first? Don't know which procedure to convert to machine code?

This application helps you to identify the performance bottlenecks in your Basic programs. No longer will you be halving the time one procedure takes only to find that it shaves a measly one percent off the total execution time of your program.

In outline, the application works as follows. Running the application installs the Profile icon on the icon bar. Drag a Basic program to the icon and a new Basic program will be generated in the same directory as this source program; its name will be the same as the source program except that the name will be followed by the tilde (~) character. This new program will, when run, produce profiling information indicating where the program's time is being spent. The information will appear in a file called "Prof" (once again in the same directory as the source program). An example follows this text. Diagrammatically this is what happens:

YourProg --> Profile --> YourProg~ --> Prof

The Output File "Prof"
----------------------
The output file shows how many times each procedure or function is invoked, how much time is spent in each routine, and how long per invocation. The "time" column shows the amount of time spent in the routine but excluding time spent in the routines it calls. In this way the total of this column gives correctly the total time spent in the program altogether, shown separately at the foot of the output. Routines which are not invoked are shown with entries "0", "0.00" and "--not called--", as shown for PROCerror in the example below.

Time spent not in any routine (typically the first few lines of code) is shown as the special pseudo-routine "-MAIN-". This should always have a count of exactly one and will always be present; for programs with neither procedures, functions, nor CALLs it will be the only routine.

Machine code is catered for, too. This will be shown as "CALL" in the first column, but instead of the name of the routine, the string following the CALL in the program text will be shown, but note that the algorithm for reading the string is not very clever, so the string may not be exactly as expected.

Note that the output file is always called "Prof"; if any results are to be kept you must rename this file or it will be overwritten.

How It Works
------------
The application works as follows. Bytes are transferred from the source file to the new file one by one, largely untouched. Extra code is inserted at the beginning and end of the program, at the start and end of each procedure and function, before and after each occurrence of CALL, before each occurrence of STOP, END, RUN or CHAIN and at the end of the program. As the application stands it also removes comments beginning with REM, but they can be included in the transformed file if required by changing the assignment of the variable remT% in PROCconst in !Profile.!RunImage (line 250) to "remT%=0". Empty lines are also removed (this does not include lines containing a single colon, for example), but can be included if required by commenting out the line "IF len%=0 ENDPROC" in PROCputLine (line 1670). Finally a chunk of code is appended to the transformed program; this is added by the procedure PROCappend.

The extra code inserted will, of course, affect the running time of the program, but steps have been taken in an attempt to ensure that such interference is kept to a minimum; the resulting profile will still, in any case, provide valuable bottleneck identification information. In order to avoid conflicts with variable names in the source program, the names of variables, procedures and functions added to the transformed program all begin with the "grave quote" (`) character. Most programmers avoid the use of this symbol in variable names, so there should be no conflicts. Note that Profile does not carry out any checks for such conflicts.

When the transformed program is executed, one of the first things it does is to create the file "Prof", using *Create, to ensure that the results can be recorded before attempting to gather them by executing further. "Prof" is initially of type Data (even if it already exists as another type); when the transformed program has terminated successfully and completed output to "Prof", it is converted to a file of type Text.

For the Technically Minded
--------------------------
As Profile processes each line of the source program it acts as a finite state machine. The initial state is 0, indicating start of statement; it also enters this state after finding ":", THEN, ELSE and after DEF PROCname(args) and DEF FNname(args) (with or without arguments). State 1 indicates that bytes are being processed and is the most common state. When DEF is found state 2 is entered, then state 3 when PROC or FN is found after that. State 4 indicates that the identifier is being read. If a left parenthesis is found here then state 5 is entered, indicating that the argument list is being processed; otherwise it re-enters state 0 immediately. State 6 indicates that CALL has been found, then state 7 while the address is being processed. If the "=" character is found while in states 0 or 4 then this indicates the end of a function definition. This or ENDPROC triggers "end of routine" code insertion, just as DEF PROC and DEF FN triggers "start of routine" code insertion. If a quote mark is found while in state 1 (it cannot be encountered anywhere else) then state 8 is entered until another is found; this is mainly to ensure that a character such as a colon found inside quote marks will be ignored for our purposes.

Restrictions
------------
There are several restrictions on the programs which can be transformed, but these are not expected to cause any difficulty:

- The file must be a tokenised Basic program (there is a limited check for this), and should preferably work correctly. There is a single check for syntax: that DEF is followed (after zero or more spaces) by PROC or FN.

- If RUN occurs in the source program then only the last RUN is logged.

- The only ways of exiting from the source program which can be recognized by Profile are END, STOP, RUN, CHAIN and simply "falling off" the end of the program. Any other ways (such as *Run) cannot be intercepted and profiling will fail. This also means that errors in the source program must be caught by using ON ERROR which terminates the program using END or STOP in the usual way. If the transformed program terminates in an unrecognized way then the "Prof" file will still be of type Data and will be empty. If the ON ERROR procedure terminates execution directly then that procedure's entry in "Prof" will be "--not called--"; therefore it is preferable to use the form ON ERROR PROCerror:END if possible. It is always preferable to terminate execution from MAIN for the purposes of Profile.

- TIME must not be assigned in the source program, since the extra code generated by Profile relies on it increasing correctly; there is a check for this. The code inserted by Profile does not, however, alter the value of TIME.

- Currently the source program should contain a maximum of 100 procedures, functions and CALLs; there is a check for this. If you need to change this limit, the variable maxR%, set in PROCvar, should be set higher; note that the higher the value chosen, the more memory is required by the transformed program.

- Currently the source program should have a maximum routine calling depth of 256. This can be changed if required by changing the value of maxD%, set in PROCvar. Once again, the higher the value chosen, then the more memory is required by the transformed program. Note that this cannot be checked by Profile - so beware!

Profiling Wimp Applications
---------------------------
When a Wimp application's program "!RunImage" is to be profiled, the transformed program is called "!RunImage~". Thus double-clicking on the application's icon will not invoke the transformed program. You could rename it to "!RunImage" (remembering to save the source program "!RunImage" first!), but often simply double-clicking on the new transformed Basic file will run the application satisfactorily.

Note in the example output file given below that the routine using the most time is PROCpoll - this is the routine which invokes the SWI call "Wimp_Poll". One must be careful in interpreting results here because time accumulated for this routine will include time spent by the Wimp serving other applications; in other words a routine such as this could indicate a large time even though the program has not actually spent the time executing this routine. In the example case the time for PROCpoll can be ignored. Tuning effort would therefore be most fruitfully directed towards PROCprocess.

Note also that data is only written to the file "Prof" when the transformed program terminates; in the case of an application this means that it must be quit (usually by selecting the appropriate option on the icon bar menu) before the file can be read. A "Prof" file which is not complete has type Data, as indicated above.

Errors
------
When an error occurs in Profile, the routine PROCerror is called. This smashes the hourglass and closes files where appropriate (note that there are two file handles used (fhIn% and fhOut%) which are always set to zero if the files are closed). The transformed file (if any) is deleted. The user is offered the choices "OK" and "Cancel". Choosing the second of these causes termination of the application; this should always be the choice if there are errors in Profile. Choosing "OK" leaves the application running and ready to accept further files; the internally-generated errors for which "OK" is an appropriate choice are as follows:

- "Object is a directory", "Object is an application", "File is not BASIC": the reasons for these are obvious.

- "Line nnn too long": the line nnn in the source program would become longer than 255 bytes when transformed; try splitting it.

- "TIME assign at line nnn": the sequence "TIME=" has been detected at line nnn in the source program; this is not allowed.

- "Incorrect syntax after DEF": this occurs when the token for DEF has been encountered but the next token is neither PROC nor FN.

- "Max no of routines exceeded": the number of routines (procedures, functions or CALLs) encountered in the source program exceeds the limit maxR%; try increasing this variable.

Some errors, such as "Filing system full" or "Protected disc" can be responded to with "OK" and appropriate measures taken.

Any other error from Profile will normally be as a result of program errors; the appropriate response to these other errors is therefore "Cancel".

Final Note
----------
One final note about trying to tweak programs. My experience during the development of Profile was that changes such as using resident integer variables, using short variable names, using literals instead of meaningful variable names, and so on did not provide as good a performance improvement as simply left-justifying all lines.

Example of Profile Output File "Prof"
-------------------------------------
You may need to enlarge this text window to se this table in full.

 PROFILE RESULTS
 name                         count          time(s)    time/call(ms)
 -MAIN-                           1          0.04          40.00             
 PROCconst                        1          0.01          10.00             
 PROCvar                          1          0.00           0.00             
 PROCinit                         1          0.01          10.00             
 PROCerror                        0          0.00       --not called--
 PROCpoll                         6         21.00        3500.00             
 PROCmouseclick                   1          0.00           0.00             
 PROCmessage                      4          0.00           0.00             
 PROCaction                       1          5.71        5710.00             
 FNstr                            1          0.01          10.00             
 FNdir                            1          0.00           0.00             
 FNnewName                        1          0.00           0.00             
 PROCgetLine                    371          2.87           7.74             
 PROCputLine                    370          3.70          10.00             
 PROCprocess                    370         13.42          36.27             
 PROCheader                       1          0.00           0.00             
 PROCappend                       1          0.16         160.00             
 PROCline                        79          0.09           1.14             
 PROCdim                          6          0.01           1.67             
 FNpsh                           28          0.04           1.43             
 PROCstate0                     543          1.27           2.34             
 PROCstate1                    4766          6.27           1.32             
 PROCstate2                      56          0.11           1.96             
 PROCstate3                      28          0.04           1.43             
 PROCstate4                     154          0.35           2.27             
 PROCstate5                      76          0.06           0.79             
 PROCstate6                       0          0.00       --not called--
 PROCstate7                       0          0.00       --not called--
 PROCstate8                    1350          1.18           0.87             

 TOTAL TIME = 56.35 seconds

 RISC User 1992
