szaydel
11/14/2016 - 8:12 PM

Dtrace snippets for ARC performance profiling with data output as CSV

Dtrace snippets for ARC performance profiling with data output as CSV

arc_reclaim_needed
arc_available_memory
arc_released
arc_state_esize_dec
arc_state_esize_inc
arc_is_overflowing
arc_change_state
arc_mru
arc_space_return
arc_space_consume
arc_hdr_clear_flags
arc_state_dec_size
arc_state_inc_size
arc_hdr_set_flags
arc_state_size
arc_hdr_size
arc_mfu_ghost
arc_mru_ghost
arc_anon
arc_l2c_only
dtrace -qn '
  inline int WEIGHT = 952 ;
  inline int RUNLEN = 20 ;
  int emacnt;
  int start, data, cnt, noemadata, tottime, lastema ;
  BEGIN {
    printf("timedelta,avg.lat,ema.lat,stddev,longest,tot.time,slow.count,count\n") ;
    start         = timestamp ;
    slowlimit     = 10000000 ; /* 10ms is our threshold between OK and slow */
    }
  ::arc_read:entry { self->s = timestamp ; }
  ::arc_read:return 
  /self->s && timestamp - self->s > 0 && noemadata/ {
    this->ema     = (timestamp - self->s) ;
    lastema       = this->ema ;
    noemadata     = 1 ;
  }

  ::arc_read:return /self->s && timestamp - self->s > 0 / {
    this->delta   = (timestamp - self->s) ;
    @av           = avg(this->delta) ;
    @sd           = stddev(this->delta) ;
    @cnt          = count() ;
    @tottm        = sum(this->delta) ;
    @long         = max(this->delta) ; /* longest observed call latency */

    emacnt++ ;
    tottime       += this->delta ; /* used for ema computation */
    /* 
     * Any function calls slower than 10ms should be considered abnormal and
     * result in this incrementing by 1.
     */
    @slowcnt      = sum(this->delta >= slowlimit ? 1 : 0) ;
    self->s       = 0 ;
    data          = 1 ; /* have data to report */
    }
  tick-50ms /emacnt > 0/ {
    /*
     * Compute exponential moving average, and due to lack of a better means
     * store values in a avg() aggregate, which is not ideal, but it is better
     * than nothing at all.
     */
    this->ema     = ((WEIGHT * (tottime / emacnt)) + 
                    ((10000 - WEIGHT) * lastema)) / 10000 ;
    @ema          = sum(this->ema) ;
    tottime       = 0 ;
    emacnt        = 0 ;
    lastema       = this->ema ;
  }
    /*
     * If we do not have any new data to report, just print NAs,
     * this way we avoid gaps in the data, i.e. 60 seconds results
     * in 60 records stored. 
     */
  tick-1sec /!data/ {
    printf("%d,NA,NA,NA,NA,NA,NA,NA\n", cnt) ;
    ++cnt ;
  }

  tick-1sec /data/ {
    normalize(@ema, RUNLEN) ; /* average of ema(s) */
    printf("%d,", cnt) ;
    printa("%@d,%@d,%@d,%@d,%@d,%@d,%@d\n",
            @av, @ema, @sd, @long, @tottm, @slowcnt, @cnt) ;
    trunc(@av) ; trunc(@ema) ; trunc(@sd) ; trunc(@long) ; 
    trunc(@tottm) ; trunc(@slowcnt) ; trunc(@cnt) ;
    data = 0 ;
    ++cnt ;
}'