Statistics Log Cache Information

Examples

#pragma linkage(BPX1PCT, OS)
#pragma LANGLVL(EXTENDED)

extern void BPX1PCT(char *, int, int, char *, int *, int *, int *);

#include <stdio.h>

#define ZFSCALL_STATS    0x40000007
#define STATOP_LOG_CACHE 247 /* Performance API queries */
#define BUFFER_SIZE      1024 * 64

#define CONVERT_RATIO_TO_INTS(RATIO, INTEGER, DECIMAL)                  \
  {                                                                     \
    INTEGER = (int)RATIO;                                               \
    DECIMAL = (int)((RATIO - (double)INTEGER) * (double)1000.0);        \
  }

typedef struct syscall_parmlist_t
{
  int               opcode;   /* Operation code to perform             */
  int               parms[7]; /* Specific to type of operation,        */
                              /* provides access to the parms          */
                              /* parms[4]-parms[6] are currently unused*/
} syscall_parmlist;

typedef struct hyper {
  unsigned int      high; /* unsigned int  reserved */
  unsigned int      low;
} hyper;

typedef struct API_NL_STATS_t  {
  char         nl_eye[4];         /* Eye catcher = AMET */
#define        NL_EYE "NLST"
  short        nl_size;           /* Size of output structure */
  char         nl_version;        /* Version of statistics returned */
#define        NL_VER_2 2
  char         nl_future;         /* Future use */
  unsigned int nl_logs;           /* Number of log files */
  unsigned int nl_reclaim_pct;    /* Pct. of log reclaimed at log-full time */
  unsigned int nl_blocks_per_pio; /* Max number of log file blocks to write
                                     per log IO */
  unsigned int nl_sched_pct;  /*Inactive buffer schedule pct. (of log size)*/
  unsigned int nl_cachesize;  /*Number of pages in cache*/
  unsigned int nl_fixed;      /*Non-zero if cache permanently fixed in memory*/
  unsigned int nl_freeitems;  /*Number of unused pages in cache*/
  unsigned int nl_ios;        /*Number of IOs in-progress*/
  unsigned int nl_numblks;    /*Number of dirty meta blocks*/
  unsigned int nl_future1;    /*Number of unused pages in cache*/
  unsigned long long int nl_tran_started;       /* Number of started
                                                   transactions */
  unsigned long long int nl_act_schedules;      /* Number of times active
                                                   records scheduled to disk */
  unsigned long long int nl_comp_schedules;     /* Numner of times complete
                                                   records scheduled to disk */
  unsigned long long int nl_act_pages;          /* Number of active pages
                                                   scheduled to disk */
  unsigned long long int nl_comp_pages;         /* Number of completed pages
                                                   scheduled to disk */
  unsigned long long int nl_tran_merged;        /* Number of merged
                                                   transactions */
  unsigned long long int nl_act_recswrote;      /* Number of active records
                                                   written */
  unsigned long long int nl_comp_recswrote;     /* Number of complete tran
                                                   records written */
  unsigned long long int nl_comp_transize;      /* Number of batched/merged
                                                   transactions written */
  unsigned long long int nl_tran_active_force;  /* Number of times an active
                                                   tran forced */
  unsigned long long int nl_tran_complete_force;/* Number of times a complete
                                                   tran forced */
  unsigned long long int nl_recoveries;         /* Number of times log file
                                                   recovery was run */
  unsigned long long int nl_bufupdates;         /* Number of buffer updates */
  unsigned long long int nl_bufnew;             /* Number of buffer updates
                                                   creating new update record*/
  unsigned long long int nl_bufavoid;           /* Number of buffer updates
                                                   avoided due to prior
                                                   update */
  unsigned long long int nl_bufovlap;           /* Number of buffer updates
                                                   that had overlap */
  unsigned long long int nl_killavoid;          /* Avoided metadata IOs due to
                                                   kill-avoid */
  unsigned long long int nl_schedules;          /* Number of times older
                                                   buffers scheduled to disks*/
  unsigned long long int nl_bufsched;           /* Number of actual buffers
                                                   schedules and also avg.
                                                   quicksort size */
  unsigned long long int nl_endmerges;          /* Number of times merged
                                                   active records with
                                                   previously completed active
                                                   trans */
  unsigned long long int nl_endmgcnt;           /* Number of records merged
                                                   active records with
                                                   previously completed active
                                                   trans */
  unsigned long long int nl_endnew;             /* Number of records merged
                                                   that were new to prior
                                                   completed tran records */
  unsigned long long int nl_endavoid;           /* Number of records merged
                                                   that could be skipped
                                                   because prior completed
                                                   record covered it */
  unsigned long long int nl_endovlap;           /* Number of records merged
                                                   that had overlap with
                                                   previously written trans */
  unsigned long long int nl_nbswrites;          /* Number of times we added
                                                   NBS blocks to active tran */
  unsigned long long int nl_kills;              /* Number of kill calls for
                                                   buffers deallocated with
                                                   tran */
  unsigned long long int nl_forcecomp;          /* Number of times a forced
                                                   write of buffer forces
                                                   complete tran recods to
                                                   log */
  unsigned long long int nl_forceact;           /* Number of times a forced
                                                   write of buffer forces
                                                   active tran recods to log */
  unsigned long long int nl_forces;             /* Number of force calls */
  unsigned long long int nl_forcewaits;         /* Number of times a force has
                                                   to wait for in-progress
                                                   log pages*/
  unsigned long long int nl_hfact;              /* Number of times a
                                                   handle-full has to write
                                                   active records*/
  unsigned long long int nl_hfcomp;             /* Number of times a
                                                   handle-full has to write
                                                   comp records*/
  unsigned long long int nl_hf;                 /* Number of handle full
                                                   calls */
  unsigned long long int nl_hfsched;            /* Number of times a
                                                   handle-full had to schedule
                                                   buffers */
  unsigned long long int nl_hfsched_blocks;     /* Number of times a
                                                   handle-full scheduled
                                                   buffers and hence quicksort
                                                   blocks */
  unsigned long long int nl_sync;               /* Number of times a log sync
                                                   was requested */
  unsigned long long int nl_bufwaits;           /* Number of times had to wait
                                                   for a buffer */
  unsigned long long int nl_bufmallocs;         /* Number of emergency mallocs
                                                   to avoid deadlock */
  unsigned long long int nl_act_comp_copies;    /* Number of times a write to
                                                   active log had to copy
                                                   completed tran bytes */
  unsigned long long int nl_future2[8];         /* Stats for the future */
} API_NL_STATS;


/* Version 1 Output structure */
typedef struct API_LOG_STATS_t {
  char  al_eye[4];        /* Eye catcher = ALOG */
#define LS_EYE "ALOG"
  short al_size;          /* Size of output structure */
  char  al_version;       /* Version of stats */
#define LS_VER_INITIAL 1  /* First version of log stats */
  char  al_reserved1;     /* Reserved byte, 0 in version 1 */
  hyper al_buffers;       /* Number of buffers used */
  int   al_reserved2;     /* Reserved for future use, 0 in version 1 */
  int   al_buffsize;      /* Size in kilobytes of one buffer */
  hyper al_lookups;       /* Lookups/creates of item in log buffer cache */
  hyper al_hits;          /* Hits, number of times item found in cache */
  hyper al_writtenPages;  /* Number of log buffer pages written to disk */
  hyper al_fullWaits;     /* Number of time new log buffer requires wait
                             on prior log pages */
  hyper al_nbsWaits;      /* Number of time new log buffer requires wait 
                             on new block user IO */
  int   al_reserved3[10]; /* Reserved for future use */
} API_LOG_STATS;

/* reset timestamp */
typedef struct reset_time {
  unsigned int      posix_time_high; /* high order 32 bits since epoc */
  unsigned int      posix_time_low;  /* low order 32 bits since epoch */
  unsigned int      posix_usecs;     /* microseconds */
  int               pad1;
} RESET_TIME;

/*********************************************************************/
/* The following structure is the api query control block.           */
/* It is used for all api query commands.                            */
/*********************************************************************/
typedef struct stat_api_t {
#define             SA_EYE "STAP"
  char              sa_eye[4];     /* 4 byte identifier must be */
  int               sa_len;        /* length of the buffer to put data into*/
                                   /* this buffer area follows this struct */
  int               sa_ver;        /* the version number currently 1 or 2 */
#define             SA_VER_2 0x02
#define             SA_VER_INIT 0x01
  char              sa_flags;      /* flags field must be x00 or x80, */
                                   /* x80 means reset statistics      */
#define             SA_RESET 0x80
  char              sa_fill[3];       /* spare bytes */
  int               sa_supported_ver; /* version of data returned */
  int               sa_reserve[3];    /* Reserved */
  struct reset_time reset_time_info;
} STAT_API;

int print_logcache_version1(char *buffp, int buff_fill_len);
int print_logcache_version2(char *buffp, int buff_fill_len);

int main(int argc, char **argv) 
{
  int      bpxrv;
  int      bpxrc;
  int      bpxrs;
  int      i;
  double   temp_ratio;
  int      buff_fill_len;
  int      whole, decimal;
  char     buf[33];

  unsigned long long int temp_hits, temp_total;
  
  STAT_API          local_req;
  char*             buffp   = NULL;
  syscall_parmlist* parmp   = NULL;
  STAT_API*         stapptr = NULL;
  API_NL_STATS*     nlp     = NULL;

  stapptr = &local_req;
  memset( stapptr, 0x00, sizeof(STAT_API) );
  memcpy( stapptr->sa_eye, SA_EYE, 4 );

  stapptr->sa_ver = NL_VER_2;
  stapptr->sa_len = sizeof(API_NL_STATS);
  
  buffp = (char*) malloc(BUFFER_SIZE);
  if( buffp == NULL )
  {
    printf("Malloc Error\n");
    return 0;
  }
  memset( buffp, 0x00, sizeof(syscall_parmlist) + sizeof(STAT_API));

  parmp = (syscall_parmlist*) &buffp[0];
  parmp->opcode   = STATOP_LOG_CACHE;
  parmp->parms[0] = sizeof(syscall_parmlist);
  parmp->parms[1] = sizeof(syscall_parmlist) + sizeof(STAT_API);
  parmp->parms[2] = 0;
  parmp->parms[3] = 0;
  parmp->parms[4] = 0;
  parmp->parms[5] = 0;
  parmp->parms[6] = 0;
    
  buff_fill_len = sizeof(syscall_parmlist);
  stapptr = (STAT_API*) &buffp[buff_fill_len];
  memcpy( stapptr, &local_req, sizeof(STAT_API) );
  buff_fill_len += sizeof(STAT_API);

  BPX1PCT("ZFS     ",
          ZFSCALL_STATS, /* Perf statistics operation */
          BUFFER_SIZE,   /* Length of Argument */
          buffp,         /* Pointer to Argument */
          &bpxrv,        /* Pointer to Return_value */
          &bpxrc,        /* Pointer to Return_code */
          &bpxrs);       /* Pointer to Reason_code */

  if (bpxrv < 0) 
  {
    printf("Error querying log cache, BPXRV = %d BPXRC = %d BPXRS = %x\n",
           bpxrv, bpxrc, bpxrs);
    return bpxrc;
  } 
  else 
  {
    if( stapptr->sa_supported_ver == SA_VER_INIT )
      print_logcache_version1(buffp, buff_fill_len);
    else
      print_logcache_version2(buffp, buff_fill_len);

    if (0 == ctime_r((time_t*) & stapptr->reset_time_info.posix_time_low, buf))
      printf("Could not get timestamp.\n");
    else 
    {   /* Insert the microseconds into the displayable time value */
      strncpy(&(buf[27]), &(buf[20]), 6);
      sprintf(&(buf[20]), "%06d", stapptr->reset_time_info.posix_usecs);
      buf[26] = ' ';
      buf[19] = '.';
      printf("Last Reset Time: %s", buf);
    }
  }
  return 0;
}


int print_logcache_version2(char *buffp, int buff_fill_len)
{
  int      i;
  int      whole, decimal;
  double   temp_ratio;
  unsigned long long int temp_hits, temp_total;
  API_NL_STATS *nlp = NULL;

  /* Set nlp pointer to the output structure in the buffer */
  nlp = (API_NL_STATS*) &buffp[buff_fill_len];
  printf( "%52s\n","Log File Caching Statistics\n" );
  printf( "Logs\n" );
  printf( "--------\n" );
  printf( "%20u : Log files cached \n", nlp->nl_logs );
  printf( "%20llu : Log files recoveries performed \n",nlp->nl_recoveries );
  printf( "%20llu : Log file syncs (filesys quiesce)\n\n", nlp->nl_sync );
  printf( "Policies\n" );
  printf( "--------\n" );
        
  printf( "%20u : Reclaim pct. (amount reclaimed at log-full time)\n",
          nlp->nl_reclaim_pct );
  printf( "%20u : Maximuem log pages per IO\n",
          nlp->nl_blocks_per_pio );
  printf( "%20u : Inactive buffer schedule pct. (of log size)\n\n",
          nlp->nl_sched_pct );

  printf( "Storage\n" );
  printf( "--------\n" );
  printf( "%20u : Log Cache Size (in 4K pages, fixed=%s)\n",
          nlp->nl_cachesize, nlp->nl_fixed ? "YES" : "NO" );

  temp_hits = nlp->nl_freeitems;
  temp_total = nlp->nl_cachesize;
  if( temp_hits > temp_total )
    temp_hits = temp_total;
  temp_ratio = ((double)temp_hits) / temp_total;
  temp_ratio *= 100.0;

  /* Convert the ratio to ints representing the whole and decimal parts */
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  whole = 100 - whole;

  printf( "%20u : Pct. of cache in-use\n", whole );
  printf( "%20llu : Free page obtain waits\n", nlp->nl_bufwaits );
  printf( "%20llu : Allocations to avoid deadlock\n\n",nlp->nl_bufmallocs );

  printf( "Transactions\n" );
  printf( "------------\n" );
  printf( "%20llu : Transactions started\n", nlp->nl_tran_started );
  printf( "%20llu : Transactions merged\n", nlp->nl_tran_merged );

  temp_total = nlp->nl_comp_schedules;
  temp_hits  = nlp->nl_comp_transize;
  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits) / temp_total;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  decimal = decimal / 100;

  printf( "%18u.%1.1u : Average number of transactions batched together\n",
          whole, decimal );
  printf( "%20llu : Sync calls to an active transaction\n",
          nlp->nl_tran_active_force );
  printf( "%20llu : Sync calls to a completed transaction\n\n",
          nlp->nl_tran_complete_force );

  printf( "IOs and Blocks\n");
  printf( "--------------\n");
  printf( "%20u : Log IOs in progress \n",        nlp->nl_ios );
  printf( "%20u : Dirty metadata blocks\n",       nlp->nl_numblks );
  printf( "%20llu : Metadata block kill calls\n", nlp->nl_kills );
  printf( "%20llu : Log File writes initiated\n", nlp->nl_comp_schedules );

  temp_total = nlp->nl_comp_schedules;
  temp_hits  = nlp->nl_comp_pages;
  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits) / temp_total;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  decimal = decimal / 100; /* Just want tenths */
        
  printf( "     %13u.%1.1u : Average number of pages per log write\n",
          whole, decimal );
  printf( "%20llu : Avoided IOs for metadata block due to deallocation\n",
          nlp->nl_killavoid );
  printf( "%20llu : Scheduled not-recently-updated (NRU) metadata blocks\n",
          nlp->nl_schedules );

  temp_total = nlp->nl_schedules;
  temp_hits = nlp->nl_bufsched;
  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits) / temp_total;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  decimal = decimal / 100; /* Just want tenths */

  printf( "     %13u.%1.1u : Avergage number of blocks per NRU IO\n",
          whole, decimal );
  printf( "%20llu : Metadata buffers forced to disk\n",
          nlp->nl_forces );

  temp_total = nlp->nl_forces;
  temp_hits = nlp->nl_forcecomp;
  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits)/temp_total;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  decimal = decimal / 100; /* Just want tenths */

  printf( "     %13u.%1.1u : Avg where metadata write forced write of log\n",
          whole, decimal );

  temp_hits = nlp->nl_forcewaits;
  temp_total = nlp->nl_forces;

  if( temp_hits > temp_total )
    temp_hits = temp_total;

  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits)/temp_total;
  temp_ratio *= 100.0;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);

  printf( "%18u.%1.1u : Pct. of metadata buffer forces waited on log IO\n",
          whole, decimal );
  printf( "%20llu : Log-full processing calls\n", nlp->nl_hf );
  temp_total = nlp->nl_hf;
  temp_hits  = nlp->nl_hfsched_blocks;
  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits)/temp_total;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  decimal = decimal / 100;   /* Just want tenths */

  printf( "%18u.%1.1u : Avg number of metadata blocks "
          "written per log-full\n\n",
          whole, decimal );

  printf("Update Records\n");
  printf("--------------\n");
  temp_total = nlp->nl_comp_schedules;
  temp_hits = nlp->nl_comp_recswrote;
  temp_ratio = (temp_total == 0) ? 0.0 : ((double)temp_hits)/temp_total;
  CONVERT_RATIO_TO_INTS(temp_ratio,whole, decimal);
  decimal = decimal / 100;   /* Just want tenths */

  printf( "     %13u.%1.1u : Avg number of update records per log IO.\n",
          whole, decimal );
  printf( "%20llu : Number of NBS records written \n", nlp->nl_nbswrites );
  printf( "%20llu : Number of metadata buffer updates \n",
          nlp->nl_bufupdates );
  printf( "%20llu : Number of updates requiring old-byte copying\n",
          nlp->nl_act_comp_copies );
  printf( "%20llu : Avoided buffer update records due to overlap\n",
          nlp->nl_bufavoid );
  printf( "%20llu : Avoided merge update records due to overlap\n\n",
          nlp->nl_endavoid );
}

int print_logcache_version1(char *buffp, int buff_fill_len)
{
  double   temp_ratio;
  int      whole;
  int      decimal;
  API_LOG_STATS *lgstptr = (API_LOG_STATS*) &buffp[buff_fill_len];

  printf("%52s\n", "Log File Caching Statistics");
  printf(" \n");
  printf("Buffers    (K bytes) Requests   Hits       Ratio  Written \n");
  printf("---------- --------- ---------- ---------- ------ ----------\n");

  temp_ratio = (lgstptr->al_lookups.low == 0) ? 0.0 :
               (((double)lgstptr->al_hits.low) / 
                lgstptr->al_lookups.low);
  temp_ratio *= 100.0;
  CONVERT_RATIO_TO_INTS(temp_ratio, whole, decimal);
  decimal = decimal / 100; /* Just want tenths */

  printf("%10u %9u %10u %10u %3u.%1.1u%% %10u\n",
         lgstptr->al_buffers.low,
         lgstptr->al_buffers.low * lgstptr->al_buffsize,
         lgstptr->al_lookups.low, lgstptr->al_hits.low,
         whole, decimal, lgstptr->al_writtenPages.low);

  printf(" \n");
  printf("New buffer: log full waits %10u NBS IO waits %10u\n",
         lgstptr->al_fullWaits.low, lgstptr->al_nbsWaits.low);

  printf(" \n");
}