Re: [dtrace-discuss] Is the nfs dtrace script right (from nfsv3 provider wiki)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
> 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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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)?
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
