Dtrace snippets useful for observing metaslab performance in ZFS.
dtrace -qn '::metaslab_df_alloc:entry {@[args[0]->ms_start, args[0]->ms_id] = lquantize(args[0]->ms_fragmentation, 0, 100);} END {printa(" Offset: 0x%-20x\n Mslab#: %-4d\n %@d\n", @);}'
# ZFS metaslab condition, percentage free in current metaslab
dtrace -qn 'fbt::metaslab_pp_load:entry /arg0/ { this->pct = (args[0]->sm_space *100)/ args[0]->sm_size; @pct[walltimestamp, this->pct] = count();} tick-1s { printa("%Y %%pct free: %d count: %@d\n",@pct); trunc(@pct); }'
# Metaslab allocation latency
dtrace -n '::metaslab_alloc:entry { this->datetime = timestamp} ::metaslab_alloc:return / this->datetime /{ this->elapsed = timestamp - this->datetime; this->datetime = 0; printf ("%s=%-16d","Elapsed",this->elapsed/1000)}'
# Same as above, using a quantize function
dtrace -n '::metaslab_alloc:entry { self->ts = timestamp} ::metaslab_alloc:return / self->ts /{ this->elapsed = timestamp - self->ts; @lat["Time(us)"] = quantize(this->elapsed/1000); self->ts = 0} tick-5sec{ printa(@lat); trunc(@lat)}'
dtrace -n '::metaslab_alloc:entry { this->child = stringof(args[0]->spa_dsl_pool->dp_mos_dir->dd_myname); this->parent = stringof(args[0]->spa_dsl_pool->dp_mos_dir->dd_parent->dd_myname); @parent[this->child, this->parent] = count(); }'
dtrace -qn 'BEGIN {printf("Tracing ZFS metaslab alloc. metaslab_df_free_pct = %d %%\n",`metaslab_df_free_pct); } fbt::metaslab_pp_load:entry /arg0/ { this->pct = (args[0]->sm_space *100)/ args[0]->sm_size; @pct["%pct free"] = lquantize(this->pct,0,100,1); }'
dtrace -n '
BEGIN {
threshold = 32768;
}
::metaslab_alloc:entry {
self->ts = timestamp;
self->psize = args[2];
self->spa = args[0];
}
::metaslab_alloc:return /self->spa/ {
this->delta = timestamp - self->ts;
@[self->spa->spa_name,
self->psize <= threshold ? "psize <=32K" : "psize >32K"
] = quantize(this->delta);
self->ts = 0;
self->psize = 0;
self->spa = 0;
}'
dtrace -qn '
BEGIN {
printf("timestamp,bytes,aggr.func,time.delta\n");
}
tick-5sec {
ts = walltimestamp;
}
::metaslab_df_alloc:entry /ts/ {
self->amt = arg1; /* how much data needs writing */
self->alloc_ts = timestamp;
self->metaslab = args[0];
}
::metaslab_df_alloc:return /self->alloc_ts != 0 && self->metaslab/ {
this->t = (timestamp - self->alloc_ts);
this->delta = this->t > 0 ?
this->t : 1; /* make sure we do not div-by-0! */
@amin[ts, self->amt, "MIN"] = min(this->delta);
@amax[ts, self->amt, "MAX"] = max(this->delta);
/* total is a sum of time spent allocating for self->amt of data */
@asum[ts, self->amt, "TOTAL"] = sum(this->delta);
/* measure of central tendency below*/
@amean[ts, self->amt, "MEAN"] = avg(this->delta);
/* stddev is deviation between times spent allocating
for self->amt of data
*/
@astddev[ts, self->amt, "STDDEV"] = stddev(this->delta);
self->metaslab = 0;
self->alloc_ts = 0;
ok_flush = 1;
}
tick-10sec /ok_flush/ {
printa("%Y,%d,%s,%@d\n", @amin);
printa("%Y,%d,%s,%@d\n",@amax);
printa("%Y,%d,%s,%@d\n", @amean);
printa("%Y,%d,%s,%@d\n", @astddev);
printa("%Y,%d,%s,%@d\n", @asum);
trunc(@amin); trunc(@amax);
trunc(@amean); trunc(@astddev); trunc(@asum);
ok_flush = 0;
}'