dtrace discuss - Mar 2009 - suspicious dtrace results

i am doing reads and writes to /dev/rdsk/c0t2d0s4

using dtrace to see how much time it took for ssdread and ssdwrite. It shows
very small number 4 or 5.

#pragma D option flowindent
syscall::pread:entry
{
self->trace = 1;
self->size = arg2;
}
syscall::pwrite:entry
{
self->trace = 1;
self->size = arg2;
}

fbt:ssd:ssdread:entry
/self->trace/
{
self->start = timestamp;
self->minor = getminor(arg0);
}
fbt:ssd:ssdread:return
/self->start/
{
@avrg[pid,probefunc,self->minor,self->size] = avg((timestamp -
self->start) / 1000);
@numbers[pid,probefunc,self->minor,self->size] = count();
self->start = 0;
}
fbt:ssd:ssdwrite:entry
/self->trace/
{
self->start = timestamp;
self->minor = getminor(arg0);
}
fbt:ssd:ssdwrite:return
/self->start/
{
@avrg[pid,probefunc,self->minor,self->size] = avg((timestamp -
self->start) / 1000);
@numbers[pid,probefunc,self->minor,self->size] = count();
self->start = 0;
}
dtrace:::END
{
printa(@avrg);
printa(@numbers);
}

But the reads and writes take a long time actually. Why isnt that reflected in
the ssdread and ssdwrite times that dtrace shows. Problem with dtrace or this
provider does not work? I think my dtrace script is correct.

Please anybody?

Thanks
amujoo
-- 
This message posted from opensolaris.org

We could do with a bit more information to help you further.

Q) What OS are you running (uname -a)
Q) What system do you have
> i am doing reads and writes to /dev/rdsk/c0t2d0s4
Q) How are you accomplishing this?  What command(s) are you running?
Q) What is that device?  SCSI, SAS, SATA? Internal or External?
Q) Do you see similar issues when reading/writing to /dev/dsk/c0t2d0s4 
Q) Do you see issues when reading/writing to other slices on that disk?
Q) Do you see issues when reading/writing to other disks on the system?
Q) Is that disk/slice also in use by a layered driver such as SVM or VxVM?
> using dtrace to see how much time it took for ssdread and ssdwrite. It
shows very small number 4 or 5.
That''ll be 4 or 5 microseconds given you are dividing nanoseconds by
1000
> But the reads and writes take a long time actually.
How long are the reads/writes taking?  How long is a "long time"?

How are you measuring the read() and write() times?  Your DTrace isn''t
timing pread/pwrite/read/write system calls.  Consider adding the probes and
timing the entry to return so you know how long they are taking so you can
compare it with the ssdread/ssdwrite timings.
> Why isnt that reflected in the ssdread and ssdwrite times that dtrace
shows.
Most likely because the delays are further up the stack.  This goes back to how
you are doing your testing and how you are measuring the read/write elapsed
times.
> @avrg[pid,probefunc,self->minor,self->size] = avg((timestamp -
self->start) / 1000);
> @numbers[pid,probefunc,self->minor,self->size] = count();
Consider using the quantize function to produce charts.  At the moment
you''re averaging the times which may or may not be helpful if
you''re looking for outlyers.  The quantize function will show you both
the count and distribution so if you do have outlyers they will be obvious to
see.

You could also consider using the PROFILE provider to dump out stats every N
seconds if you wanted.

Q) What does "iostat -xntcz 1" show whilst doing your test?  

There''s also some good ''disk'' related scripts in the
DTrace toolkit which may be helpful to you.

Q) What exactly are you trying to achieve?  The reason I ask is that your DTrace
is measuring all ssdread/ssdwrite events to/from all disks in the system.  If
you''re interested specifically in I/O times to c0t2d0s4 you need to set
a predicate to limit the probes firing only for I/O to that device.
-- 
This message posted from opensolaris.org