szaydel
2/4/2014 - 6:52 PM

Dtrace snippets useful for observing metaslab performance in ZFS.

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;
    }'