Paul van den Bogaard
2007-Dec-11 10:54 UTC
[dtrace-discuss] DTrace USDT probes: scanning the /proc/<pid>/map files too often?
This post follows my two previous posts
(http://www.opensolaris.org/jive/forum.jspa?threadID=46632&tstart=0 and
http://www.opensolaris.org/jive/thread.jspa?threadID=44958&tstart=0)
There is a lineair relationship in time spent compiling and the number of USDT
probes being enabled. Time for compiling a DTrace script that enables USDT
probes gets excessive (up to almost an hour) due to time spent in fstat and
pread on /proc/<pid>/map files of the process(es) of interest. Both a
single fstat and a single pread on these files take 0.3 seconds.
(on a T2000, 8 * 1000MHz, S10 update 4)
When compiling a DTrace script that enables a single USDT probe in a single
process the fstat is called four times on this file (/proc/<pid>/map),
while the pread is called five times.
Doing the same thing but enabling two clauses in a single process doubles these
numbers.
Doing the same thing but now on four clauses in a single process re-doubles
these number once more. Et cetera.
BTW the clauses are all like
postgresql3157:postgres:LWLockAcquire:lwlock-acquire /arg1 == 0/ { }
postgresql3157:postgres:LWLockAcquire:lwlock-acquire /arg1 == 1/ { }
Beware, only the predicate changes. This is done to simplify testing. In real
life the probes are different (although from the same provider) and so are the
predicates. And this for many processes.
For each single probe there are two different pread calls. One with a buffer
size of 5200, all the others (4) with a buffer size of 4576. All preads use zero
for their offset value (final parameter).
Calling a ustack() to check where these calls come from, shows the following:
libc.so.1`fstat+0x4
libdtrace.so.1`dt_pid_create_usdt_probes+0x38
libdtrace.so.1`dt_pid_create_probes+0x278
libdtrace.so.1`dt_setcontext+0x60
libdtrace.so.1`dt_compile_one_clause+0x3c
libdtrace.so.1`dt_compile_clause+0x1c
libdtrace.so.1`dt_compile+0x69c
libdtrace.so.1`dtrace_program_fcompile+0x24
dtrace`compile_file+0x70
dtrace`main+0x12d8
dtrace`_start+0x17c
0 0 1
libc.so.1`_pread+0x8
libproc.so.1`Pupdate_maps+0xbc
libdtrace.so.1`dt_pid_create_usdt_probes+0x38
libdtrace.so.1`dt_pid_create_probes+0x278
libdtrace.so.1`dt_setcontext+0x60
libdtrace.so.1`dt_compile_one_clause+0x3c
libdtrace.so.1`dt_compile_clause+0x1c
libdtrace.so.1`dt_compile+0x69c
libdtrace.so.1`dtrace_program_fcompile+0x24
dtrace`compile_file+0x70
dtrace`main+0x12d8
dtrace`_start+0x17c
4576 0 1
libc.so.1`_pread+0x8
libproc.so.1`Pscantext+0x154
libproc.so.1`Psyscall+0xd4
libproc.so.1`pr_open+0x8c
libdtrace.so.1`dt_pid_usdt_mapping+0x140
libproc.so.1`Pobject_iter+0x68
libdtrace.so.1`dt_pid_create_usdt_probes+0x4c
libdtrace.so.1`dt_pid_create_probes+0x278
libdtrace.so.1`dt_setcontext+0x60
libdtrace.so.1`dt_compile_one_clause+0x3c
libdtrace.so.1`dt_compile_clause+0x1c
libdtrace.so.1`dt_compile+0x69c
libdtrace.so.1`dtrace_program_fcompile+0x24
dtrace`compile_file+0x70
dtrace`main+0x12d8
dtrace`_start+0x17c
5200 0 1
libc.so.1`fstat+0x4
libproc.so.1`object_name_to_map+0x14
libproc.so.1`Pxlookup_by_name+0x2c
libdtrace.so.1`dt_pid_usdt_mapping+0x64
libproc.so.1`Pobject_iter+0x68
libdtrace.so.1`dt_pid_create_usdt_probes+0x4c
libdtrace.so.1`dt_pid_create_probes+0x278
libdtrace.so.1`dt_setcontext+0x60
libdtrace.so.1`dt_compile_one_clause+0x3c
libdtrace.so.1`dt_compile_clause+0x1c
libdtrace.so.1`dt_compile+0x69c
libdtrace.so.1`dtrace_program_fcompile+0x24
dtrace`compile_file+0x70
dtrace`main+0x12d8
dtrace`_start+0x17c
0 0 3
libc.so.1`_pread+0x8
libproc.so.1`Pupdate_maps+0xbc
libproc.so.1`object_name_to_map+0x14
libproc.so.1`Pxlookup_by_name+0x2c
libdtrace.so.1`dt_pid_usdt_mapping+0x64
libproc.so.1`Pobject_iter+0x68
libdtrace.so.1`dt_pid_create_usdt_probes+0x4c
libdtrace.so.1`dt_pid_create_probes+0x278
libdtrace.so.1`dt_setcontext+0x60
libdtrace.so.1`dt_compile_one_clause+0x3c
libdtrace.so.1`dt_compile_clause+0x1c
libdtrace.so.1`dt_compile+0x69c
libdtrace.so.1`dtrace_program_fcompile+0x24
dtrace`compile_file+0x70
dtrace`main+0x12d8
dtrace`_start+0x17c
4576 0 3
This information is created with:
syscall::pread:entry,
syscall::fstat:entry
/pid == $target/
{
self->filename = basename(fds[arg0].fi_pathname);
}
syscall::pread:entry,
syscall::fstat:entry
/self->filename == "map"/
{
self->flagIt = 1;
self->a1 = 0;
self->a2 = 0;
}
syscall::pread:entry
/self->flagIt/
{
self->a1 = arg2;
self->a2 = arg3;
}
syscall::pread:return,
syscall::fstat:return
/self->flagIt /
{
self->flagIt = 0;
@c[ustack(),self->a1, self->a2] = count();
}
END {
printf("Elapsed: %d\n", (timestamp - started) / 1000 );
printa( @c);
}
If the naming conventions are proper this indeed shows that a map file is
accessed for each and every clause. I assume (and I can be dead wrong with
this!) that the map information is constant for the sake of these DTrace probe
compilations. It would be most advantaguous if the information read from the
map would be cached by DTrace instead of calling the pread/fstat for each clause
that references the same process. And indeed also when referencing multiple
processses created from the same program.
--
This message posted from opensolaris.org