This is the mail archive of the
systemtap@sourceware.org
mailing list for the systemtap project.
Re: DTrace for Linux
- From: Martin Hunt <hunt at redhat dot com>
- To: "Stone, Joshua I" <joshua dot i dot stone at intel dot com>
- Cc: "systemtap at sources dot redhat dot com" <systemtap at sources dot redhat dot com>
- Date: Wed, 14 Dec 2005 15:32:39 -0800
- Subject: Re: DTrace for Linux
- Organization: Red Hat Inc
- References: <CBDB88BFD06F7F408399DBCF8776B3DC05DDE7E7@scsmsx403.amr.corp.intel.com>
On Wed, 2005-12-14 at 10:47 -0800, Stone, Joshua I wrote:
> This is getting a lot of buzz on the blogosphere:
> http://blogs.sun.com/roller/page/ahl?entry=dtrace_for_linux
OK, I gave it a quick try. To do this, I needed the system_call tapset,
which (like the rest of systemtap) is a rapidly changing work-in-
progress. Unfortunately it doesn't run of my x86_64 dev system, so I had
to switch to an x86.
First, to get a quick look at what top was doing, I ran this script:
>stap -c top sys1.stp
-------
global called
probe kernel.syscall.* {
if (execname() == "top")
called[name] += 1
}
probe end {
foreach (n in called-)
printf("top called %s\t%d times\n", n, called[n])
}
--------
When I exited top, it gave me the following output:
top called read 1551 times
top called open 1433 times
top called creat 1433 times
top called close 1430 times
top called stat64 700 times
top called alarm 285 times
top called fcntl64 253 times
top called rt_sigaction 201 times
top called mmap2 33 times
top called fstat64 30 times
top called write 23 times
top called ioctl 20 times
top called munmap 17 times
top called lseek 15 times
top called getdents64 12 times
top called llseek 10 times
top called access 8 times
top called gettimeofday 6 times
top called select 6 times
[...]
That looks fine. And very much like what Sun got. So on to some crude
profiling:
First thing I notice is that the tapset sets "name" to different values
for the entry and exit probes. This makes matching them up a bit of a
headache. So I edited the tapset and removed the ".return" on the values
for "name" in the return probes. If no one has a reason why they should
be there then we should make this change permanent.
Unfortunately, then I got an error on from the syscall tapset on
execve.return.
semantic error: no match for probe point
while: resolving probe point kernel.function
("sys_execve").return
So I commented out the whole sysexecve section in the tapset and tried
again.
----
global called, ttime
probe kernel.syscall.* {
if (execname() == "top")
called[name] = gettimeofday_us()
}
probe kernel.syscall.*.return {
if (execname() == "top")
ttime[name] += gettimeofday_us() - called[name]
}
probe end {
foreach ([n] in ttime-)
printf("%s took %d usecs\n", n, ttime[n])
}
----
This time I got the following output:
select took 100037096 usecs
open took 93042 usecs
read took 79974 usecs
creat took 66253 usecs
close took 30882 usecs
stat64 took 28486 usecs
write took 7171 usecs
fcntl64 took 6297 usecs
alarm took 5958 usecs
rt_sigaction took 4017 usecs
getdents64 took 2289 usecs
ioctl took 747 usecs
lseek took 353 usecs
access took 324 usecs
llseek took 253 usecs
fstat64 took 238 usecs
mmap2 took 186 usecs
munmap took 171 usecs
gettimeofday took 124 usecs
time took 117 usecs
socketcall took 76 usecs
mprotect took 30 usecs
connect took 24 usecs
socket took 16 usecs
[...]
OK, now this is much different than what Sun got. There is certainly no
munmap() problem here. Without detail about Sun's emulation environment
and what version of linux they are running, I cannot even guess what the
problem is. Maybe one clue is this odd comment "[...]what I've heard my
colleague, Bryan, refer to as the "top problem": your system is slow, so
you run top. What's the top process? Top!"
I've never seen "top" the top process in anything but an extremely idle
system.
Martin