Hi Experts,
_write
value ------------- Distribution ------------- count
4096 | 0
8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1161825
16384 | 2754
32768 |@ 42041
65536 | 1175
131072 | 649
262144 | 492
524288 | 143
1048576 | 50
2097152 | 31
4194304 | 54
8388608 | 275
16777216 | 27
33554432 | 23
67108864 | 5
134217728 | 0
If you look at the statistics value for the second last interval, the value is 5
writes for 67ms. There are instances when the statistic is spoiled by just few
writes like this.
My question related to this is " can we isolate why this write is taking
so much time?" or "can we isolate during which write this data was
seen?"
--
This message posted from opensolaris.org
On Mon, Apr 27, 2009 at 8:31 AM, Renil Thomas <thomson_pace at yahoo.co.in> wrote:> Hi Experts, > > > ?_write > ? ? ? ? ? value ?------------- Distribution ------------- count > ? ? ? ? ? ?4096 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 0 > ? ? ? ? ? ?8192 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ ? 1161825 > ? ? ? ? ? 16384 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 2754 > ? ? ? ? ? 32768 |@ ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?42041 > ? ? ? ? ? 65536 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 1175 > ? ? ? ? ?131072 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 649 > ? ? ? ? ?262144 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 492 > ? ? ? ? ?524288 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 143 > ? ? ? ? 1048576 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 50 > ? ? ? ? 2097152 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 31 > ? ? ? ? 4194304 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 54 > ? ? ? ? 8388608 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 275 > ? ? ? ?16777216 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 27 > ? ? ? ?33554432 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 23 > ? ? ? ?67108864 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 5 > ? ? ? 134217728 | ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 0 > > > If you look at the statistics value for the second last interval, the value is 5 writes for 67ms. There are instances when the statistic is spoiled by just few writes like this. > My question related to this is ?" can we isolate why this write is taking so much time?" or "can we isolate during which write this data was seen?"Yes, you can get more information about the long writes. Use the difference you''re using to create this distribution (e.g., timestamp - self->ts) in the predicate for a separate clause, like this (assuming you''re tracing the write(2) system call): syscall::write:return / self->ts && timestamp - self->ts > 33554432 / { /* record data */ } Chad
Currently, the d-script used here is as below :
#!/usr/sbin/dtrace -s
syscall::write:entry
/pid == $1 && tid == 3 /
{
self->timestamp_ = timestamp;
self->traceme = 1;
}
syscall::write:return
/self->timestamp_ && pid == $1 && tid == 3 /
{
self->traceme = 0;
@data["write"] = quantize(timestamp - self->timestamp_);
@dataavg["write"] = avg(timestamp - self->timestamp_);
}
alloccgblk:entry
/self->traceme/
{
self->timestamp_alloccgblk = timestamp;
}
alloccgblk:return
/self->traceme && self->timestamp_alloccgblk/
{
@data["alloccgblk"] = quantize(timestamp -
self->timestamp_alloccgblk);
@dataavg["alloccgblk"] = avg(timestamp -
self->timestamp_alloccgblk);
self->timestamp_alloccgblk = 0;
}
mapsearch:entry
/self->traceme/
{
self->timestamp_mapsearch = timestamp;
}
mapsearch:return
/self->traceme && self->timestamp_mapsearch/
{
@data["mapsearch"] = quantize(timestamp -
self->timestamp_mapsearch);
@dataavg["mapsearch"] = avg(timestamp -
self->timestamp_mapsearch);
self->timestamp_mapsearch = 0;
}
tick-60sec {
printa(@dataavg);
printa(@data);
exit(0);
}
--
This message posted from opensolaris.org
You may try this: Renil Thomas wrote:> Currently, the d-script used here is as below : > > #!/usr/sbin/dtrace -s > > syscall::write:entry > /pid == $1 && tid == 3 / > { > self->timestamp_ = timestamp; > self->traceme = 1; > } > > syscall::write:return > /self->timestamp_ && pid == $1 && tid == 3 / > { > self->traceme = 0; > @data["write"] = quantize(timestamp - self->timestamp_); > @dataavg["write"] = avg(timestamp - self->timestamp_);self->need_attention = timestamp - self->timestamp_ > 1000000?1:0;> } >syscall::write:return /self->need_attention/ { self->need_attention = 0; printf("Caught:"); stack(); ustack(); //or something else... }> alloccgblk:entry > /self->traceme/ > { > self->timestamp_alloccgblk = timestamp; > } > > alloccgblk:return > /self->traceme && self->timestamp_alloccgblk/ > { > @data["alloccgblk"] = quantize(timestamp - > self->timestamp_alloccgblk); @dataavg["alloccgblk"] > avg(timestamp - self->timestamp_alloccgblk); > self->timestamp_alloccgblk = 0; > > } > > mapsearch:entry > /self->traceme/ > { > self->timestamp_mapsearch = timestamp; > } > > mapsearch:return > /self->traceme && self->timestamp_mapsearch/ > { > @data["mapsearch"] = quantize(timestamp - > self->timestamp_mapsearch); @dataavg["mapsearch"] > avg(timestamp - self->timestamp_mapsearch); > self->timestamp_mapsearch = 0; } > > > tick-60sec { > printa(@dataavg); > printa(@data); > exit(0); > }