syscalls_in_mutex_wait.d

#!/usr/sbin/dtrace -ZCs
#pragma D option quiet
/*
   This file is part of demos for "Latch, Mutex and beyond" blog http://AndreyNikolaev.wordpress.com
   Copyright: (c) Andrey S. Nikolaev (Andrey.Nikolaev@rdtex.ru)
   Trace operating system calls inside the mutex wait. 24.08.2011
*/
#include <sys/sem.h>
#include <sys/time.h>

pid$target::kgxSharedExamine:entry
{
 printf("%s(0x%X,mutex=0x%X,aol=0x%X)\n",probefunc,arg0,arg1,arg2); 
 in_mutex=1;
 prev_syscall=" ";
 cntr=0;
 flag=0;
 prev_timeout=(long) 0;
}

pid$target::kgxSharedExamine:return
{
 in_mutex=0;
}

syscall:::entry
/(pid == $target) &&in_mutex/
{
 cntr++;
 probefunc==prev_syscall?1:(flag=1);
}

syscall::pollsys:entry
/(pid == $target) &&in_mutex/
{
 this->timespec=(timestruc_t *)copyin((uintptr_t) arg2 ,sizeof(timestruc_t));
 timeout=(long) this->timespec->tv_sec*100+ (long) this->timespec->tv_nsec/1000000;
 timeout==prev_timeout?1:(flag=1);
}

syscall::semsys:entry
/(pid == $target) &&in_mutex&& ((int)arg0 == 2)/	/* semop syscall -  wait until posted */
{
 timeout=(long)(-1);
 timeout==prev_timeout?1:(flag=1);
}

syscall::semsys:entry
/(pid == $target) &&in_mutex&& ((int)arg0 == 4)/	/* semtimedop syscall -  timed wait */
{
 this->timespec=(timestruc_t *)copyin((uintptr_t) arg4 ,sizeof(timestruc_t));
 timeout=(long) this->timespec->tv_sec*100+ (long) this->timespec->tv_nsec/1000000;
 timeout==prev_timeout?1:(flag=1);
}

syscall:::entry
/(pid == $target) &&in_mutex&&flag&&(cntr>1)/
{
 printf("  %s()",prev_syscall);
}

syscall:::entry
/(pid == $target) &&in_mutex&&flag&&(cntr>1)&&((prev_syscall=="pollsys")||(prev_syscall=="semsys"))/
{
 printf("   timeout=%d ms   ",prev_timeout);
}

syscall:::entry
/(pid == $target) &&in_mutex&&flag&&(cntr>2)/
{
 printf(" call repeated %d times",cntr-1);
}

syscall:::entry
/(pid == $target) &&in_mutex&&flag/
{
 printf("\n");
 flag=0;
 cntr=1;
 prev_syscall=probefunc;
 prev_timeout=timeout;
}