Time profiling with nhc98

Time profiling allows a programmer to see which of the functions in their program consume the most time, and how many times each is called. The information is collected as the program is executing, so it is simple to try the analysis with various types of input data, viewing behaviour in "average" and "worst" cases.

The profiles produced can be used to compare two different implementations, or can direct programmers to "hot spots" in a program that use a disproportionate amount of resources. The effort to improve the program can then be focussed on these critical pieces, where it will be of most benefit. The profile may also highlight functions that are being called more or less often than a programmer expects, indicating possible bugs that have been overlooked.

To obtain a time profile of a computation:

1. Compile all modules of the program with the -t option; also specify -t at link-time. Using hmake -t does all the necessary compiling and linking automatically. eg. to compile MyProg.hs and everything it depends on for time profiling simply use hmake -t MyProg

2. Run the program with the additional runtime argument -t eg. ./MyProg +RTS -t -RTS will output profiling data to the file MyProg.tp

Time profiling options

The various single-letter flags can be aggregated together, e.g. -tmt which will order the functions by time within each module - this is the default if just -t is supplied. You can give a list of module names separated by spaces using the shell quoting mechanism eg. -t"+Prelude -Main +IO" The default is to show all functions written by the user separately but only show the total for library modules (Prelude, IO, etc.).

Example

The program used in this example is taken from the nofib Benchmark Suite, and uses Peanno arithmetic to raise 3 to the power 8.

data Peanno = Z | S Peanno

add Z     y = y
add (S x) y = S (add x y)

mult x Z     = Z
mult x (S y) = add (mult x y) x

raise x Z     = S Z
raise x (S y) = mult x (raise x y)

intTOpeanno x = if x < 1 then Z else S (intTOpeanno (x-1))

peannoTOint Z     = 0
peannoTOint (S x) = 1 + peannoTOint x

main = print (peannoTOint (raise (intTOpeanno 3) (intTOpeanno 8)))

The resulting profile is given below. The listing, by module, gives the percentage of time consumed, and the number of calls, per function. The profile shows that most of the execution time (>75%) is spent in the add function, and that there are far more calls made to this function than any other.

JOB ./Peanno +RTS -t -RTS ;

----------------------------------------------------------
Main		  76.0% time	   8079493 calls
----------------------------------------------------------
 % time     # calls                                       
   76.0     8069620   add
    0.0        6562   peannoTOint
    0.0        3288   mult
    0.0          13   intTOpeanno
    0.0           9   raise
    0.0           1   main

Prelude 	   0.5% time	     39752 calls

GarbageCollect	  23.5% time	       416 calls

Time figures based on 208 samples

Why are there so many applications of the add function?

From the recursive definition, the evaluation of add x y leads to x more applications of add. The evaluation of mult x y leads to y nested applications of add in the form (add (add (add x x) x) ... ). The evaluation of the innermost of these leads to just x more applications of add, but then the evaluation of the next leads to twice as many, and so on.

By altering the definition of mult to add x (mult x y), the nested applications of add are in the form (add ... (add x (add x x))), and so each gives rise to just x add functions. This change decreased the number of calls for add from 8069620 to 13120, and reduced the program's runtime by a factor of about 100.

The latest updates to these pages are available on the WWW from http://www.haskell.org/nhc98/

York Functional Programming Group