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
Brendan Gregg - Sun Microsystems
2007-Jun-12 00:29 UTC
[dtrace-discuss] 2 iosnoop scripts: different results
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]