Bug 191506 - [dtrace] [dtruss] dtruss doesn't seem to work on -HEAD
Summary: [dtrace] [dtruss] dtruss doesn't seem to work on -HEAD
Status: Closed Works As Intended
Alias: None
Product: Base System
Classification: Unclassified
Component: bin (show other bugs)
Version: CURRENT
Hardware: Any Any
: --- Affects Only Me
Assignee: freebsd-bugs (Nobody)
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2014-06-30 05:23 UTC by Adrian Chadd
Modified: 2014-08-09 04:49 UTC (History)
3 users (show)

See Also:

Attachments
Add an attachment (proposed patch, testcase, etc.)

Note You need to log in before you can comment on or make changes to this bug.
Description Adrian Chadd freebsd_committer freebsd_triage 2014-06-30 05:23:52 UTC 
Compiled up a fresh -HEAD as of the timestamp:

FreeBSD adrian-hackbox 11.0-CURRENT FreeBSD 11.0-CURRENT #1 b01e1c9(local/rss)-dirty: Mon Jun 30 04:51:05 UTC 2014     adrian@adrian-hackbox:/usr/home/adrian/git/github/erikarn/freebsd-obj/usr/home/adrian/git/github/erikarn/freebsd/sys/RSS  amd64

.. and then looked at using the userland dtrace bits. The first example i found from:

https://wiki.freebsd.org/DTrace/userland

was to use dtruss, so I tried it.

It didn't work.

root@adrian-hackbox:/home/adrian/git/github/erikarn/freebsd-rss/rss-http # dtruss -c date
dtrace: invalid probe specifier 
#pragma D option quiet
#pragma D option switchrate=10
 
/*
 * Command line arguments
 */
inline int OPT_command   = 1;
inline int OPT_follow    = 0;
inline int OPT_printid   = 0;
inline int OPT_relative  = 0;
inline int OPT_elapsed   = 0;
inline int OPT_cpu       = 0;
inline int OPT_counts    = 1;
inline int OPT_pid       = 0;
inline int OPT_name      = 0;
inline int OPT_trace     = 0;
inline int OPT_stack     = 0;
inline string NAME       = ".";
inline string TRACE      = ".";

dtrace:::BEGIN 
{
        /* print header */
        OPT_printid  ? printf("%-9s  ", "PID/LWP") : 1;
        OPT_relative ? printf("%8s ", "RELATIVE") : 1;
        OPT_elapsed  ? printf("%7s ", "ELAPSD") : 1;
        OPT_cpu      ? printf("%6s ", "CPU") : 1;
        printf("SYSCALL(args) \t\t = return\n");
}

/*
 * Save syscall entry info
 */
syscall:::entry
/((OPT_command || OPT_pid) && pid == $target) || 
 (OPT_name && execname == NAME) ||
 (OPT_follow && progenyof($target))/
{
        /* set start details */
        self->start = timestamp;
        self->vstart = vtimestamp;
        self->arg0 = arg0;
        self->arg1 = arg1;
        self->arg2 = arg2;

        /* count occurances */
        OPT_counts == 1 ? @Counts[probefunc] = count() : 1;
}

/*
 * Follow children
 */
syscall::fork*:return
/(OPT_follow && progenyof($target)) && (!OPT_trace || (TRACE == probefunc))/
{
        /* print output */
        self->code = errno == 0 ? "" : "Err#";
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d:  ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d:  ", 0) : 1;
        OPT_cpu      ? printf("%6d ", 0) : 1;
        printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
            self->arg0, self->arg1, self->arg2, (int)arg0, self->code,
            (int)errno);
}

/*
 * Check for syscall tracing
 */
syscall:::entry
/OPT_trace && probefunc != TRACE/
{
        /* drop info */
        self->start = 0;
        self->vstart = 0;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/*
 * Print return data
 */

/*
 * The following code is written in an intentionally repetative way.
 * The first versions had no code redundancies, but performed badly during
 * benchmarking. The priority here is speed, not cleverness. I know there
 * are many obvious shortcuts to this code, I have tried them. This style has
 * shown in benchmarks to be the fastest (fewest probes fired, fewest actions).
 */

/* print 3 args, return as hex */
syscall::sigprocmask:return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s(0x%X, 0x%X, 0x%X)\t\t = 0x%X %s%d\n", probefunc,
            (int)self->arg0, self->arg1, self->arg2, (int)arg0,
            self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* print 3 args, arg0 as a string */
syscall::access*:return,
syscall::stat*:return, 
syscall::lstat*:return, 
syscall::readlink*:return,
syscall::open*:return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s(\"%S\", 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
            copyinstr(self->arg0), self->arg1, self->arg2, (int)arg0,
            self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* print 3 args, arg1 as a string */
syscall::write:return,
syscall::pwrite:return,
syscall::*read*:return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
            stringof(copyin(self->arg1, self->arg2)), self->arg2, (int)arg0,
            self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* print 0 arg output */
syscall::*fork*:return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s()\t\t = %d %s%d\n", probefunc,
            (int)arg0, self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* print 1 arg output */
syscall::close:return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s(0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
            (int)arg0, self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* print 2 arg output */
syscall::utimes:return,
syscall::munmap:return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s(0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
            self->arg1, (int)arg0, self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* print 3 arg output - default */
syscall:::return
/self->start/
{
        /* calculate elapsed time */
        this->elapsed = timestamp - self->start;
        self->start = 0;
        this->cpu = vtimestamp - self->vstart;
        self->vstart = 0;
        self->code = errno == 0 ? "" : "Err#";
 
        /* print optional fields */
        OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
        OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
        OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
        OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
        /* print main data */
        printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
            self->arg1, self->arg2, (int)arg0, self->code, (int)errno);
        OPT_stack ? ustack()    : 1;
        OPT_stack ? trace("\n") : 1;
        self->arg0 = 0;
        self->arg1 = 0;
        self->arg2 = 0;
}

/* program exited */
proc:::exit
/(OPT_command || OPT_pid) && pid == $target/
{
        exit(0);
}

/* print counts */
dtrace:::END
{
        OPT_counts == 1 ? printf("\n%-32s %16s\n", "CALL", "COUNT") : 1;
        OPT_counts == 1 ? printa("%-32s %@16d\n", @Counts) : 1;
}
: "/usr/lib/dtrace/errno.d", line 150: failed to resolve INP_IPV4: Unknown variable name
Comment 1 Ed Maste freebsd_committer freebsd_triage 2014-06-30 14:48:14 UTC 
Tried on my just-built -HEAD (in QEMU) and it works:

root@:~ # dtruss -c date
dtrace: buffer size lowered to 512k
dtrace: aggregation size lowered to 512k
SYSCALL(args)            = return
Mon Jun 30 14:45:05 UTC 2014
mmap(0x0, 0x8000, 0x3)           = 6422528 0
issetugid(0x0, 0x0, 0x0)                 = 0 0
lstat("/etc\0", 0x7FFFFFFFD438, 0x0)             = 0 0
lstat("/etc/libmap.conf\0", 0x7FFFFFFFD438, 0x0)                 = 0 0
open("/etc/libmap.conf\0", 0x100000, 0x3F0)              = 3 0
fstat(0x3, 0x7FFFFFFFE0F0, 0x0)          = 0 0
mmap(0x0, 0x2F, 0x1)             = 6455296 0
close(0x3)               = 0 0
...
Comment 2 Adrian Chadd freebsd_committer freebsd_triage 2014-06-30 16:57:23 UTC 
Well, how do I debug it? line 150 of errno.d doesn't at all look like the missing variable in question.
Comment 3 Mark Johnston freebsd_committer freebsd_triage 2014-06-30 16:59:13 UTC 
(In reply to Adrian Chadd from comment #2)
> Well, how do I debug it? line 150 of errno.d doesn't at all look like the
> missing variable in question.

Could you try running with the DTRACE_DEBUG environment variable set to 1, and paste the output?
Comment 4 Adrian Chadd freebsd_committer freebsd_triage 2014-06-30 17:27:24 UTC 
root@adrian-hackbox:/home/adrian # env DTRACE_DEBUG=1 dtruss date
libdtrace DEBUG: opened provider dtrace
libdtrace DEBUG: opened 64-bit module kernel () [0]
libdtrace DEBUG: opened 64-bit module sem.ko () [0]
libdtrace DEBUG: opened 64-bit module uhid.ko () [0]
libdtrace DEBUG: opened 64-bit module snd_uaudio.ko () [0]
libdtrace DEBUG: opened 64-bit module ums.ko () [0]
libdtrace DEBUG: opened 64-bit module uftdi.ko () [0]
libdtrace DEBUG: opened 64-bit module ucom.ko () [0]
libdtrace DEBUG: opened 64-bit module hwpmc.ko () [0]
libdtrace DEBUG: opened 64-bit module dtrace.ko () [0]
libdtrace DEBUG: opened 64-bit module cyclic.ko () [0]
libdtrace DEBUG: opened 64-bit module opensolaris.ko () [0]
libdtrace DEBUG: opened 64-bit module ksyms.ko () [0]
libdtrace DEBUG: created CTF container for C (0x802830580)
libdtrace DEBUG: created CTF container for D (0x802830800)
libdtrace DEBUG: loaded kernel [.SUNW_ctf] (734272 bytes)
libdtrace DEBUG: loaded kernel [.symtab] (1308384 bytes)
libdtrace DEBUG: loaded kernel [.strtab] (1421142 bytes)
libdtrace DEBUG: hashed kernel [.symtab] (54475 symbols)
libdtrace DEBUG: sorted kernel [.symtab] (54422 symbols)
libdtrace DEBUG: loaded CTF container for kernel (0x802830a80)
libdtrace DEBUG: loaded printf conversion %a
libdtrace DEBUG: loaded printf conversion %A
libdtrace DEBUG: loaded printf conversion %c
libdtrace DEBUG: loaded printf conversion %C
libdtrace DEBUG: loaded printf conversion %d
libdtrace DEBUG: loaded printf conversion %e
libdtrace DEBUG: loaded printf conversion %E
libdtrace DEBUG: loaded printf conversion %f
libdtrace DEBUG: loaded printf conversion %g
libdtrace DEBUG: loaded printf conversion %G
libdtrace DEBUG: loaded printf conversion %hd
libdtrace DEBUG: loaded printf conversion %hi
libdtrace DEBUG: loaded printf conversion %ho
libdtrace DEBUG: loaded printf conversion %hu
libdtrace DEBUG: loaded printf conversion %hx
libdtrace DEBUG: loaded printf conversion %hX
libdtrace DEBUG: loaded printf conversion %i
libdtrace DEBUG: loaded printf conversion %I
libdtrace DEBUG: loaded printf conversion %k
libdtrace DEBUG: loaded printf conversion %lc
libdtrace DEBUG: loaded printf conversion %ld
libdtrace DEBUG: loaded printf conversion %li
libdtrace DEBUG: loaded printf conversion %lo
libdtrace DEBUG: loaded printf conversion %lu
libdtrace DEBUG: loaded printf conversion %ls
libdtrace DEBUG: loaded printf conversion %lx
libdtrace DEBUG: loaded printf conversion %lX
libdtrace DEBUG: loaded printf conversion %lld
libdtrace DEBUG: loaded printf conversion %lli
libdtrace DEBUG: loaded printf conversion %llo
libdtrace DEBUG: loaded printf conversion %llu
libdtrace DEBUG: loaded printf conversion %llx
libdtrace DEBUG: loaded printf conversion %llX
libdtrace DEBUG: loaded printf conversion %Le
libdtrace DEBUG: loaded printf conversion %LE
libdtrace DEBUG: loaded printf conversion %Lf
libdtrace DEBUG: loaded printf conversion %Lg
libdtrace DEBUG: loaded printf conversion %LG
libdtrace DEBUG: loaded printf conversion %o
libdtrace DEBUG: loaded printf conversion %p
libdtrace DEBUG: loaded printf conversion %P
libdtrace DEBUG: loaded printf conversion %s
libdtrace DEBUG: loaded printf conversion %S
libdtrace DEBUG: loaded printf conversion %T
libdtrace DEBUG: loaded printf conversion %u
libdtrace DEBUG: loaded printf conversion %wc
libdtrace DEBUG: loaded printf conversion %ws
libdtrace DEBUG: loaded printf conversion %x
libdtrace DEBUG: loaded printf conversion %X
libdtrace DEBUG: loaded printf conversion %Y
libdtrace DEBUG: loaded printf conversion %%
libdtrace DEBUG: populating global idhash from 0x800cdf330
libdtrace DEBUG: loaded sem.ko [.SUNW_ctf] (17127 bytes)
libdtrace DEBUG: loaded sem.ko [.symtab] (3696 bytes)
libdtrace DEBUG: loaded sem.ko [.strtab] (2533 bytes)
libdtrace DEBUG: hashed sem.ko [.symtab] (141 symbols)
libdtrace DEBUG: sorted sem.ko [.symtab] (56 symbols)
libdtrace DEBUG: loaded CTF container for sem.ko (0x802830d00)
libdtrace DEBUG: loaded uhid.ko [.SUNW_ctf] (5077 bytes)
libdtrace DEBUG: loaded uhid.ko [.symtab] (2904 bytes)
libdtrace DEBUG: loaded uhid.ko [.strtab] (2190 bytes)
libdtrace DEBUG: hashed uhid.ko [.symtab] (107 symbols)
libdtrace DEBUG: sorted uhid.ko [.symtab] (36 symbols)
libdtrace DEBUG: loaded CTF container for uhid.ko (0x802831200)
libdtrace DEBUG: loaded snd_uaudio.ko [.SUNW_ctf] (15626 bytes)
libdtrace DEBUG: loaded snd_uaudio.ko [.symtab] (7224 bytes)
libdtrace DEBUG: loaded snd_uaudio.ko [.strtab] (6236 bytes)
libdtrace DEBUG: hashed snd_uaudio.ko [.symtab] (286 symbols)
libdtrace DEBUG: sorted snd_uaudio.ko [.symtab] (134 symbols)
libdtrace DEBUG: loaded CTF container for snd_uaudio.ko (0x802831480)
libdtrace DEBUG: loaded ums.ko [.SUNW_ctf] (4755 bytes)
libdtrace DEBUG: loaded ums.ko [.symtab] (3000 bytes)
libdtrace DEBUG: loaded ums.ko [.strtab] (2150 bytes)
libdtrace DEBUG: hashed ums.ko [.symtab] (111 symbols)
libdtrace DEBUG: sorted ums.ko [.symtab] (29 symbols)
libdtrace DEBUG: loaded CTF container for ums.ko (0x802831700)
libdtrace DEBUG: loaded uftdi.ko [.SUNW_ctf] (8047 bytes)
libdtrace DEBUG: loaded uftdi.ko [.symtab] (3312 bytes)
libdtrace DEBUG: loaded uftdi.ko [.strtab] (2645 bytes)
libdtrace DEBUG: hashed uftdi.ko [.symtab] (121 symbols)
libdtrace DEBUG: sorted uftdi.ko [.symtab] (47 symbols)
libdtrace DEBUG: loaded CTF container for uftdi.ko (0x802831980)
libdtrace DEBUG: loaded ucom.ko [.SUNW_ctf] (5755 bytes)
libdtrace DEBUG: loaded ucom.ko [.symtab] (3648 bytes)
libdtrace DEBUG: loaded ucom.ko [.strtab] (2552 bytes)
libdtrace DEBUG: hashed ucom.ko [.symtab] (136 symbols)
libdtrace DEBUG: sorted ucom.ko [.symtab] (69 symbols)
libdtrace DEBUG: loaded CTF container for ucom.ko (0x802832100)
libdtrace DEBUG: loaded hwpmc.ko [.SUNW_ctf] (32595 bytes)
libdtrace DEBUG: loaded hwpmc.ko [.symtab] (9384 bytes)
libdtrace DEBUG: loaded hwpmc.ko [.strtab] (6451 bytes)
libdtrace DEBUG: hashed hwpmc.ko [.symtab] (377 symbols)
libdtrace DEBUG: sorted hwpmc.ko [.symtab] (253 symbols)
libdtrace DEBUG: loaded CTF container for hwpmc.ko (0x802832b00)
libdtrace DEBUG: loaded dtrace.ko [.SUNW_ctf] (26565 bytes)
libdtrace DEBUG: loaded dtrace.ko [.symtab] (12000 bytes)
libdtrace DEBUG: loaded dtrace.ko [.strtab] (9234 bytes)
libdtrace DEBUG: hashed dtrace.ko [.symtab] (484 symbols)
libdtrace DEBUG: sorted dtrace.ko [.symtab] (362 symbols)
libdtrace DEBUG: loaded CTF container for dtrace.ko (0x802832d80)
libdtrace DEBUG: loaded cyclic.ko [.SUNW_ctf] (2921 bytes)
libdtrace DEBUG: loaded cyclic.ko [.symtab] (2232 bytes)
libdtrace DEBUG: loaded cyclic.ko [.strtab] (1734 bytes)
libdtrace DEBUG: hashed cyclic.ko [.symtab] (81 symbols)
libdtrace DEBUG: sorted cyclic.ko [.symtab] (40 symbols)
libdtrace DEBUG: loaded CTF container for cyclic.ko (0x802833000)
libdtrace DEBUG: loaded opensolaris.ko [.SUNW_ctf] (2445 bytes)
libdtrace DEBUG: loaded opensolaris.ko [.symtab] (3024 bytes)
libdtrace DEBUG: loaded opensolaris.ko [.strtab] (2128 bytes)
libdtrace DEBUG: hashed opensolaris.ko [.symtab] (113 symbols)
libdtrace DEBUG: sorted opensolaris.ko [.symtab] (63 symbols)
libdtrace DEBUG: loaded CTF container for opensolaris.ko (0x802833500)
libdtrace DEBUG: loaded ksyms.ko [.SUNW_ctf] (9952 bytes)
libdtrace DEBUG: loaded ksyms.ko [.symtab] (1896 bytes)
libdtrace DEBUG: loaded ksyms.ko [.strtab] (1263 bytes)
libdtrace DEBUG: hashed ksyms.ko [.symtab] (66 symbols)
libdtrace DEBUG: sorted ksyms.ko [.symtab] (23 symbols)
libdtrace DEBUG: loaded CTF container for ksyms.ko (0x802833c80)
libdtrace DEBUG: pid 12291: failed to find a.out`main: No error: 0
libdtrace DEBUG: breakpoints disabled
libdtrace DEBUG: created pid 12291
libdtrace DEBUG: error parsing library /usr/lib/dtrace/ip.d: "/usr/lib/dtrace/ip.d", line 28: program requires provider ip
libdtrace DEBUG: error parsing library /usr/lib/dtrace/io.d: "/usr/lib/dtrace/io.d", line 259: program requires provider io
libdtrace DEBUG: error parsing library /usr/lib/dtrace/udp.d: "/usr/lib/dtrace/udp.d", line 109: program requires provider udp
libdtrace DEBUG: error parsing library /usr/lib/dtrace/tcp.d: "/usr/lib/dtrace/tcp.d", line 75: program requires provider tcp
libdtrace DEBUG: library /usr/lib/dtrace/errno.d sorted (1/2)
libdtrace DEBUG: library /usr/lib/dtrace/udp.d sorted (4/5)
libdtrace DEBUG: library /usr/lib/dtrace/tcp.d sorted (6/7)
libdtrace DEBUG: library /usr/lib/dtrace/ip.d sorted (3/8)
libdtrace DEBUG: library /usr/lib/dtrace/io.d sorted (9/10)
libdtrace DEBUG: library /usr/lib/dtrace/signal.d sorted (11/12)
libdtrace DEBUG: library /usr/lib/dtrace/regs_x86.d sorted (13/14)
libdtrace DEBUG: library /usr/lib/dtrace/unistd.d sorted (15/16)
libdtrace DEBUG: library /usr/lib/dtrace/psinfo.d sorted (17/18)
libdtrace DEBUG: typedef psinfo_t added as id 32805
libdtrace DEBUG: typedef lwpsinfo_t added as id 32808
libdtrace DEBUG: skipping library /usr/lib/dtrace/io.d: "/usr/lib/dtrace/io.d", line 30: program requires provider io
libdtrace DEBUG: typedef devinfo_t added as id 32811
libdtrace DEBUG: typedef bufinfo_t added as id 32817
libdtrace DEBUG: skipping library /usr/lib/dtrace/ip.d: "/usr/lib/dtrace/ip.d", line 108: program requires provider ip
libdtrace DEBUG: typedef pktinfo_t added as id 32820
libdtrace DEBUG: typedef zoneid_t added as id 32821
libdtrace DEBUG: typedef csinfo_t added as id 32823
libdtrace DEBUG: typedef ipinfo_t added as id 32825
libdtrace DEBUG: typedef ifinfo_t added as id 32827
libdtrace DEBUG: typedef ipaddr_t added as id 32828
libdtrace DEBUG: typedef ipha_t added as id 32830
libdtrace DEBUG: typedef ipv4info_t added as id 32833
libdtrace DEBUG: typedef in6_addr_t added as id 32844
libdtrace DEBUG: typedef ip6_t added as id 32851
libdtrace DEBUG: typedef ipv6info_t added as id 32855
libdtrace DEBUG: skipping library /usr/lib/dtrace/tcp.d: "/usr/lib/dtrace/tcp.d", line 257: program requires library "/usr/lib/dtrace/ip.d" which failed to load
libdtrace DEBUG: skipping library /usr/lib/dtrace/udp.d: "/usr/lib/dtrace/udp.d", line 1: program requires provider tcp
libdtrace DEBUG: typedef tcpsinfo_t added as id 32864
libdtrace DEBUG: typedef tcplsinfo_t added as id 32866
libdtrace DEBUG: typedef tcpinfo_t added as id 32873
libdtrace DEBUG: typedef tcpinfoh_t added as id 32875
dtrace: invalid probe specifier 
#pragma D option quiet
#pragma D option switchrate=10
 
/*
 * Command line arguments
 */
inline int OPT_command   = 1;
inline int OPT_follow    = 0;
inline int OPT_printid   = 0;
inline int OPT_relative  = 0;
inline int OPT_elapsed   = 0;
inline int OPT_cpu       = 0;
inline int OPT_counts    = 0;
inline int OPT_pid       = 0;
inline int OPT_name      = 0;
inline int OPT_trace     = 0;
inline int OPT_stack     = 0;
inline string NAME       = ".";
inline string TRACE      = ".";

dtrace:::BEGIN 
{
	/* print header */
	OPT_printid  ? printf("%-9s  ", "PID/LWP") : 1;
	OPT_relative ? printf("%8s ", "RELATIVE") : 1;
	OPT_elapsed  ? printf("%7s ", "ELAPSD") : 1;
	OPT_cpu      ? printf("%6s ", "CPU") : 1;
	printf("SYSCALL(args) \t\t = return\n");
}

/*
 * Save syscall entry info
 */
syscall:::entry
/((OPT_command || OPT_pid) && pid == $target) || 
 (OPT_name && execname == NAME) ||
 (OPT_follow && progenyof($target))/
{
	/* set start details */
	self->start = timestamp;
	self->vstart = vtimestamp;
	self->arg0 = arg0;
	self->arg1 = arg1;
	self->arg2 = arg2;

	/* count occurances */
	OPT_counts == 1 ? @Counts[probefunc] = count() : 1;
}

/*
 * Follow children
 */
syscall::fork*:return
/(OPT_follow && progenyof($target)) && (!OPT_trace || (TRACE == probefunc))/
{
	/* print output */
	self->code = errno == 0 ? "" : "Err#";
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d:  ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d:  ", 0) : 1;
	OPT_cpu      ? printf("%6d ", 0) : 1;
	printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
	    self->arg0, self->arg1, self->arg2, (int)arg0, self->code,
	    (int)errno);
}

/*
 * Check for syscall tracing
 */
syscall:::entry
/OPT_trace && probefunc != TRACE/
{
	/* drop info */
	self->start = 0;
	self->vstart = 0;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/*
 * Print return data
 */

/*
 * The following code is written in an intentionally repetative way.
 * The first versions had no code redundancies, but performed badly during
 * benchmarking. The priority here is speed, not cleverness. I know there
 * are many obvious shortcuts to this code, I have tried them. This style has
 * shown in benchmarks to be the fastest (fewest probes fired, fewest actions).
 */

/* print 3 args, return as hex */
syscall::sigprocmask:return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s(0x%X, 0x%X, 0x%X)\t\t = 0x%X %s%d\n", probefunc,
	    (int)self->arg0, self->arg1, self->arg2, (int)arg0,
	    self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* print 3 args, arg0 as a string */
syscall::access*:return,
syscall::stat*:return, 
syscall::lstat*:return, 
syscall::readlink*:return,
syscall::open*:return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s(\"%S\", 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc,
	    copyinstr(self->arg0), self->arg1, self->arg2, (int)arg0,
	    self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* print 3 args, arg1 as a string */
syscall::write:return,
syscall::pwrite:return,
syscall::*read*:return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s(0x%X, \"%S\", 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
	    stringof(copyin(self->arg1, self->arg2)), self->arg2, (int)arg0,
	    self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* print 0 arg output */
syscall::*fork*:return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s()\t\t = %d %s%d\n", probefunc,
	    (int)arg0, self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* print 1 arg output */
syscall::close:return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s(0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
	    (int)arg0, self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* print 2 arg output */
syscall::utimes:return,
syscall::munmap:return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s(0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
	    self->arg1, (int)arg0, self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* print 3 arg output - default */
syscall:::return
/self->start/
{
	/* calculate elapsed time */
	this->elapsed = timestamp - self->start;
	self->start = 0;
	this->cpu = vtimestamp - self->vstart;
	self->vstart = 0;
	self->code = errno == 0 ? "" : "Err#";
 
	/* print optional fields */
	OPT_printid  ? printf("%6d/%d:  ", pid, tid) : 1;
	OPT_relative ? printf("%8d ", vtimestamp/1000) : 1;
	OPT_elapsed  ? printf("%7d ", this->elapsed/1000) : 1;
	OPT_cpu      ? printf("%6d ", this->cpu/1000) : 1;
 
	/* print main data */
	printf("%s(0x%X, 0x%X, 0x%X)\t\t = %d %s%d\n", probefunc, self->arg0,
	    self->arg1, self->arg2, (int)arg0, self->code, (int)errno);
	OPT_stack ? ustack()    : 1;
	OPT_stack ? trace("\n") : 1;
	self->arg0 = 0;
	self->arg1 = 0;
	self->arg2 = 0;
}

/* program exited */
proc:::exit
/(OPT_command || OPT_pid) && pid == $target/
{
	exit(0);
}

/* print counts */
dtrace:::END
{
	OPT_counts == 1 ? printf("\n%-32s %16s\n", "CALL", "COUNT") : 1;
	OPT_counts == 1 ? printa("%-32s %@16d\n", @Counts) : 1;
}
: "/usr/lib/dtrace/errno.d", line 150: failed to resolve INP_IPV4: Unknown variable name
libdtrace DEBUG: killing pid 12291
libdtrace DEBUG: breakpoints enabled
libdtrace DEBUG: breakpoints enabled
libdtrace DEBUG: dt_buf_destroy(section headers): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(string table): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(loadable data): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(unloadable data): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(probe data): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(probe args): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(probe offs): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(probe is-enabled offs): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(probe rels): size=512 resizes=0
libdtrace DEBUG: dt_buf_destroy(xlate members): size=512 resizes=0
root@adrian-hackbox:/home/adrian #
Comment 5 Adrian Chadd freebsd_committer freebsd_triage 2014-06-30 17:28:07 UTC 
Hm, I tried on a freshly installed -HEAD and it works. This has been upgraded (with make delete-old and make delete-old-libs) from -HEAD monthly for about twelve months.

I wonder if anything old is hanging around .
Comment 6 Mark Johnston freebsd_committer freebsd_triage 2014-06-30 17:33:53 UTC 
(In reply to Adrian Chadd from comment #5)
> Hm, I tried on a freshly installed -HEAD and it works. This has been
> upgraded (with make delete-old and make delete-old-libs) from -HEAD monthly
> for about twelve months.
> 
> I wonder if anything old is hanging around .

The debug output indicates that you don't have sdt.ko loaded (it can be loaded by kldloading dtraceall.ko). Rui changed libdtrace to automatically kldload dtraceall in r254197, a little under a year ago.
Comment 7 Adrian Chadd freebsd_committer freebsd_triage 2014-06-30 17:43:45 UTC 
Well, this is running a _really_ recent version of -HEAD. Is there some left over library crap floating around that may be being loaded that screws with this?


-a
Comment 8 Mark Johnston freebsd_committer freebsd_triage 2014-06-30 17:47:14 UTC 
(In reply to Adrian Chadd from comment #7)
> Well, this is running a _really_ recent version of -HEAD. Is there some left
> over library crap floating around that may be being loaded that screws with
> this?

There shouldn't be. We look at the debug.dtrace.providers sysctl to see which providers are available. In your case it looks like libdtrace isn't seeing a few of them (ip, io, tcp, udp). The error message is bogus I think; there are some bugs in libdtrace's D parser's error handling.
Comment 9 Rui Paulo freebsd_committer freebsd_triage 2014-08-09 04:49:12 UTC 
Adrian, isn't this a problem with your environment?  Shall we close?