[dtrace-discuss] Re: timestamp and walltimestamp

[rickey c weisner]

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