dtrace discuss - Jun 2007 - 2 iosnoop scripts: different results

I am teaching a DTrace class and a student noticed that 2 iosnoop scripts run in
two different windows were producing different results. I was not able to answer
why this is. Can anyone explain this. Here are the reults from the two windows:

# io.d
...
           sched     0                           <none>    1024       dad1
W   0.156
            bash  1998                     /dtrace/mod2    1024       dad1  R  
8.807
            bash  5184                      /usr/bin/ls    8192       dad1  R 
10.332
              ls  5184            /dtrace/mod2/examples    1024       dad1  R  
0.259
         fsflush     3               /var/tmp/dtrace-1b    8192       dad1  W  
0.278

# io.d
...
           sched     0                           <none>    1024       dad1
W   0.176
            bash  1998                     /dtrace/mod2    1024       dad1  R  
8.835
            bash  5184                      /usr/bin/ls    8192       dad1  R 
10.360
              ls  5184            /dtrace/mod2/examples    1024       dad1  R  
0.285
         fsflush     3               /var/tmp/dtrace-1b    8192       dad1  W  
0.307

Here is the script:
#!/usr/sbin/dtrace -qs

#pragma D option dynvarsize=16m

BEGIN
{
  printf("%16s %5s %32s %7s %10s %2s %7s\n", "COMMAND",
"PID", "FILE", "SIZE",
  "DEVICE", "RW", "MS");
}

io:::start
{
  start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
  command[args[0]->b_edev, args[0]->b_blkno] = execname;
  mypid[args[0]->b_edev, args[0]->b_blkno] = pid;
}

io:::done
/start[args[0]->b_edev, args[0]->b_blkno]/
{
  elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
  printf("%16s %5d %32s %7d %10s %2s %3d.%03d\n",
command[args[0]->b_edev,
  args[0]->b_blkno], mypid[args[0]->b_edev, args[0]->b_blkno],
  args[2]->fi_pathname, args[0]->b_bcount, args[1]->dev_statname,
  args[0]->b_flags&B_READ? "R": "W", elapsed/1000000,
  (elapsed/1000)%1000);
  start[args[0]->b_edev, args[0]->b_blkno] = 0;   /* free memory */
  command[args[0]->b_edev, args[0]->b_blkno] = 0; /* free memory */
  mypid[args[0]->b_edev, args[0]->b_blkno] = 0;   /* free memory */
}
--
This message posted from opensolaris.org

G''Day Dave,

On Mon, Jun 11, 2007 at 04:59:44PM -0700, David Rubio
wrote:
> I am teaching a DTrace class and a student noticed that 2 iosnoop scripts
run in two different windows were producing different results. I was not able to
answer why this is. Can anyone explain this. Here are the reults from the two
windows:
> 
> # io.d
> ...
>            sched     0                           <none>    1024      
dad1  W   0.156
>             bash  1998                     /dtrace/mod2    1024       dad1 
R   8.807
>             bash  5184                      /usr/bin/ls    8192       dad1 
R  10.332
>               ls  5184            /dtrace/mod2/examples    1024       dad1 
R   0.259
>          fsflush     3               /var/tmp/dtrace-1b    8192       dad1 
W   0.278
> 
> # io.d
> ...
>            sched     0                           <none>    1024      
dad1  W   0.176
>             bash  1998                     /dtrace/mod2    1024       dad1 
R   8.835
>             bash  5184                      /usr/bin/ls    8192       dad1 
R  10.360
>               ls  5184            /dtrace/mod2/examples    1024       dad1 
R   0.285
>          fsflush     3               /var/tmp/dtrace-1b    8192       dad1 
W   0.307
> 
> Here is the script:
> #!/usr/sbin/dtrace -qs
> 
> #pragma D option dynvarsize=16m
> 
> BEGIN
> {
>   printf("%16s %5s %32s %7s %10s %2s %7s\n", "COMMAND",
"PID", "FILE", "SIZE",
>   "DEVICE", "RW", "MS");
> }
> 
> io:::start
> {
>   start[args[0]->b_edev, args[0]->b_blkno] = timestamp;
>   command[args[0]->b_edev, args[0]->b_blkno] = execname;
>   mypid[args[0]->b_edev, args[0]->b_blkno] = pid;
> }
> 
> io:::done
> /start[args[0]->b_edev, args[0]->b_blkno]/
> {
>   elapsed = timestamp - start[args[0]->b_edev, args[0]->b_blkno];
>   printf("%16s %5d %32s %7d %10s %2s %3d.%03d\n",
command[args[0]->b_edev,
>   args[0]->b_blkno], mypid[args[0]->b_edev, args[0]->b_blkno],
>   args[2]->fi_pathname, args[0]->b_bcount, args[1]->dev_statname,
>   args[0]->b_flags&B_READ? "R": "W",
elapsed/1000000,
>   (elapsed/1000)%1000);
>   start[args[0]->b_edev, args[0]->b_blkno] = 0;   /* free memory */
>   command[args[0]->b_edev, args[0]->b_blkno] = 0; /* free memory */
>   mypid[args[0]->b_edev, args[0]->b_blkno] = 0;   /* free memory */
> }
I imagine the two scripts would attach their actions to the same ECB,
and since their actions are chained the timestamp can be read from
different times. The ~30 us noise that you see would be due to DTrace
overhead.

This rather strange one-liner may help explain it,

# dtrace -n ''syscall::gtime:entry { trace(timestamp); trace(timestamp);
}
  syscall::gtime:entry { trace(timestamp); trace(timestamp); }
  syscall::gtime:entry { trace(timestamp); trace(timestamp); }
  syscall::gtime:entry { trace(timestamp); trace(timestamp); }''
dtrace: description ''syscall::gtime:entry '' matched 4 probes
CPU     ID                    FUNCTION:NAME
  0  20089                      gtime:entry  2943651820090774 2943651820090774
  0  20089                      gtime:entry  2943651820094288 2943651820094288
  0  20089                      gtime:entry  2943651820096660 2943651820096660
  0  20089                      gtime:entry  2943651820099211 2943651820099211
^C

Notice that,
- within the action, the timestamp remains the same
- between actions (of identical probes), the timestamp moved by about 3 us.

You can also estimate DTrace overheads by using "{ trace(timestamp);
}"
actions in creative ways.

Also, and the "elapsed" variable should really be
"this->elapsed" to
potentially reduce DTrace overhead, as in /usr/demo/dtrace/iotime.d.

Brendan

-- 
Brendan
[CA, USA]