This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.


Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]
Other format: [Raw text]

Re: DTrace for Linux


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






Index Nav: [Date Index] [Subject Index] [Author Index] [Thread Index]
Message Nav: [Date Prev] [Date Next] [Thread Prev] [Thread Next]