Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-11 Thread Marcelo Leal
No, i'm not thinking about the numbers like "good" or "bad" for now. Because of 
that little bug in the first script, i'm just trying to realize if the numbers 
are OK. ;-)
 Like Max said, all the IO's time can be greater than the tracing period. The 
only problem was the "two" days of the first script, but now 20 minutes can be 
"right". 
 Assuming that, i can continue investigating to now realize if that numbers are 
good or not and work to understand/fix them.
 Thanks a lot for your answers Jim, and Max.
 
 ps.: Max, i just update my profile, and i'm receiving your mails.

 __
Leal
[http://www.eall.com.br/blog]
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread [EMAIL PROTECTED]
Hi Marcelo,

Marcelo Leal wrote:
> Sorry, but i do not agree.
>  We are talking about a NFSv3 provider, and not about how many cpu's there 
> are on the system. I do not have the knowledge to discuss with you the 
> aspects about the implementation, but as a user point of view, i think that 
> numbers don't make sense. If the fact that the number of cpu's is important 
> for the start/done for the NFS provider, i think it will for all other dtrace 
> providers. 
>   
I have found that almost all "bugs" with dtrace are either in the scripting
or in the interpretation of the output.  The mechanism used to implement
dtrace is quite simple, and for the script you are running, I don't believe
you are hitting any bug in the implementation of dtrace.  Also, using dtrace
to examine the system is like using a microscope.  You need to know the
big picture first, before you can determine what you need to trace.
Otherwise you can end up getting a lot of detail about something that
has nothing to do with the problem you are experiencing.  In this instance,
as Jim says, iostat will give you a better view of the big picture.

As for the 20 minutes total time spent for I/O in a script running 10 
minutes,
this could happen even on a single CPU.  For example, you start the script
and immediately 10 I/O requests are made.  Now, let's say all 10 requests
are queued (i.e., block, waiting for some resource).  If they all finish 
just before
the end of the 10 minute period, the total elapsed time would be about 
100 minutes.
So long as the total time divided by the number of operations does not 
exceed
10 minutes, the output is reasonable.

I suspect the outliers, (the I/Os that are taking 2-4 seconds) are due 
to queuing at
the disk driver, but they could be due to scheduling as well.  (I would 
have to look
at exactly when the start and done probes fire to determine this.  But 
fortunately,
source code is available to determine this.).  As I mentioned in an 
earlier post,
speculative tracing can be used to determine the code path taken for the 
longest
I/O.  I have written a script that might work, but have no way to test 
it at this time.
If you are interested, I'll post it.

Jim, as for taking this offline, that is ok for you, but my posts to 
Marcelo are bouncing...

max


>  Thanks a lot for your answers Max!
>
> __
> Leal
> [http://www.eall.com.br/blog]
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread Jim Mauro
No bug here - we can absolutely use DTrace on MP systems,
reliably and with confidence.

The script output shows some nasty outliers for a small percentage
of the reads and writes happening on the server. Time to take a closer
look at the IO subsystem. I'd start with "iostat -znx 1", and see what
the queues look like, IO rates, and service times.

I'd also have a look at the network. Download nicstat and run it
(go to blogs.sun.com and search for "nicstat" - it's easy to find).

What are you using for an on-disk file system? UFS or ZFS?

/jim



Marcelo Leal wrote:
> Ok, but that is a bug, or should work like that? 
>  We can not use dtrace on multiple processors systems?
>  Sorry, but i don't get it...
> __
>  Leal
> [http://www.eall.com.br/blog]
>   
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread Marcelo Leal
Sorry, but i do not agree.
 We are talking about a NFSv3 provider, and not about how many cpu's there are 
on the system. I do not have the knowledge to discuss with you the aspects 
about the implementation, but as a user point of view, i think that numbers 
don't make sense. If the fact that the number of cpu's is important for the 
start/done for the NFS provider, i think it will for all other dtrace 
providers. 
 Thanks a lot for your answers Max!

__
Leal
[http://www.eall.com.br/blog]
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread [EMAIL PROTECTED]
Hi Marcelo,

Marcelo Leal wrote:
> Ok, but that is a bug, or should work like that? 
>  We can not use dtrace on multiple processors systems?
>  Sorry, but i don't get it...
>   
I don't consider this a bug.  I think it depends on what you are trying 
to measure.
The script you are using measures latency for read/write operations
across all cpus.  There is nothing wrong with the sum of the times
being longer than the total time you are tracing, if there are multiple 
cpus.
If you wanted to measure latency per cpu,
the script would need to be changed.

So, what are you trying to measure?
I think more interesting is to find out why some I/O operations
take longer than others.  For this, you can use speculative tracing.
Trace all function entries and returns, but only commit if the time
spent is longer than the longest time found thus far.

I'm sure others have ideas about this...

max

> __
>  Leal
> [http://www.eall.com.br/blog]
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread Marcelo Leal
Ok, but that is a bug, or should work like that? 
 We can not use dtrace on multiple processors systems?
 Sorry, but i don't get it...
__
 Leal
[http://www.eall.com.br/blog]
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread [EMAIL PROTECTED]
Hi Marcelo,

Marcelo Leal wrote:
> I think (us) is microseconds. There is one division by "1000" on the source 
> code...
>
>   
Oops.  You're right.  I did not see that.  (That might explain
the 4-8 nanosecond I/Os, which I did think seemed pretty fast.
They are actually 4-8 microsecond).  So, you want to know how
you can spend 19 or 20 minutes in a 10 minute trace?
You have multiple cpu's, so each cpu can be working in parallel
on different I/O requests.  If you have 8 cpu's, the average time
spent by each cpu would be about 2.5 minutes.  This does sound a little
high to me, but not extreme.  If you got 80 minutes, I would be
concerned that all cpus are working on requests all the time.
It might be difficult to correlate per cpu, as I suspect the start and
done probe for a given I/O could fire on different cpus.

max
>  Leal
> [http://www.eall.com.br/blog]
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread Marcelo Leal
I think (us) is microseconds. There is one division by "1000" on the source 
code...

 Leal
[http://www.eall.com.br/blog]
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread [EMAIL PROTECTED]
Marcelo Leal wrote:
>> Marcelo Leal wrote:
>> 
>>> Hello all...
>>>  Thanks a lot for the answers! I think the problem
>>>   
>> is "almost" fixed. Every dtrace documentation says to
>> use predicates to guarantee the relation between the
>> start/done probes... Max was the only one paying
>> attention reading the docs. ;-)
>> 
>>>  But i'm still getting weird numbers:
>>>   
>>>   
>> Which numbers don't look right?  3 of your reads took
>> between 2 and 4 
>> milliseconds, most were between
>> 8 and 16 nanoseconds.  21 writes took between 2 and 4
>> milliseconds, the 
>> most amount of time
>> spent doing read/write by host is about 1.2 seconds,
>> and teste/file10 
>> took about 1.1 seconds.
>> Looks pretty good to me.(?).  I'm curious about what
>> you were expecting 
>> to see.
>> 
>  
>  The problem is the total numbers...
>  1267135728 and 1126991407, for example. 
>  21 and 19 minutes in a ten minutes trace.
>  Or am i missing something?
>   
When I do the arithmetic, I get about 1.2 seconds for the first number,
and 1.1 seconds for the second number.  These numbers are in 
nanoseconds, no?
So, 1267135728/(1000*1000*1000) = 1.267... seconds.
max

>  Leal
> [http://www.eall.com.br/blog]
>
>   
>>> Wed Dec 10 08:36:33 BRST 2008
>>> Wed Dec 10 08:46:55 BRST 2008
>>>
>>>  cut here -
>>> Tracing... Hit Ctrl-C to end.
>>> ^C
>>> NFSv3 read/write distributions (us):
>>>
>>>   read
>>>value  - Distribution
>>>   
>> - count
>> 
>>>2 |
>>>   
>> 0
>>  631
>> @@@ 145603
>> 
>>>   16 |@
>>>   
>>155926
>>   15970
>>6111
>>   942
>>372
>>   883
>>1649
>>   1090
>>8278
>>   24605
>>8868
>>   1694
>>304
>>   63
>>27
>>   31
>>43
>>   3
>>0
>> value  - Distribution -
>>  count
>> 128 |
>> 0
>>  1083 
>> @@@ 32622
>> 
>>> 1024 |@
>>>   
>>70353
>>   70851
>>47906
>>   44898
>>20481
>>   5633 
>>1605 
>>   1339
>>957
>>   380
>>143
>>   21
>>0
>> otal us):
>> 
>>>   x.16.0.x
>>>   
>> 647019
>> 
>>>   x.16.0.x
>>>   
>> 734488
>> 
>>>   x.16.0.x
>>>   
>> 0890034
>> 
>>>   x.16.0.x
>>>   
>> 8852624
>> 
>>>   x.16.0.x
>>>   
>> 0407241
>> 
>>>   x.16.0.x
>>>   
>> 9028592
>> 
>>>   x.16.0.x
>>>   
>> 3013688
>> 
>>>   x.16.0.x
>>>   
>> 04045281
>> 
>>>   x.16.0.x
>>>   
>> 05245138
>> 
>>>   x.16.0.x
>>>   
>> 24286383
>> 
>>>   x.16.0.x
>>>   
>> 54526695
>> 
>>>   x.16.0.x
>>>   
>> 94419023
>> 
>>>   x.16.0.x
>>>   
>> 21794650
>> 
>>>   x.16.0.x
>>>   
>> 59302970
>> 
>>>   x.16.0.x
>>>   
>> 89694542
>> 
>>>   x.16.0.x
>>>   
>> 90207418
>> 
>>>   x.16.0.x
>>>   
>> 87983050
>> 
>>>   x.16.0.x
>>>   
>> 267135728
>> 
>>> NFSv3 read/write top 10 files (total us):
>>>
>>>   /teste/file1   95870303
>>>   /teste/file2  104212948
>>>   /teste/file3  104311607
>>>   /teste/file4  121076447
>>>   /teste/file5  137687236
>>>   /teste/file6  160895273
>>>   /teste/file7  180765880
>>>   /teste/file8  198827114
>>>   /teste/file9  372380414
>>>   /teste/file10 1126991407
>>> -- cut here --
>>>   
>>>   
>>>  Max, will be difficult disable processors on that
>>>   
>> machine (production). 
>> 
>>>   
>>>   
>> Yes.  I understand. 
>> Regards,
>> max
>>
>> 
>>>  Thanks again!
>>>
>>>  Leal
>>> [http://www.eall.com.br/blog]
>>>   
>>>   
>> ___
>> dtrace-discuss mailing l

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread Marcelo Leal
> Marcelo Leal wrote:
> > Hello all...
> >  Thanks a lot for the answers! I think the problem
> is "almost" fixed. Every dtrace documentation says to
> use predicates to guarantee the relation between the
> start/done probes... Max was the only one paying
> attention reading the docs. ;-)
> >   
> Actually, this is not from reading the docs.  It is
> from being burnt a 
> few times by
> getting "impossible" time values.  By the way, I am
> replying to you and 
> to the mailing
> list, but messages to you are getting bounced.

 Oh, seems like i need to update my profile. ;-)

> >  But i'm still getting weird numbers:
> >   
> Which numbers don't look right?  3 of your reads took
> between 2 and 4 
> milliseconds, most were between
> 8 and 16 nanoseconds.  21 writes took between 2 and 4
> milliseconds, the 
> most amount of time
> spent doing read/write by host is about 1.2 seconds,
> and teste/file10 
> took about 1.1 seconds.
> Looks pretty good to me.(?).  I'm curious about what
> you were expecting 
> to see.
 
 The problem is the total numbers...
 1267135728 and 1126991407, for example. 
 21 and 19 minutes in a ten minutes trace.
 Or am i missing something?

 Leal
[http://www.eall.com.br/blog]

> 
> > Wed Dec 10 08:36:33 BRST 2008
> > Wed Dec 10 08:46:55 BRST 2008
> >
> >  cut here -
> > Tracing... Hit Ctrl-C to end.
> > ^C
> > NFSv3 read/write distributions (us):
> >
> >   read
> >value  - Distribution
> - count
> >2 |
> 0
>  631
> @@@ 145603
> >   16 |@
>155926
>   15970
>6111
>   942
>372
>   883
>1649
>   1090
>8278
>   24605
>8868
>   1694
>304
>   63
>27
>   31
>43
>   3
>0
> value  - Distribution -
>  count
> 128 |
> 0
>  1083 
> @@@ 32622
> > 1024 |@
>70353
>   70851
>47906
>   44898
>20481
>   5633 
>1605 
>   1339
>957
>   380
>143
>   21
>0
> otal us):
> >
> >   x.16.0.x
> 
> 647019
> >   x.16.0.x
> 
> 734488
> >   x.16.0.x
> 
> 0890034
> >   x.16.0.x
> 
> 8852624
> >   x.16.0.x
> 
> 0407241
> >   x.16.0.x
> 
> 9028592
> >   x.16.0.x
> 
> 3013688
> >   x.16.0.x
> 
> 04045281
> >   x.16.0.x
> 
> 05245138
> >   x.16.0.x
> 
> 24286383
> >   x.16.0.x
> 
> 54526695
> >   x.16.0.x
> 
> 94419023
> >   x.16.0.x
> 
> 21794650
> >   x.16.0.x
> 
> 59302970
> >   x.16.0.x
> 
> 89694542
> >   x.16.0.x
> 
> 90207418
> >   x.16.0.x
> 
> 87983050
> >   x.16.0.x
> 
> 267135728
> >
> > NFSv3 read/write top 10 files (total us):
> >
> >   /teste/file1   95870303
> >   /teste/file2  104212948
> >   /teste/file3  104311607
> >   /teste/file4  121076447
> >   /teste/file5  137687236
> >   /teste/file6  160895273
> >   /teste/file7  180765880
> >   /teste/file8  198827114
> >   /teste/file9  372380414
> >   /teste/file10 1126991407
> > -- cut here --
> >   
> 
> >  Max, will be difficult disable processors on that
> machine (production). 
> >   
> Yes.  I understand. 
> Regards,
> max
> 
> >  Thanks again!
> >
> >  Leal
> > [http://www.eall.com.br/blog]
> >   
> 
> ___
> dtrace-discuss mailing list
> dtrace-discuss@opensolaris.org
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread [EMAIL PROTECTED]
Marcelo Leal wrote:
> Hello all...
>  Thanks a lot for the answers! I think the problem is "almost" fixed. Every 
> dtrace documentation says to use predicates to guarantee the relation between 
> the start/done probes... Max was the only one paying attention reading the 
> docs. ;-)
>   
Actually, this is not from reading the docs.  It is from being burnt a 
few times by
getting "impossible" time values.  By the way, I am replying to you and 
to the mailing
list, but messages to you are getting bounced.
>  But i'm still getting weird numbers:
>   
Which numbers don't look right?  3 of your reads took between 2 and 4 
milliseconds, most were between
8 and 16 nanoseconds.  21 writes took between 2 and 4 milliseconds, the 
most amount of time
spent doing read/write by host is about 1.2 seconds, and teste/file10 
took about 1.1 seconds.
Looks pretty good to me.(?).  I'm curious about what you were expecting 
to see.

> Wed Dec 10 08:36:33 BRST 2008
> Wed Dec 10 08:46:55 BRST 2008
>
>  cut here -
> Tracing... Hit Ctrl-C to end.
> ^C
> NFSv3 read/write distributions (us):
>
>   read
>value  - Distribution - count
>2 | 0
>4 | 631
>8 | 145603
>   16 |@155926
>   32 |@@   15970
>   64 |@6111
>  128 | 942
>  256 | 372
>  512 | 883
> 1024 | 1649
> 2048 | 1090
> 4096 |@8278
> 8192 |@@@  24605
>16384 |@8868
>32768 | 1694
>65536 | 304
>   131072 | 63
>   262144 | 27
>   524288 | 31
>  1048576 | 43
>  2097152 | 3
>  4194304 | 0
>
>   write
>value  - Distribution - count
>  128 | 0
>  256 | 1083 
>  512 | 32622
> 1024 |@70353
> 2048 |@@   70851
> 4096 |@@   47906
> 8192 |@@   44898
>16384 |@@@  20481
>32768 |@5633 
>65536 | 1605 
>   131072 | 1339
>   262144 | 957
>   524288 | 380
>  1048576 | 143
>  2097152 | 21
>  4194304 | 0
>
> NFSv3 read/write by host (total us):
>
>   x.16.0.x   3647019
>   x.16.0.x   8734488
>   x.16.0.x  50890034
>   x.16.0.x  68852624
>   x.16.0.x  70407241
>   x.16.0.x  79028592
>   x.16.0.x  83013688
>   x.16.0.x 104045281
>   x.16.0.x 105245138
>   x.16.0.x 124286383
>   x.16.0.x154526695
>   x.16.0.x 194419023
>   x.16.0.x 221794650
>   x.16.0.x 259302970
>   x.16.0.x 289694542
>   x.16.0.x 290207418
>   x.16.0.x  

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-10 Thread Marcelo Leal
Hello all...
 Thanks a lot for the answers! I think the problem is "almost" fixed. Every 
dtrace documentation says to use predicates to guarantee the relation between 
the start/done probes... Max was the only one paying attention reading the 
docs. ;-)
 But i'm still getting weird numbers:

Wed Dec 10 08:36:33 BRST 2008
Wed Dec 10 08:46:55 BRST 2008

 cut here -
Tracing... Hit Ctrl-C to end.
^C
NFSv3 read/write distributions (us):

  read
   value  - Distribution - count
   2 | 0
   4 | 631
   8 | 145603
  16 |@155926
  32 |@@   15970
  64 |@6111
 128 | 942
 256 | 372
 512 | 883
1024 | 1649
2048 | 1090
4096 |@8278
8192 |@@@  24605
   16384 |@8868
   32768 | 1694
   65536 | 304
  131072 | 63
  262144 | 27
  524288 | 31
 1048576 | 43
 2097152 | 3
 4194304 | 0

  write
   value  - Distribution - count
 128 | 0
 256 | 1083 
 512 | 32622
1024 |@70353
2048 |@@   70851
4096 |@@   47906
8192 |@@   44898
   16384 |@@@  20481
   32768 |@5633 
   65536 | 1605 
  131072 | 1339
  262144 | 957
  524288 | 380
 1048576 | 143
 2097152 | 21
 4194304 | 0

NFSv3 read/write by host (total us):

  x.16.0.x   3647019
  x.16.0.x   8734488
  x.16.0.x  50890034
  x.16.0.x  68852624
  x.16.0.x  70407241
  x.16.0.x  79028592
  x.16.0.x  83013688
  x.16.0.x 104045281
  x.16.0.x 105245138
  x.16.0.x 124286383
  x.16.0.x154526695
  x.16.0.x 194419023
  x.16.0.x 221794650
  x.16.0.x 259302970
  x.16.0.x 289694542
  x.16.0.x 290207418
  x.16.0.x 487983050
  x.16.0.x1267135728

NFSv3 read/write top 10 files (total us):

  /teste/file1   95870303
  /teste/file2  104212948
  /teste/file3  104311607
  /teste/file4  121076447
  /teste/file5  137687236
  /teste/file6  160895273
  /teste/file7  180765880
  /teste/file8  198827114
  /teste/file9  372380414
  /teste/file10 1126991407
-- cut here --
 Max, will be difficult disable processors on that machine (production). 
 Thanks again!

 Leal
[http://www.eall.com.br/blog]
-- 
This message posted fro

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Brendan Gregg - Sun Microsystems
On Tue, Dec 09, 2008 at 05:04:49PM +0100, [EMAIL PROTECTED] wrote:
> Hi,
> I have looked at the script, and there is no correspondence between 
> start and done.
> So, I am not sure how this script is supposed to work.
> I think there should be a predicate in the done probes...
> The way the script is written, it assumes that for any start, the done
> that fires after it is for the same noi_xid.
> 
> Current script:
> 
> nfsv3:::op-read-start,
> nfsv3:::op-write-start
> {
> start[args[1]->noi_xid] = timestamp;
> }
> 
> nfsv3:::op-read-done,
> nfsv3:::op-write-done
> {
> ...
> 
> Changed script:
> 
> nfsv3:::op-read-start,
> nfsv3:::op-write-start
> {
> start[args[1]->noi_xid] = timestamp;
> }
> 
> nfsv3:::op-read-done,
> nfsv3:::op-write-done
> /start[args[1]->noi_xid] != 0/
> {
> 
> That way, you don't have the done probe clause executing
> for id's where the start has not fired first.

Thanks, unusual for me to miss that.  Anyway, now fixed on the wiki.

>  (This still does not
> match start/done for a given xid).
> But what do I know...

The xid is the key in the hash...

Brendan

-- 
Brendan Gregg, Sun Microsystems Fishworks.http://blogs.sun.com/brendan
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread [EMAIL PROTECTED]
Hi Brendan,

Brendan Gregg - Sun Microsystems wrote:
> On Tue, Dec 09, 2008 at 05:04:49PM +0100, [EMAIL PROTECTED] wrote:
>   
>> Hi,
>> I have looked at the script, and there is no correspondence between 
>> start and done.
>> So, I am not sure how this script is supposed to work.
>> I think there should be a predicate in the done probes...
>> The way the script is written, it assumes that for any start, the done
>> that fires after it is for the same noi_xid.
>>
>> Current script:
>>
>> nfsv3:::op-read-start,
>> nfsv3:::op-write-start
>> {
>> start[args[1]->noi_xid] = timestamp;
>> }
>>
>> nfsv3:::op-read-done,
>> nfsv3:::op-write-done
>> {
>> ...
>>
>> Changed script:
>>
>> nfsv3:::op-read-start,
>> nfsv3:::op-write-start
>> {
>> start[args[1]->noi_xid] = timestamp;
>> }
>>
>> nfsv3:::op-read-done,
>> nfsv3:::op-write-done
>> /start[args[1]->noi_xid] != 0/
>> {
>>
>> That way, you don't have the done probe clause executing
>> for id's where the start has not fired first.
>> 
>
> Thanks, unusual for me to miss that.  Anyway, now fixed on the wiki.
>
>   
>>  (This still does not
>> match start/done for a given xid).
>> But what do I know...
>> 
>
> The xid is the key in the hash...
>
>   
Yes, and I think the check for non-zero is sufficient...
> Brendan
>
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread [EMAIL PROTECTED]
Marcelo Leal wrote:
> Oops, that would be a nice test, but something i cannot do. ;-)
>   
What is it that you cannot do?
> [http://www.eall.com.br/blog]
>
>  Leal.
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread [EMAIL PROTECTED]
Hi Marcelo,

Marcelo Leal wrote:
> Some kind of both... ;-)
>  I was investigating a "possible" performance problem, that i'm not sure if 
> is the NFS server or not. 
>  So, i was faced with that weird numbers. I think one thing is not related 
> with the other, but we need to fix whatever is the problem with the script or 
> the provider, to have confidence on the tool. Except that numbers, the other 
> latency values seems to be fine, don't you agree?
>   
Yes.  And I think it is a problem with the script.  Did you try 
modifying the script
as I suggested in my earlier email?
max

>  Leal
> [http://www.eall.com.br/blog]
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Jim Mauro
D'oh! Good spot Max - feeling sheepish that I missed that.

Marcelo - add the predicate to the "done" probes as per Max's
message, and let's see where that takes us

Thanks,
/jim


[EMAIL PROTECTED] wrote:
> Hi,
> I have looked at the script, and there is no correspondence between 
> start and done.
> So, I am not sure how this script is supposed to work.
> I think there should be a predicate in the done probes...
> The way the script is written, it assumes that for any start, the done
> that fires after it is for the same noi_xid.
>
> Current script:
>
> nfsv3:::op-read-start,
> nfsv3:::op-write-start
> {
>start[args[1]->noi_xid] = timestamp;
> }
>
> nfsv3:::op-read-done,
> nfsv3:::op-write-done
> {
> ...
>
> Changed script:
>
> nfsv3:::op-read-start,
> nfsv3:::op-write-start
> {
>start[args[1]->noi_xid] = timestamp;
> }
>
> nfsv3:::op-read-done,
> nfsv3:::op-write-done
> /start[args[1]->noi_xid] != 0/
> {
>
> That way, you don't have the done probe clause executing
> for id's where the start has not fired first.  (This still does not
> match start/done for a given xid).
> But what do I know...
>
> max
>
> Jim Mauro wrote:
>> Also (I meant to ask) - are you having performance problems, or
>> just monitoring with the NFS provider scripts?
>>
>> Thanks,
>> /jim
>>
>>
>> Marcelo Leal wrote:
>>  
>>> Hello Jim, this is not a benchmark. The filenames i did change for 
>>> privacy...
>>>  This is a NFS server, yes.
>>>
>>> # uname -a
>>> SunOS test 5.11 snv_89 i86pc i386 i86pc
>>>
>>> # cat /etc/release
>>>Solaris Express Community Edition snv_89 X86
>>>Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
>>> Use is subject to license terms.
>>>   Assembled 06 May 2008
>>>   
>> ___
>> dtrace-discuss mailing list
>> dtrace-discuss@opensolaris.org
>>
>>   
>
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Marcelo Leal
Some kind of both... ;-)
 I was investigating a "possible" performance problem, that i'm not sure if is 
the NFS server or not. 
 So, i was faced with that weird numbers. I think one thing is not related with 
the other, but we need to fix whatever is the problem with the script or the 
provider, to have confidence on the tool. Except that numbers, the other 
latency values seems to be fine, don't you agree?

 Leal
[http://www.eall.com.br/blog]
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Marcelo Leal
Oops, that would be a nice test, but something i cannot do. ;-)

[http://www.eall.com.br/blog]

 Leal.
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread [EMAIL PROTECTED]
Hi,
I have looked at the script, and there is no correspondence between 
start and done.
So, I am not sure how this script is supposed to work.
I think there should be a predicate in the done probes...
The way the script is written, it assumes that for any start, the done
that fires after it is for the same noi_xid.

Current script:

nfsv3:::op-read-start,
nfsv3:::op-write-start
{
start[args[1]->noi_xid] = timestamp;
}

nfsv3:::op-read-done,
nfsv3:::op-write-done
{
...

Changed script:

nfsv3:::op-read-start,
nfsv3:::op-write-start
{
start[args[1]->noi_xid] = timestamp;
}

nfsv3:::op-read-done,
nfsv3:::op-write-done
/start[args[1]->noi_xid] != 0/
{

That way, you don't have the done probe clause executing
for id's where the start has not fired first.  (This still does not
match start/done for a given xid).
But what do I know...

max

Jim Mauro wrote:
> Also (I meant to ask) - are you having performance problems, or
> just monitoring with the NFS provider scripts?
>
> Thanks,
> /jim
>
>
> Marcelo Leal wrote:
>   
>> Hello Jim, this is not a benchmark. The filenames i did change for privacy...
>>  This is a NFS server, yes.
>>
>> # uname -a
>> SunOS test 5.11 snv_89 i86pc i386 i86pc
>>
>> # cat /etc/release
>>Solaris Express Community Edition snv_89 X86
>>Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
>> Use is subject to license terms.
>>   Assembled 06 May 2008
>>   
>> 
> ___
> dtrace-discuss mailing list
> dtrace-discuss@opensolaris.org
>
>   

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread [EMAIL PROTECTED]
Hi Marcelo and Jim,

Marcelo Leal wrote:
> Hello Jim, this is not a benchmark. The filenames i did change for privacy...
>  This is a NFS server, yes.
>
> # uname -a
> SunOS test 5.11 snv_89 i86pc i386 i86pc
>
> # cat /etc/release
>Solaris Express Community Edition snv_89 X86
>Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
> Use is subject to license terms.
>   Assembled 06 May 2008
>   
Out of curiosity, what happens if you turn off all the processors
except 1 (via psradm(1)), and then run the script?

max

___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Jim Mauro
Also (I meant to ask) - are you having performance problems, or
just monitoring with the NFS provider scripts?

Thanks,
/jim


Marcelo Leal wrote:
> Hello Jim, this is not a benchmark. The filenames i did change for privacy...
>  This is a NFS server, yes.
>
> # uname -a
> SunOS test 5.11 snv_89 i86pc i386 i86pc
>
> # cat /etc/release
>Solaris Express Community Edition snv_89 X86
>Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
> Use is subject to license terms.
>   Assembled 06 May 2008
>   
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Marcelo Leal
Hello Jim, this is not a benchmark. The filenames i did change for privacy...
 This is a NFS server, yes.

# uname -a
SunOS test 5.11 snv_89 i86pc i386 i86pc

# cat /etc/release
   Solaris Express Community Edition snv_89 X86
   Copyright 2008 Sun Microsystems, Inc.  All Rights Reserved.
Use is subject to license terms.
  Assembled 06 May 2008
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Jim Mauro
HmmmSomething is certainly wrong. 11 writes at 137k - 275k seconds
(which is where your 1.5M seconds sum is coming from) is bogus.

What version of Solaris is this ('uname -a' and 'cat /etc/release')?

Your running this on an NFS server, right (not client)?

Is this a benchmark? I ask because the file names (file1, file2, etc)
seem like names used in synthetic benchmarks.

I need to take a closer look at the code and figure out how to chase
this. Either there's a bug somewhere, or we're missing something.

Thanks,
/jim


Marcelo Leal wrote:
> Hello Jim!
>  Actually i can repeat it... every time i did run some d script to collect 
> some data i got some (how do you call it? nasty :) values. Look:
>
> Fri Dec  5 10:19:32 BRST 2008
> Fri Dec  5 10:29:34 BRST 2008
>
>
> NFSv3 read/write distributions (us):
>
>   read
>value  - Distribution - count
>2 | 0
>4 | 1092
>8 |@93773
>   16 | 64481
>   32 |@@   11713
>   64 |@7590
>  128 | 1156
>  256 | 698
>  512 | 1394
> 1024 | 1729
> 2048 | 805
> 4096 |@2732
> 8192 |@@@  14893
>16384 |@@   9351
>32768 |@2988
>65536 | 647
>   131072 | 119
>   262144 | 29
>   524288 | 30
>  1048576 | 28
>  2097152 | 0
>
>   write
>value  - Distribution - count
>   64 | 0
>  128 | 8
>  256 | 2418
>  512 |@@@  22679
> 1024 | 28442
> 2048 | 59887
> 4096 |@68852
> 8192 |@65152
>16384 | 32224
>32768 |@@   11554
>65536 | 3162
>   131072 | 1100
>   262144 | 446
>   524288 | 105
>  1048576 | 70
>  2097152 | 11
>  4194304 | 0
>  8388608 | 0
> 16777216 | 0
> 33554432 | 0
> 67108864 | 0
>134217728 | 0
>268435456 | 0
>536870912 | 0
>   1073741824 | 0
>   2147483648 | 0
>   4294967296 | 0
>   8589934592 | 0
>  17179869184 | 0
>  34359738368 | 0
>  68719476736 | 0
> 137438953472 | 11
> 274877906944 | 0
>
> NFSv3 read/write by host (total us):
>
>   x.16.0.x   4707246
>   x.16.0.x  28397213
>   x.16.0.x  40901275
>   x.16.0.x  68333664
>   x.16.0.x  89357734
>   x.16.0.x 125890329
>   x.16.0.x  

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-09 Thread Marcelo Leal
Hello Jim!
 Actually i can repeat it... every time i did run some d script to collect some 
data i got some (how do you call it? nasty :) values. Look:

Fri Dec  5 10:19:32 BRST 2008
Fri Dec  5 10:29:34 BRST 2008


NFSv3 read/write distributions (us):

  read
   value  - Distribution - count
   2 | 0
   4 | 1092
   8 |@93773
  16 | 64481
  32 |@@   11713
  64 |@7590
 128 | 1156
 256 | 698
 512 | 1394
1024 | 1729
2048 | 805
4096 |@2732
8192 |@@@  14893
   16384 |@@   9351
   32768 |@2988
   65536 | 647
  131072 | 119
  262144 | 29
  524288 | 30
 1048576 | 28
 2097152 | 0

  write
   value  - Distribution - count
  64 | 0
 128 | 8
 256 | 2418
 512 |@@@  22679
1024 | 28442
2048 | 59887
4096 |@68852
8192 |@65152
   16384 | 32224
   32768 |@@   11554
   65536 | 3162
  131072 | 1100
  262144 | 446
  524288 | 105
 1048576 | 70
 2097152 | 11
 4194304 | 0
 8388608 | 0
16777216 | 0
33554432 | 0
67108864 | 0
   134217728 | 0
   268435456 | 0
   536870912 | 0
  1073741824 | 0
  2147483648 | 0
  4294967296 | 0
  8589934592 | 0
 17179869184 | 0
 34359738368 | 0
 68719476736 | 0
137438953472 | 11
274877906944 | 0

NFSv3 read/write by host (total us):

  x.16.0.x   4707246
  x.16.0.x  28397213
  x.16.0.x  40901275
  x.16.0.x  68333664
  x.16.0.x  89357734
  x.16.0.x 125890329
  x.16.0.x 127848295
  x.16.0.x 132248305
  x.16.0.x 135161278
  x.16.0.x 138579146
  x.16.0.x 146275507
  x.16.0.x 156761509
  x.16.0.x 566154684
  x.16.0.x  185948455950
  x.16.0.x  186184056503
  x.16.0.x  186341816343
  x.16.0.x1488962592532

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-08 Thread Jim Mauro
Nasty, nasty outlier.

You have a very nasty outlier in the quantized write latency data;

 34359738368 | 0
 68719476736 | 1
137438953472 | 0


See that sucker with the count of 1? That means there was 1 occurence where
the quantized value fell in the range of 68 billion - 137 billion, and 
your nasty sum
number is 131 billion.

Now, how you ended up with a single write latency value that large is a
bit of a head scratcher. It seems unlikely that you had 1 disk write that
took 36 hours, and given you recorded data for 10 minutes, it seems
highly unlikely that a 36 hour disk write could be captured in a 10 minute
data collection window... :^)

So I need to noodle this a bit more, and see if the DTrace experts have an
opinion. If you can't repeat this (can you?), I would just toss it out as
noise interference. If you can repeat this, we need to look closer..

Thanks,
/jim


Marcelo Leal wrote:
> Hello Jim,
>  - cut here ---
> Qui Dez  4 19:08:39 BRST 2008
> Qui Dez  4 19:18:02 BRST 2008
>
>  - cut here ---
> NFSv3 read/write distributions (us):
>
>   read
>value  - Distribution - count
>2 | 0
>4 | 22108
>8 |@@@  80611
>   16 | 66331
>   32 |@@   11497
>   64 |@4939
>  128 | 979
>  256 | 727
>  512 | 788
> 1024 | 1663
> 2048 | 496
> 4096 |@3389
> 8192 |@@@  14518
>16384 |@4856
>32768 | 742
>65536 | 119
>   131072 | 38
>   262144 | 9
>   524288 | 25
>  1048576 | 7
>  2097152 | 0
>
>   write
>value  - Distribution - count
>   64 | 0
>  128 | 55
>  256 |@@   8750
>  512 |@@   52926
> 1024 |@34370
> 2048 |@@@  24610
> 4096 |@@@  12136
> 8192 |@@@  10819
>16384 |@4181
>32768 | 1198
>65536 | 811
>   131072 | 793
>   262144 | 278
>   524288 | 26
>  1048576 | 2
>  2097152 | 0
>  4194304 | 0
>  8388608 | 0
> 16777216 | 0
> 33554432 | 0
> 67108864 | 0
>134217728 | 0
>268435456 | 0
>536870912 | 0
>   1073741824 | 0
>   2147483648 | 0
>   4294967296 | 0
>   8589934592 | 0
>  17179869184 | 0
>  34359738368 | 0
>  68719476736 | 1
> 137438953472 | 0
>
> NFSv3 read/write by host (total us):
>
>   x.16.0.x   1987595
>   x.16.0.x   2588

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-08 Thread Marcelo Leal
36 hours... ;-))

 Leal.
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-08 Thread Marcelo Leal
Hello Jim,
 - cut here ---
Qui Dez  4 19:08:39 BRST 2008
Qui Dez  4 19:18:02 BRST 2008

 - cut here ---
NFSv3 read/write distributions (us):

  read
   value  - Distribution - count
   2 | 0
   4 | 22108
   8 |@@@  80611
  16 | 66331
  32 |@@   11497
  64 |@4939
 128 | 979
 256 | 727
 512 | 788
1024 | 1663
2048 | 496
4096 |@3389
8192 |@@@  14518
   16384 |@4856
   32768 | 742
   65536 | 119
  131072 | 38
  262144 | 9
  524288 | 25
 1048576 | 7
 2097152 | 0

  write
   value  - Distribution - count
  64 | 0
 128 | 55
 256 |@@   8750
 512 |@@   52926
1024 |@34370
2048 |@@@  24610
4096 |@@@  12136
8192 |@@@  10819
   16384 |@4181
   32768 | 1198
   65536 | 811
  131072 | 793
  262144 | 278
  524288 | 26
 1048576 | 2
 2097152 | 0
 4194304 | 0
 8388608 | 0
16777216 | 0
33554432 | 0
67108864 | 0
   134217728 | 0
   268435456 | 0
   536870912 | 0
  1073741824 | 0
  2147483648 | 0
  4294967296 | 0
  8589934592 | 0
 17179869184 | 0
 34359738368 | 0
 68719476736 | 1
137438953472 | 0

NFSv3 read/write by host (total us):

  x.16.0.x   1987595
  x.16.0.x   2588201
  x.16.0.x  20370903
  x.16.0.x  21400116
  x.16.0.x  25208119
  x.16.0.x  28874221
  x.16.0.x  32523821
  x.16.0.x  41103342
  x.16.0.x  43934153
  x.16.0.x  51819379
  x.16.0.x 57477455
  x.16.0.x  57679165
  x.16.0.x  59575938
  x.16.0.x  95072158
  x.16.0.x 305615207
  x.16.0.x 349252742
  x.16.0.x  131175486635

NFSv3 read/write top 10 files (total us):

  /teste/file1   29942610
  /teste/file2   32180289
  /teste

Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-08 Thread Jim Mauro
Got it.

OK, so you traced for 10 minutes, and dtrace reported a total
value of 131175486635, which we'll round up to 132 billion
microseconds, or (if I'm doing the math right),
132,000 seconds or 2200 minutes. That certainly seems to be
an extraordinarily large value for 10 minutes of data collection, but...

Before we venture further into  this, I need to
know what size machine (how many CPUs, etc) this script was run
on, and I need to see the other output - the read and write latency
quantize graphs. I'm interested in seeing the counts as well as
the latency values, and the file latency summary.


Marcelo Leal wrote:
> Hello,
>
>   
>> Are you referring to nfsv3rwsnoop.d?
>>
>> The TIME(us) value from that script is not a latency
>> measurement,
>> it's just a time stamp.
>>
>> If you're referring to a different script, let us
>> know specifically
>> which script.
>> 
>
>  Sorry, when i did write "latency", i did assume that you will know that i 
> was talking about the "nfsv3rwtime.d" script. Sorry...  i mean, that is the 
> script in the wiki page to see the latencies. 
>  The:
>  "NFSv3 read/write by host (total us):" 
>  and
> "NFSv3 read/write top 10 files (total us):"
>
>  are showing that numbers...
>
>  Thanks a lot for your answer!
>
>  Leal.
>   
>> /jim
>>
>>
>> Marcelo Leal wrote:
>> 
>>> Hello there,
>>>  Ten minutes of trace (latency), using the nfs
>>>   
>> dtrace script from nfsv3 provider wiki page, i got
>> total numbers (us) like:
>> 
>>>  131175486635
>>>   ???
>>>
>>>  thanks!
>>>   
>>>   
>> ___
>> dtrace-discuss mailing list
>> dtrace-discuss@opensolaris.org
>> 
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-08 Thread Marcelo Leal
Hello,

> Are you referring to nfsv3rwsnoop.d?
> 
> The TIME(us) value from that script is not a latency
> measurement,
> it's just a time stamp.
> 
> If you're referring to a different script, let us
> know specifically
> which script.

 Sorry, when i did write "latency", i did assume that you will know that i was 
talking about the "nfsv3rwtime.d" script. Sorry...  i mean, that is the script 
in the wiki page to see the latencies. 
 The:
 "NFSv3 read/write by host (total us):" 
 and
"NFSv3 read/write top 10 files (total us):"

 are showing that numbers...

 Thanks a lot for your answer!

 Leal.
> 
> /jim
> 
> 
> Marcelo Leal wrote:
> > Hello there,
> >  Ten minutes of trace (latency), using the nfs
> dtrace script from nfsv3 provider wiki page, i got
> total numbers (us) like:
> >  131175486635
> >   ???
> >
> >  thanks!
> >   
> ___
> dtrace-discuss mailing list
> dtrace-discuss@opensolaris.org
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-05 Thread Jim Mauro
Are you referring to nfsv3rwsnoop.d?

The TIME(us) value from that script is not a latency measurement,
it's just a time stamp.

If you're referring to a different script, let us know specifically
which script.

/jim


Marcelo Leal wrote:
> Hello there,
>  Ten minutes of trace (latency), using the nfs dtrace script from nfsv3 
> provider wiki page, i got total numbers (us) like:
>  131175486635
>   ???
>
>  thanks!
>   
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org


[dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?

2008-12-04 Thread Marcelo Leal
Hello there,
 Ten minutes of trace (latency), using the nfs dtrace script from nfsv3 
provider wiki page, i got total numbers (us) like:
 131175486635
  ???

 thanks!
-- 
This message posted from opensolaris.org
___
dtrace-discuss mailing list
dtrace-discuss@opensolaris.org