Re: New DTrace source snapshot

Hi John,

Snapshot dtrace-20080211.tar.bz compiled well for me on i386. However
during boot with DTrace I am getting the following tracebacks:

GEOM_LABEL: Label for provider acd0 is iso9660/FreeBSD_Install.
WARNING: WITNESS option enabled, expect reduced performance.
lock order reversal:
  1st 0xc2302e28 devfs (devfs) _at_ /usr/src/sys/kern/vfs_subr.c:2061
  2nd 0xc2388894 devfsmount (devfsmount) _at_
/usr/src/sys/fs/devfs/devfs_vnops.c:201
KDB: stack backtrace:
db_trace_self_wrapper(c0ac0b5c,cbd0ebbc,c078457d,c0ac2fb8,c2388894,...)
at db_trace_self_wrapper+0x26
kdb_backtrace(c0ac2fb8,c2388894,c0ab4500,c0ab4500,c0ab4541,...) at
kdb_backtrace+0x29
witness_checkorder(c2388894,9,c0ab4541,c9,0,...) at witness_checkorder+0x6af
_sx_xlock(c2388894,0,c0ab4541,c9,c2388894,...) at _sx_xlock+0x77
devfs_allocv(c231a200,c2393000,cbd0ec28,c20e8d20,c0ac8dd7,...) at
devfs_allocv+0x13e
devfs_root(c2393000,2,c0c2da58,c20e8d20,ca,...) at devfs_root+0x51
set_rootvnode(c0c2da40,0,c0ac8dd7,5ed,c07bf0ca,...) at set_rootvnode+0x2b
vfs_mountroot(c0bdb670,4,c0ab89a2,260,cbd0ecc4,...) at vfs_mountroot+0x334
start_init(0,cbd0ed38,c0aba2c5,323,c20e6ac0,...) at start_init+0x65
fork_exit(c0718755,0,cbd0ed38) at fork_exit+0xb8
fork_trampoline() at fork_trampoline+0x8
--- trap 0, eip = 0, esp = 0xcbd0ed70, ebp = 0 ---
Trying to mount root from ufs:/dev/ad0s1a
lock order reversal:
  1st 0xc23029e8 ufs (ufs) _at_ /usr/src/sys/kern/vfs_subr.c:2061
  2nd 0xc2393000 vfslock (vfslock) _at_ /usr/src/sys/kern/vfs_subr.c:364
KDB: stack backtrace:
db_trace_self_wrapper(c0ac0b5c,cbd0e9e0,c078457d,c0ac2fb8,c2393000,...)
at db_trace_self_wrapper+0x26
kdb_backtrace(c0ac2fb8,c2393000,c0ac8ed5,c0ac8ed5,c0ac9472,...) at
kdb_backtrace+0x29
witness_checkorder(c2393000,1,c0ac9472,16c,151,...) at
witness_checkorder+0x6af
_lockmgr(c2393000,2001,c2393030,c0ac9472,16c,...) at _lockmgr+0x167
vfs_busy(c2393000,0,0,c20e8d20,cbd0eb58,...) at vfs_busy+0x187
lookup(cbd0eb44,c0ac8b85,c6,bf,c20cd02c,...) at lookup+0x78c
namei(cbd0eb44,c0b76804,c0c2d2b8,c0ac8dd7,c2393030,...) at namei+0x32c
kern_unlink(c20e8d20,c0ac9214,1,628,0,...) at kern_unlink+0x39
vfs_mountroot_try(c0ac93ce,c0ab76c3,c0ab05ae,1,c07bf0ca,...) at
vfs_mountroot_try+0x466
vfs_mountroot(c0bdb670,4,c0ab89a2,260,cbd0ecc4,...) at vfs_mountroot+0x3f6
start_init(0,cbd0ed38,c0aba2c5,323,c20e6ac0,...) at start_init+0x65
fork_exit(c0718755,0,cbd0ed38) at fork_exit+0xb8
fork_trampoline() at fork_trampoline+0x8
--- trap 0, eip = 0, esp = 0xcbd0ed70, ebp = 0 ---
lock order reversal:
  1st 0xc20ec044 user map (user map) _at_ /usr/src/sys/vm/vm_map.c:3111
  2nd 0xc23027c8 ufs (ufs) _at_ /usr/src/sys/kern/vfs_subr.c:2061
KDB: stack backtrace:
db_trace_self_wrapper(c0ac0b5c,cbd0e9c8,c078457d,c0ac2fb8,c23027c8,...)
at db_trace_self_wrapper+0x26
kdb_backtrace(c0ac2fb8,c23027c8,c0ab7f76,c0ab7f76,c0ac9472,...) at
kdb_backtrace+0x29
witness_checkorder(c23027c8,1,c0ac9472,80d,0,...) at
witness_checkorder+0x6af
_lockmgr(c23027c8,3041,c23027f8,c0ac9472,80d,...) at _lockmgr+0x167
ffs_lock(cbd0ea74,c073ff64,c0be6c34,3041,c2302770,...) at ffs_lock+0x83
VOP_LOCK1_APV(c0b919c0,cbd0ea74,c0ab76c1,3,c23027f8,...) at
VOP_LOCK1_APV+0xab
_vn_lock(c2302770,3041,c0ac9472,80d,0,...) at _vn_lock+0xe8
vget(c2302770,3041,c20e8d20,4a9,c1460a00,...) at vget+0xff
vnode_pager_lock(c1460880,0,c0adfa2f,127,cbd0ebe8,...) at
vnode_pager_lock+0x1a5
vm_fault(c20ec000,80ce000,2,8,80ce000,...) at vm_fault+0x1dc
trap_pfault(5,0,c0aede07,2ed,c20e6ac0,...) at trap_pfault+0x117
trap(cbd0ed38) at trap+0x281
calltrap() at calltrap+0x6
--- trap 0xc, eip = 0x80480e5, esp = 0xbfbfeef0, ebp = 0xbfbfef10 ---

Not sure how much of it is connected to DTrace code itself.
Then I tried running a bunch of scripts and failed mostly because many
probes were not implemented. But the real reason that I am writing is
that when I run the following:
#!/usr/sbin/dtrace -Zs

#pragma D option quiet

dtrace:::BEGIN
{
         printf("Tracing... Hit Ctrl-C to end.\n");
}

sh*:::line
{
         _at_lines[pid, uid, copyinstr(arg0)] = count();
}

dtrace:::END
{
         printf("   %6s %6s %6s %s\n", "PID", "UID", "LINES", "FILE");
         printa("   %6d %6d %_at_6d %s\n", _at_lines);
}

I see nothing:
[andrew_at_freebsd8-current /usr/local/DTT/Bin]$ sudo ./sh_who.d
Tracing... Hit Ctrl-C to end.
<20 seconds elapses during which there was user activity>
^C
       PID    UID  LINES FILE

Or another example that similarly gives no output:

#!/usr/sbin/dtrace -Zs

#pragma D option quiet

dtrace:::BEGIN
{
         printf("Tracing... Hit Ctrl-C to end.\n");
}

sh*:::function-entry
{
         self->depth++;
         self->function[self->depth] = vtimestamp;
         self->exclude[self->depth] = 0;
}

sh*:::function-return
/self->function[self->depth]/
{
         this->oncpu_incl = vtimestamp - self->function[self->depth];
         this->oncpu_excl = this->oncpu_incl - self->exclude[self->depth];
         self->function[self->depth] = 0;
         self->exclude[self->depth] = 0;
         this->file = basename(copyinstr(arg0));
         this->name = copyinstr(arg1);

         _at_num[this->file, "func", this->name] = count();
         _at_num["-", "total", "-"] = count();
         _at_types_incl[this->file, "func", this->name] =
sum(this->oncpu_incl);
         _at_types_excl[this->file, "func", this->name] =
sum(this->oncpu_excl);
         _at_types_excl["-", "total", "-"] = sum(this->oncpu_excl);

         self->depth--;
         self->exclude[self->depth] += this->oncpu_incl;
}

sh*:::builtin-entry
{
         self->builtin = vtimestamp;
}

sh*:::builtin-return
/self->builtin/
{
         this->oncpu = vtimestamp - self->builtin;
         self->builtin = 0;
         this->file = basename(copyinstr(arg0));
         this->name = copyinstr(arg1);

         _at_num[this->file, "builtin", this->name] = count();
         _at_num["-", "total", "-"] = count();
         _at_types[this->file, "builtin", this->name] = sum(this->oncpu);
         _at_types["-", "total", "-"] = sum(this->oncpu);

         self->exclude[self->depth] += this->oncpu;
}

sh*:::command-entry
{
         incmd[pid] = basename(copyinstr(arg0));
         depth[pid] = self->depth;
}

sh*:::command-return
{
         incmd[pid] = 0;
}

proc:::exec-success
{
         /*
          * Due to thread timing after fork(), this probe can fire before
          * sh*:::command-entry has, which means we can't predicate this
          * exec() away just yet. Store the vtimestamp in case it is needed.
          */
         self->command = vtimestamp;
}

proc:::exit
/incmd[ppid] == NULL/
{
         self->command = 0;
}

proc:::exit
/incmd[ppid] != NULL/
{
         this->oncpu = vtimestamp - self->command;
         self->command = 0;

         _at_num[incmd[ppid], "cmd", execname] = count();
         _at_num["-", "total", "-"] = count();
         _at_types[incmd[ppid], "cmd", execname] = sum(this->oncpu);
         _at_types["-", "total", "-"] = sum(this->oncpu);

         self->exclude[depth[ppid]] += this->oncpu;
         incmd[ppid] = 0;
         depth[ppid] = 0;
}

dtrace:::END
{
         printf("\nCounts,\n");
         printf("   %-20s %-10s %-32s %8s\n", "FILE", "TYPE", "NAME",
"COUNT");
         printa("   %-20s %-10s %-32s %_at_8d\n", _at_num);

         normalize(_at_types, 1000);
         printf("\nOn-CPU times (us),\n");
         printf("   %-20s %-10s %-32s %8s\n", "FILE", "TYPE", "NAME",
"TOTAL");
         printa("   %-20s %-10s %-32s %_at_8d\n", _at_types);

         normalize(_at_types_excl, 1000);
         printf("\nExclusive function on-CPU times (us),\n");
         printf("   %-20s %-10s %-32s %8s\n", "FILE", "TYPE", "NAME",
"TOTAL");
         printa("   %-20s %-10s %-32s %_at_8d\n", _at_types_excl);

         normalize(_at_types_incl, 1000);
         printf("\nInclusive function on-CPU times (us),\n");
         printf("   %-20s %-10s %-32s %8s\n", "FILE", "TYPE", "NAME",
"TOTAL");
         printa("   %-20s %-10s %-32s %_at_8d\n", _at_types_incl);
}

John Birrell wrote:
> This one fixes problems with the previous one:
> 
> - buildkernel would fail because NO_CTF=1 was not set when
>   building the lone kernel build tool.
> - A number of things were missing from the dtrace kernel 
>   module on i386.
> - Missing syscall names in the kernel without witness have
>   been resolved so this snapshot should build with and without
>   witness, invariants, smp etc.
> 
> <http://people.freebsd.org/~jb/dtrace/dtrace-20080211.tar.bz>

-- 
Sincerely,
Andrew Pogrebennyk