Overhead for "stap -t" timing information

Overhead for "stap -t" timing information

[William Cohen]

This morning I did some experiments to get an idea about the overhead
the "-t" option in the stap translator on amd64 (2GHz) and em64t
(2.8GHz) machine this afternoon.  These tests were just done by
hand. I didn't have a script set up.

The latest cvs version of systemtap (2006-06-10) was used. The amd64
machine was a fully updated FC-4 machine with a 2.6.17-rc1-perfmon2
kernel and the em64t machine was a RHEL4U3 with the 6.9-35.ELsmp
kernel.

The probe instrumented kernel.function("sys_getuid") and a small user
program was run to trigger one million calls to that function (itest.c
from Martin's benchmarking). The itest was run three times in each
case. itest reports the average number of nanoseconds per call.

itest getuid	FC-4		|	RHEL4
per iteration	AMD64 (ns)	|	em64t (ns)
itest		220 217 216	|	227 277 227
itest+stap	715 735 733	|	1805 1805 1801
itest+stap -t	781 781 778	|	1863 1860 1861

It appears that collecting the timing information on the probes adds
about 50 cycles for AMD64 and 60 cycles for em64t.  The timing
information from the -t does not include the overhead of the
kprobe. Below is the output of the timing information generated on the
probes.

For the AMD stap -t get the following additional timing output:

probe at base_time.stp:17:1 (end) 1@8740 (8740 <= t <= 8740)
probe at base_time.stp:12:1 
(kernel.function("sys_getuid@kernel/timer.c:1005")) 3000000@37 (20 <= t 
<= 1322)
probe at base_time.stp:7:1 (begin) 1@6260 (6260 <= t <= 6260)


For the em64t stap -t get the following additional timing output:

probe at base_time.stp:17:1 (end) 1@12866 (12866 <= t <= 12866)
probe at base_time.stp:12:1 
(kernel.function("sys_getuid@kernel/timer.c:1070")) 1000001@103 (98 <= t 
<= 8456)
probe at base_time.stp:7:1 (begin) 1@9009 (9009 <= t <= 9009)

-Will