Timing the cost of trace instrumentation

[Erwan Jahier]

Fergus Henderson wrote:

> > I've done benchmarks on a program that solve the hanoi tower problem
> > with 19 disks, and it happends that the program with tracing on runs
> > around 15% slower which is already not too bad (I shall do more
> > benchmarks).
> 
> Yes, please do, and let us know the results.
> 

Here are the results. I've done other measures on sparc and it is
roughly the same. The ratio ranges from 36% slowdown to 2% speedup (!).

I have used the programs in tests/benchmark.

The times calculated are the sum of ther user time and the system time
produced by the command /usr/bin/time for each program run 10000 times
(/usr/bin/time -f "%U %S +p" run_10000_foo | dc). I don't know whether
it is the best way to time that... but I think it gives a rough idea. 
 
I have run that stuff three times.

::::::::::::::
cqueens.res.linux
::::::::::::::
cqueens 10000 times :
510.57

cqueens_nt 10000 times :
502.76
ratio = 1.02
--------------------------------------------------------------
cqueens 10000 times :
503.93

cqueens_nt 10000 times :
496.46
ratio = 1.02
--------------------------------------------------------------
cqueens 10000 times :
501.48

cqueens_nt 10000 times :
511.38
ratio = 0.98
--------------------------------------------------------------
::::::::::::::
deriv.res.linux
::::::::::::::
deriv 10000 times :
523.32

deriv_nt 10000 times :
531.95
ratio = 0.98
--------------------------------------------------------------
deriv 10000 times :
519.28

deriv_nt 10000 times :
520.84
ratio = 1
--------------------------------------------------------------
deriv 10000 times :
516.71

deriv_nt 10000 times :
517.68
ratio = 1
--------------------------------------------------------------
::::::::::::::
deriv2.res.linux
::::::::::::::
deriv2 10000 times :
538.94

deriv2_nt 10000 times :
532.92
ratio = 1.01
--------------------------------------------------------------
deriv2 10000 times :
525.30

deriv2_nt 10000 times :
521.11
ratio = 1.01
--------------------------------------------------------------
deriv2 10000 times :
634.12

deriv2_nt 10000 times :
621.80
ratio = 1.02
--------------------------------------------------------------
::::::::::::::
nrev.res.linux
::::::::::::::
nrev 10000 times :
500.00

nrev_nt 10000 times :
494.11
ratio = 1.01
--------------------------------------------------------------
nrev 10000 times :
498.95

nrev_nt 10000 times :
493.08
ratio = 1.01
--------------------------------------------------------------
nrev 10000 times :
494.23

nrev_nt 10000 times :
489.05
ratio = 1.01
--------------------------------------------------------------
::::::::::::::
poly.res.linux
::::::::::::::
poly 10000 times :
696.32

poly_nt 10000 times :
630.55
ratio = 1.1
--------------------------------------------------------------
poly 10000 times :
691.38

poly_nt 10000 times :
627.78
ratio = 1.1
--------------------------------------------------------------
poly 10000 times :
687.74

poly_nt 10000 times :
626.61
ratio = 1.1
--------------------------------------------------------------
::::::::::::::
primes.res.linux
::::::::::::::
primes 10000 times :
511.71

primes_nt 10000 times :
520.10
ratio = 0.98
--------------------------------------------------------------
primes 10000 times :
505.69

primes_nt 10000 times :
504.95
ratio = 1
--------------------------------------------------------------
primes 10000 times :
601.26

primes_nt 10000 times :
608.07
ratio = 0.99
--------------------------------------------------------------
::::::::::::::
qsort.res.linux
::::::::::::::
qsort 10000 times :
509.02

qsort_nt 10000 times :
514.55
ratio = 0.99
--------------------------------------------------------------
qsort 10000 times :
505.77

qsort_nt 10000 times :
503.82
ratio = 1
--------------------------------------------------------------
qsort 10000 times :
502.30

qsort_nt 10000 times :
502.97
ratio = 1
--------------------------------------------------------------
::::::::::::::
queens.res.linux
::::::::::::::
queens 10000 times :
801.30

queens_nt 10000 times :
650.20
ratio = 1.23
--------------------------------------------------------------
queens 10000 times :
799.14

queens_nt 10000 times :
643.05
ratio = 1.25
--------------------------------------------------------------
queens 10000 times :
847.64

queens_nt 10000 times :
640.59
ratio = 1.32
--------------------------------------------------------------
::::::::::::::
query.res.linux
::::::::::::::
query 10000 times :
510.09

query_nt 10000 times :
503.71
ratio = 1.01
--------------------------------------------------------------
query 10000 times :
507.15

query_nt 10000 times :
502.41
ratio = 1.01
--------------------------------------------------------------
query 10000 times :
502.98

query_nt 10000 times :
498.87
ratio = 1
--------------------------------------------------------------
::::::::::::::
tak.res.linux
::::::::::::::
tak 10000 times :
725.11

tak_nt 10000 times :
547.58
ratio = 1.32
--------------------------------------------------------------
tak 10000 times :
719.11

tak_nt 10000 times :
538.49
ratio = 1.34
--------------------------------------------------------------
tak 10000 times :
718.38

tak_nt 10000 times :
533.83
ratio = 1.34
--------------------------------------------------------------

- machine:
paraski8[8:18]%uname -a
Linux paraski8 2.0.34 #1 Thu Jun 4 09:28:21 MEST 1998 i686 unknown
paraski8[10:05]%mmc
Mercury Compiler, version rotd-1998-09-22, configured for
i686-pc-linux-gnu
Copyright (C) 1993-1998 The University of Melbourne

- here is the script I used to compile the different executables (just
in case I've done something wrong):

mmake $1.depend
mmake $1
 
mv $1 $1_nt
 
mmc -c $1 --trace all --cflags "-DMR_USE_EXTERNAL_DEBUGGER -g"
--link-flags -g -lsocket
mmake $1


-- 
R1.