Debugging and Profiling

Debugging in Phix is much easier than in most other programming languages. Extensive run-time checking provided by the phix interpreter catches many bugs that in other languages might take hours of your time to track down. When the interpreter catches an error, you will always get a brief report on your screen, and a detailed report in a file called ex.err . These reports include a full English description of what happened, along with a call-stack traceback. The file ex.err will also have a dump of all variable values, and optionally a list of the most recently executed statements. For extremely large sequences, only a partial dump is shown. If ex.err is not convenient, you can choose another file name, anywhere on your system, by calling crash_file().

In addition, you are able to create user-defined types that precisely determine the set of legal values for each of your variables. An error report will occur the moment that one of your variables is assigned an illegal value.

Sometimes a program will misbehave without failing any run-time checks. In any programming language it may be a good idea to simply study the source code and rethink the algorithm that you have coded. It may also be useful to insert print statements at strategic locations in order to monitor the internal logic of the program. This approach is particularly convenient in an interpreted language like phix since you can simply edit the source and rerun the program without waiting for a re-compile/re-link.

The interpreter provides you with additional powerful tools for debugging. Using trace(1) you can trace the execution of your program on one screen while you witness the output of your program on another. trace(2) is the same as trace(1) but the trace screen will be in monochrome. Finally, using trace(3), you can log all executed statements to a file called ctrace.out.

with trace / without trace special statements select the parts of your program that are available for tracing. Often you will simply insert a with trace statement at the very beginning of your source code to make it all traceable. Sometimes it is better to place the first with trace after all of your user-defined types, so you do not trace into these routines after each assignment to a variable. At other times, you may know exactly which routine or routines you are interested in tracing, and you will want to select only these ones. Of course, once you are in the trace window you can interactively skip over the execution of any routine by pressing down-arrow on the keyboard rather than Enter.

DEV (ctrace.out not yet supported)
Only traceable lines can appear in ctrace.out or in ex.err as "Traced lines leading up to the failure" should a run-time error occur. If you want this information and did not get it, you should insert a with trace and then rerun your program. Execution will be slower when lines compiled with trace are executed, especially when trace(3) is used.

After you have predetermined the lines that are traceable, your program must then dynamically cause the trace facility to be activated by executing a trace() statement. You could simply say:
        with trace
        trace(1)
at the top of your program, so you can start tracing from the beginning of execution. More commonly, you will want to trigger tracing when a certain routine is entered, or when some condition arises. e.g.
        if x < 0 then
            trace(1)
        end if
You can turn off tracing by executing a trace(0) statement. You can also turn it off interactively by typing 'q' to quit tracing. Remember that with trace must appear outside of any routine, whereas trace() can appear inside a routine or outside .

You might want to turn on tracing from within a type. Suppose you run your program and it fails, with the ex.err file showing that one of your variables has been set to a strange, although not illegal value, and you wonder how it could have happened. Simply create a type for that variable that executes trace(1) if the value being assigned to the variable is the strange one that you are interested in. e.g.
        type positive_int(integer x)
            if x = 99 then
                trace(1) -- how can this be???
                return 1 -- keep going
            else
                return x > 0
            end if
        end type
When positive_int() returns, you will see the exact statement that caused your variable to be set to the strange value, and you will be able to check the values of other variables. You will also be able to check the output screen to see what has happened up to this precise moment. If you define positive_int() so it returns 0 for the strange value (99) instead of 1, you can force a diagnostic dump into ex.err .

3.1.1 The Trace Screen

When a trace(1) or trace(2) statement is executed by the interpreter, your main output screen is saved and a trace screen appears. It shows a view of your program with the statement that will be executed next highlighted, and several statements before and after showing as well. Several lines at the bottom of the screen are reserved for displaying variable names and values. The top line shows the commands that you can enter at this point:

F1 - display main output screen - take a look at your program’s output so far
F2 - redisplay trace screen. Press this key while viewing the main output screen to return to the trace display.
Enter - execute the currently-highlighted statement only
down-arrow - continue execution and break when any statement coming after this one in the source listing is about to be executed. This lets you skip over subroutine calls. It also lets you stop on the first statement following the end of a for-loop or while-loop without having to witness all iterations of the loop.
? - display the value of a variable. Many variables are displayed automatically as they are assigned a value, but sometimes you will have to explicitly ask for one that is not on display. After hitting ? you will be prompted for the name of the variable. Variables that are not defined at this point cannot be shown. Variables that have not yet been initialized will have "< NO VALUE >" beside their name. Only variables, not general expressions, can be displayed.
q - quit tracing and resume normal execution. Tracing will start again when the next trace(1) is executed.
Q - quit tracing and let the program run freely to its normal completion. trace() statements will be ignored.
! - this will abort execution of your program. A traceback and dump of variable values will go to ex.err .

 
As you trace your program, variable names and values appear automatically in the bottom portion of the screen. Whenever a variable is assigned-to, you will see its name and new value appear at the bottom. This value is always kept up-to-date. Private variables are automatically cleared from the screen when their routine returns. When the variable display area is full, least-recently referenced variables will be discarded to make room for new variables. The value of a long sequence will be cut off after 80 characters.

For your convenience, numbers that are in the range of printable ASCII characters (32-127) are displayed along with the ASCII character itself. The ASCII character will be in a different color (or in quotes in a mono display). This is done for all variables, since phix does not know in general whether you are thinking of a number as an ASCII character or not. You will also see ASCII characters (in quotes) in ex.err . This can make for a rather "busy" display, but the ASCII information is often very useful.

When a traced program requests keyboard input, the main output screen will appear, to let you type your input as you normally would. This works fine for gets() (read one line) input. When get_key() (quickly sample the keyboard) is called you will be given 8 seconds to type a character, otherwise it is assumed that there is no input for this call to get_key(). This allows you to test the case of input and also the case of no input for get_key().

3.1.2 The Trace File

When your program calls trace(3), tracing to a file is activated. The file, ctrace.out will be created in the current directory. It contains the last 500 phix statements that your program executed. It is set up as a circular buffer that holds a maximum of 500 statements. The very last statement executed is always followed by "=== THE END ===". Because it is circular, the last statement executed could appear anywhere in ctrace.out. The statement coming after "=== THE END ===" is the 500th-last. When the end of ctrace.out is reached, the next statement is written at the beginning of the file.


DEV (ctrace.out not yet supported)
This form of tracing is supported by both the interpreter and compiler. It is particularly useful when a machine-level error occurs that prevents phix from writing out an ex.err diagnostic file. By looking at the last statement executed, you may be able to guess why the program crashed. Perhaps the last statement was a poke() into an illegal area of memory. Perhaps it was a call to a C routine. In some cases it might be a bug in the interpreter or compiler.

Statements are written to ctrace.out, and flushed, just before the statement is performed, so the crash will likely have happened during execution of the final statement.

3.2 Profiling
If you specify with profile or with profile_time then a special listing of your program, called a profile , will be produced by the interpreter when your program finishes execution. This listing is written to the file ex.pro in the current directory.

There are two types of profiling available: execution-count profiling , and time profiling . You get execution-count profiling when you specify with profile . You get time profiling when you specify with profile_time . You cannot mix the two types of profiling in a single run of your program. You need to make two separate runs.

We ran the sieve.ex benchmark program in demo\bench under both types of profiling. The results are in sieve1.pro (execution-count profiling) and sieve2.pro (time profiling).

Execution-count profiling shows precisely how many times each statement in your program was executed. If the statement was never executed the count field will be blank.

Time profiling shows an estimate of the total time spent executing each statement. This estimate is expressed as a percentage of the time spent profiling your program. If a statement was never sampled, the percentage field will be blank. If you see 0.00 it means the statement was sampled, but not enough to get a score of 0.01.

Only statements compiled with profile or with profile_time are shown in the listing. Normally you will specify either with profile or with profile_time at the top of your main .ex file, so you can get a complete listing. View this file with Edita/Edix to see a color display.

Profiling can help you in many ways:
  • it lets you see which statements are heavily executed, as a clue to speeding up your program
  • it lets you verify that your program is actually working the way you intended
  • it can provide you with statistics about the input data
  • it lets you see which sections of code were never tested - don’t let your users be the first!
Sometimes you will want to focus on a particular action performed by your program. For example, in the Language War game, we found that the game in general was fast enough, but when a planet exploded, shooting 2500 pixels off in all directions, the game slowed down. We wanted to speed up the explosion routine. We didn’t care about the rest of the code. The solution was to call profile(0) at the beginning of Language War, just after with profile_time , to turn off profiling, and then to call profile(1) at the beginning of the explosion routine and profile(0) at the end of the routine. In this way we could run the game, creating numerous explosions, and logging a lot of samples, just for the explosion effect. If samples were charged against other lower-level routines, we knew that those samples occurred during an explosion. If we had simply profiled the whole program, the picture would not have been clear, as the lower-level routines would also have been used for moving ships, drawing phasors etc. profile() can help in the same way when you do execution-count profiling.

Sometimes you will see a significant percentage beside a return statement. This is usually due to time spent deallocating storage for temporary and private variables used within the routine. Significant storage deallocation time can also occur when you assign a new value to a large sequence.

If disk swapping starts to happen, you may see large times attributed to statements that need to access the swap file, such as statements that access elements of a large swapped-out sequence.