I want to print a stack trace whenever thread 1 for the PID of
interest spends more than 6 seconds in lwp_mutex_timedlock.
So I wrote the following:
#!/usr/sbin/dtrace -s
syscall::lwp_mutex_timedlock:entry
/ pid == $1 && tid == 1 /
{
trace(probefunc);
printf("%Y \n",walltimestamp);
self->my_traceon=timestamp;
}
syscall::lwp_mutex_timedlock:return
/ self->my_traceon && self->my_traceon - timestamp >
6000000000/
{
ustack();
}
syscall::lwp_mutex_timedlock:return
/ self->my_traceon /
{
trace(probefunc);
printf("%Y \n",walltimestamp);
my_traceon=0;
}
fbt:::
/ self->my_traceon /
{
trace(probefunc);
printf("%Y \n",walltimestamp);
}
I expect to get an entry from the syscall
and entry from fbt ?
a stack from those > 6 sec
a return from the syscall.
I get as output:
The output is like this:
0 11028 lwp_mutex_timedlock:entry lwp_mutex_timedlock
2007 Jan 12 10:35:50
0 11029 lwp_mutex_timedlock:return lwp_mutex_timedlock
2007 Jan 12 10:35:50
0 11028 lwp_mutex_timedlock:entry lwp_mutex_timedlock
2007 Jan 12 10:35:50
0 11029 lwp_mutex_timedlock:return
libc.so.1`___lwp_mutex_timedlock+0x8
libc.so.1`mutex_lock_internal+0x218
... rest of stack
0 11029 lwp_mutex_timedlock:return lwp_mutex_timedlock
2007 Jan 12 10:35:50
So I got a stack, so the method took longer than 6 seconds, but the
walltimestamps between entry and exit show less than a 1 second difference.
How can that be ?
Plus I get nothing from the fbt probe.
rick
--
Rickey C. Weisner
Software Development and Performance Specialist
Sun Microsystems, INC
cell phone: 615-308-1147
email: rick.weisner at sun.com
> / self->my_traceon && self->my_traceon - timestamp > 6000000000/I think you want to do ''timestamp - self->my_traceon''. Otherwise you''ll get a big unsigned value. You''re also using the global my_traceon variable in addition to the thread- local version. Adam On Tue, Jan 16, 2007 at 02:45:38PM -0600, rickey c weisner wrote:> I want to print a stack trace whenever thread 1 for the PID of > interest spends more than 6 seconds in lwp_mutex_timedlock. > So I wrote the following: > #!/usr/sbin/dtrace -s > syscall::lwp_mutex_timedlock:entry > / pid == $1 && tid == 1 / > { > trace(probefunc); > printf("%Y \n",walltimestamp); > self->my_traceon=timestamp; > } > syscall::lwp_mutex_timedlock:return > / self->my_traceon && self->my_traceon - timestamp > 6000000000/ > { > ustack(); > } > syscall::lwp_mutex_timedlock:return > / self->my_traceon / > { > trace(probefunc); > printf("%Y \n",walltimestamp); > my_traceon=0; > } > fbt::: > / self->my_traceon / > { > trace(probefunc); > printf("%Y \n",walltimestamp); > } > I expect to get an entry from the syscall > and entry from fbt ? > a stack from those > 6 sec > a return from the syscall. > > I get as output: > The output is like this: > 0 11028 lwp_mutex_timedlock:entry lwp_mutex_timedlock > 2007 Jan 12 10:35:50 > > 0 11029 lwp_mutex_timedlock:return lwp_mutex_timedlock > 2007 Jan 12 10:35:50 > > 0 11028 lwp_mutex_timedlock:entry lwp_mutex_timedlock > 2007 Jan 12 10:35:50 > > 0 11029 lwp_mutex_timedlock:return > libc.so.1`___lwp_mutex_timedlock+0x8 > libc.so.1`mutex_lock_internal+0x218 > ... rest of stack > 0 11029 lwp_mutex_timedlock:return lwp_mutex_timedlock > 2007 Jan 12 10:35:50 > > So I got a stack, so the method took longer than 6 seconds, but the > walltimestamps between entry and exit show less than a 1 second difference. > How can that be ? > Plus I get nothing from the fbt probe. > > rick > -- > > Rickey C. Weisner > Software Development and Performance Specialist > Sun Microsystems, INC > cell phone: 615-308-1147 > email: rick.weisner at sun.com > _______________________________________________ > dtrace-discuss mailing list > dtrace-discuss at opensolaris.org-- Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl
Thanks, I am more than a little embarrassed. rick On Tue, Jan 16, 2007 at 02:50:19PM -0800, Adam Leventhal wrote:> Date: Tue, 16 Jan 2007 14:50:19 -0800 > From: Adam Leventhal <ahl at eng.sun.com> > Subject: Re: [dtrace-discuss] Re: timestamp and walltimestamp > In-reply-to: <20070116144538.A2161 at arwen.sfbay.sun.com> > To: rickey c weisner <Rick.Weisner at Sun.COM> > Cc: dtrace-discuss at opensolaris.org > User-Agent: Mutt/1.5.10i > Original-recipient: rfc822;rw8775 at bedge4-mail1.Central.Sun.COM > > > / self->my_traceon && self->my_traceon - timestamp > 6000000000/ > > I think you want to do ''timestamp - self->my_traceon''. Otherwise you''ll get > a big unsigned value. > > You''re also using the global my_traceon variable in addition to the thread- > local version. > > Adam > > On Tue, Jan 16, 2007 at 02:45:38PM -0600, rickey c weisner wrote: > > I want to print a stack trace whenever thread 1 for the PID of > > interest spends more than 6 seconds in lwp_mutex_timedlock. > > So I wrote the following: > > #!/usr/sbin/dtrace -s > > syscall::lwp_mutex_timedlock:entry > > / pid == $1 && tid == 1 / > > { > > trace(probefunc); > > printf("%Y \n",walltimestamp); > > self->my_traceon=timestamp; > > } > > syscall::lwp_mutex_timedlock:return > > / self->my_traceon && self->my_traceon - timestamp > 6000000000/ > > { > > ustack(); > > } > > syscall::lwp_mutex_timedlock:return > > / self->my_traceon / > > { > > trace(probefunc); > > printf("%Y \n",walltimestamp); > > my_traceon=0; > > } > > fbt::: > > / self->my_traceon / > > { > > trace(probefunc); > > printf("%Y \n",walltimestamp); > > } > > I expect to get an entry from the syscall > > and entry from fbt ? > > a stack from those > 6 sec > > a return from the syscall. > > > > I get as output: > > The output is like this: > > 0 11028 lwp_mutex_timedlock:entry lwp_mutex_timedlock > > 2007 Jan 12 10:35:50 > > > > 0 11029 lwp_mutex_timedlock:return lwp_mutex_timedlock > > 2007 Jan 12 10:35:50 > > > > 0 11028 lwp_mutex_timedlock:entry lwp_mutex_timedlock > > 2007 Jan 12 10:35:50 > > > > 0 11029 lwp_mutex_timedlock:return > > libc.so.1`___lwp_mutex_timedlock+0x8 > > libc.so.1`mutex_lock_internal+0x218 > > ... rest of stack > > 0 11029 lwp_mutex_timedlock:return lwp_mutex_timedlock > > 2007 Jan 12 10:35:50 > > > > So I got a stack, so the method took longer than 6 seconds, but the > > walltimestamps between entry and exit show less than a 1 second difference. > > How can that be ? > > Plus I get nothing from the fbt probe. > > > > rick > > -- > > > > Rickey C. Weisner > > Software Development and Performance Specialist > > Sun Microsystems, INC > > cell phone: 615-308-1147 > > email: rick.weisner at sun.com > > _______________________________________________ > > dtrace-discuss mailing list > > dtrace-discuss at opensolaris.org > > -- > Adam Leventhal, Solaris Kernel Development http://blogs.sun.com/ahl-- Rickey C. Weisner Software Development and Performance Specialist Sun Microsystems, INC cell phone: 615-308-1147 email: rick.weisner at sun.com