iosnoop, iotop, opensnoop, execsnoop, opensnoop, dtruss and other dtrace based commands don't work on osx El capitan, macOS Sierra

Ara Yeressian picture Ara Yeressian · Nov 19, 2015 · Viewed 9.8k times · Source

While running iosnoop command on OSX 10.11.1 I get an error with the following text:

dtrace: invalid probe specifier
 /*
  * Command line arguments
  */
 inline int OPT_dump    = 0;
 inline int OPT_device  = 0;
 inline int OPT_delta   = 0;
 inline int OPT_devname = 0;
 inline int OPT_file    = 0;
 inline int OPT_args    = 0;
 inline int OPT_ins     = 0;
 inline int OPT_nums    = 0;
 inline int OPT_dtime   = 0;
 inline int OPT_mount   = 0;
 inline int OPT_start   = 0;
 inline int OPT_pid     = 0;
 inline int OPT_name    = 0;
 inline int OPT_end     = 0;
 inline int OPT_endstr  = 0;
 inline int FILTER  = 0;
 inline int PID     = 0;
 inline string DEVICE   = ".";
 inline string FILENAME = ".";
 inline string MOUNT    = ".";
 inline string NAME     = ".";

 #pragma D option quiet
 #pragma D option switchrate=10hz

 /*
  * Print header
  */
 dtrace:::BEGIN
 {
    last_event[""] = 0;

    /* print optional headers */
    OPT_start   ? printf("%-14s ","STIME")   : 1;
    OPT_end     ? printf("%-14s ","TIME")    : 1;
    OPT_endstr  ? printf("%-20s ","STRTIME") : 1;
    OPT_devname ? printf("%-7s ","DEVICE")   : 1;
    OPT_ins     ? printf("%-3s ","INS")      : 1;
    OPT_nums    ? printf("%-3s %-3s ","MAJ","MIN") : 1;
    OPT_delta   ? printf("%-10s ","DELTA")   : 1;
    OPT_dtime   ? printf("%-10s ","DTIME")   : 1;

    /* print main headers */
    OPT_dump ?
        printf("%s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s %s\n",
        "TIME", "STIME", "DELTA", "DEVICE", "INS", "MAJ", "MIN", "UID",
        "PID", "PPID", "D", "BLOCK", "SIZE", "MOUNT", "FILE", "PATH",
        "COMM","ARGS") :
        printf("%5s %5s %1s %8s %6s ", "UID", "PID", "D", "BLOCK", "SIZE");
    OPT_args == 0 ? printf("%10s %s\n", "COMM", "PATHNAME") : 1;
    OPT_args == 1 ? printf("%28s %s\n", "PATHNAME", "ARGS") : 1;
 }

 /*
  * Check event is being traced
  */
 io:::start
 {
    /* default is to trace unless filtering, */
    self->ok = FILTER ? 0 : 1;

    /* check each filter, */
    (OPT_device == 1 && DEVICE == args[1]->dev_statname)? self->ok = 1 : 1;
    (OPT_file == 1 && FILENAME == args[2]->fi_pathname) ? self->ok = 1 : 1;
    (OPT_mount == 1 && MOUNT == args[2]->fi_mount) ? self->ok = 1 : 1;
    (OPT_name == 1 && NAME == strstr(NAME, execname)) ? self->ok = 1 : 1;
    (OPT_name == 1 && execname == strstr(execname, NAME)) ? self->ok = 1 : 1;
    (OPT_pid == 1 && PID == pid) ? self->ok = 1 : 1;
 }

 /*
  * Reset last_event for disk idle -> start
  * this prevents idle time being counted as disk time.
  */
 io:::start
 /! pending[args[1]->dev_statname]/
 {
    /* save last disk event */
    last_event[args[1]->dev_statname] = timestamp;
 }

 /*
  * Store entry details
  */
 io:::start
 /self->ok/
 {
    /* these are used as a unique disk event key, */
    this->dev = args[0]->b_edev;
    this->blk = args[0]->b_blkno;

    /* save disk event details, */
    start_uid[this->dev, this->blk] = (int)uid;
    start_pid[this->dev, this->blk] = pid;
    start_ppid[this->dev, this->blk] = ppid;
    start_args[this->dev, this->blk] = (char *)curpsinfo->pr_psargs;
    start_comm[this->dev, this->blk] = execname;
    start_time[this->dev, this->blk] = timestamp;

    /* increase disk event pending count */
    pending[args[1]->dev_statname]++;

    self->ok = 0;
 }

 /*
  * Process and Print completion
  */
 io:::done
 /start_time[args[0]->b_edev, args[0]->b_blkno]/
 {
    /* decrease disk event pending count */
    pending[args[1]->dev_statname]--;

    /*
     * Process details
     */

    /* fetch entry values */
    this->dev = args[0]->b_edev;
    this->blk = args[0]->b_blkno;
    this->suid = start_uid[this->dev, this->blk];
    this->spid = start_pid[this->dev, this->blk];
    this->sppid = start_ppid[this->dev, this->blk];
    self->sargs = (int)start_args[this->dev, this->blk] == 0 ?
        "" : start_args[this->dev, this->blk];
    self->scomm = start_comm[this->dev, this->blk];
    this->stime = start_time[this->dev, this->blk];
    this->etime = timestamp; /* endtime */
    this->delta = this->etime - this->stime;
    this->dtime = last_event[args[1]->dev_statname] == 0 ? 0 :
        timestamp - last_event[args[1]->dev_statname];

    /* memory cleanup */
    start_uid[this->dev, this->blk]  = 0;
    start_pid[this->dev, this->blk]  = 0;
    start_ppid[this->dev, this->blk] = 0;
    start_args[this->dev, this->blk] = 0;
    start_time[this->dev, this->blk] = 0;
    start_comm[this->dev, this->blk] = 0;
    start_rw[this->dev, this->blk]   = 0;

    /*
     * Print details
     */

    /* print optional fields */
    OPT_start   ? printf("%-14d ", this->stime/1000) : 1;
    OPT_end     ? printf("%-14d ", this->etime/1000) : 1;
    OPT_endstr  ? printf("%-20Y ", walltimestamp) : 1;
    OPT_devname ? printf("%-7s ", args[1]->dev_statname) : 1;
    OPT_ins     ? printf("%3d ", args[1]->dev_instance) : 1;
    OPT_nums    ? printf("%3d %3d ",
        args[1]->dev_major, args[1]->dev_minor) : 1;
    OPT_delta   ? printf("%-10d ", this->delta/1000) : 1;
    OPT_dtime   ? printf("%-10d ", this->dtime/1000) : 1;

    /* print main fields */
    OPT_dump ?
        printf("%d %d %d %s %d %d %d %d %d %d %s %d %d %s %s %s %s %S\n",
        this->etime/1000, this->stime/1000, this->delta/1000,
        args[1]->dev_statname, args[1]->dev_instance, args[1]->dev_major,
        args[1]->dev_minor, this->suid, this->spid, this->sppid,
        args[0]->b_flags & B_READ ? "R" : "W",
        args[0]->b_blkno, args[0]->b_bcount, args[2]->fi_mount,
        args[2]->fi_name, args[2]->fi_pathname, self->scomm, self->sargs) :
        printf("%5d %5d %1s %8d %6d ",
        this->suid, this->spid, args[0]->b_flags & B_READ ? "R" : "W",
        args[0]->b_blkno, args[0]->b_bcount);
    OPT_args == 0 ? printf("%10s %s\n", self->scomm, args[2]->fi_pathname)
        : 1;
    OPT_args == 1 ? printf("%28s %S\n",
        args[2]->fi_pathname, self->sargs) : 1;

    /* save last disk event */
    last_event[args[1]->dev_statname] = timestamp;

    /* cleanup */
    self->scomm = 0;
    self->sargs = 0;
 }

 /*
  * Prevent pending from underflowing
  * this can happen if this program is started during disk events.
  */
 io:::done
 /pending[args[1]->dev_statname] < 0/
 {
    pending[args[1]->dev_statname] = 0;
 }
: probe description io:::start does not match any probes

Tested on two machines running the same version of OSX and got the same error. Also tested on 10.10 and it worked as it should.

Answer

Marc Bejarano picture Marc Bejarano · Jan 5, 2016

iosnoop relies on the dtrace subsystem. from: http://jimtechstuff.blogspot.com/2015/10/dtrace-broken-under-el-capitan.html


Dtrace is broken under El Capitan

One of the tools that I use quite a lot in debugging is 'dtrace' and the various utilities that use it. e.g. open snoop, iotop and a few that I wrote myself.

With the GA of El Capitan, any utility that resides in a system directory cannot be traced by dtrace which is a bit of a problem. I was wanting to see what open system calls the Photos app was using and came across this.

I know I could have used some other Mac utilities (fs_usage, sc_usage etc.) but I'm showing my Solaris roots here and I still wanted to use dtrace.

Fortunately there looks to be a way of enabling dtrace:

Reboot the mac
Hold ⌘R during reboot
From the Utilities menu, run Terminal
Enter the following command
csrutil enable --without dtrace

Note, that when doing so I got the following warning:

This is an unsupported configuration, likely to break in the future and leave your machine in an unknown state.

I'll live with it just now.


(I wanted to just add a comment to Ara Yeressian's mostly correct answer, but stackoverflow won't let me with my current low reputation)