rf_tracestats.c

RAIDFrame是个非常好的磁盘阵列RAID仿真工具

/*
 * Copyright (c) 1995 Carnegie-Mellon University.
 * All rights reserved.
 *
 * Author: Mark Holland, Rachad Youssef
 *
 * Permission to use, copy, modify and distribute this software and
 * its documentation is hereby granted, provided that both the copyright
 * notice and this permission notice appear in all copies of the
 * software, derivative works or modified versions, and any portions
 * thereof, and that both notices appear in supporting documentation.
 *
 * CARNEGIE MELLON ALLOWS FREE USE OF THIS SOFTWARE IN ITS "AS IS"
 * CONDITION.  CARNEGIE MELLON DISCLAIMS ANY LIABILITY OF ANY KIND
 * FOR ANY DAMAGES WHATSOEVER RESULTING FROM THE USE OF THIS SOFTWARE.
 *
 * Carnegie Mellon requests users of this software to return to
 *
 *  Software Distribution Coordinator  or  [e-mail]
 *  School of Computer Science
 *  Carnegie Mellon University
 *  Pittsburgh PA 15213-3890
 *
 * any improvements or extensions that they make and grant Carnegie the
 * rights to redistribute these changes.
 */

/*
 * rf_tracestates.c - Post-processor which profiles execution time
 *
 * $Locker:  $
 *
 * $Log: rf_tracestats.c,v $
 * Revision 1.19  1996/07/17  21:00:58  jimz
 * clean up timer interface, tracing
 *
 * Revision 1.18  1996/06/09  02:36:46  jimz
 * lots of little crufty cleanup- fixup whitespace
 * issues, comment #ifdefs, improve typing in some
 * places (esp size-related)
 *
 * Revision 1.17  1996/06/05  18:06:02  jimz
 * Major code cleanup. The Great Renaming is now done.
 * Better modularity. Better typing. Fixed a bunch of
 * synchronization bugs. Made a lot of global stuff
 * per-desc or per-array. Removed dead code.
 *
 * Revision 1.16  1996/05/31  22:26:54  jimz
 * fix a lot of mapping problems, memory allocation problems
 * found some weird lock issues, fixed 'em
 * more code cleanup
 *
 * Revision 1.15  1996/05/30  18:05:42  jimz
 * etimer name change
 *
 * Revision 1.14  1996/05/30  12:59:18  jimz
 * make etimer happier, more portable
 *
 * Revision 1.13  1996/05/23  21:46:35  jimz
 * checkpoint in code cleanup (release prep)
 * lots of types, function names have been fixed
 *
 * Revision 1.12  1996/05/23  00:33:23  jimz
 * code cleanup: move all debug decls to rf_options.c, all extern
 * debug decls to rf_options.h, all debug vars preceded by rf_
 *
 * Revision 1.11  1995/12/12  18:10:06  jimz
 * MIN -> RF_MIN, MAX -> RF_MAX, ASSERT -> RF_ASSERT
 * fix 80-column brain damage in comments
 *
 * Revision 1.10  1995/12/06  15:15:34  root
 * added copyright info
 *
 * Revision 1.9  1995/09/30  22:13:32  jimz
 * fix missing device name error msg
 *
 * Revision 1.8  1995/09/30  20:40:49  jimz
 * added mode where rf_tracestats.c can extract totals,
 * histograms, etc, directly from kernel
 *
 * Revision 1.7  1995/09/30  19:35:06  jimz
 * use rf_hist.h mechanisms for histograms
 *
 * Revision 1.6  1995/09/30  19:28:31  jimz
 * print user_reccount along with avg_acc_time if response_time_only
 * (wvcii change, merged so I can grab lock)
 *
 * Revision 1.5  1995/09/29  21:47:57  wvcii
 * added "-r" option which only prints mean response time
 *
 * Revision 1.4  95/09/12  19:05:41  wvcii
 * reformatted output, commented code
 * 
 * Revision 1.3  1995/09/12  00:22:04  wvcii
 * added support for tracing disk queue time
 *
 * Revision 1.2  95/09/06  15:16:23  wvcii
 * fixed divide by zero errors for workloads with 0 reads or writes
 * 
 */

#include <stdio.h>
#include <unistd.h>
#include <fcntl.h>
#include <sys/param.h>

#include "rf_threadstuff.h"
#include "rf_acctrace.h"
#include "rf_etimer.h"
#include "rf_general.h"
#include "rf_hist.h"
#include "rf_raidframe.h"

#define F(x) ((float) (x))

#define RETRIEVE(_a_) _a_ = acc->_a_

static RF_Hist_t dw_hist[RF_HIST_NUM_BUCKETS], tot_hist[RF_HIST_NUM_BUCKETS];
static int initialized = 0;
static int verbose = 0;
static char *progname;

static unsigned long suspend_ovhd_us= 0, map_us = 0, lock_us = 0;
static unsigned long dag_create_us = 0, dag_retry_us = 0, exec_us = 0;
static unsigned long q_us = 0, xor_us = 0, exec_engine_us = 0, diskwait_us = 0;
static unsigned long plog_us = 0, cleanup_us = 0, total_us = 0, phys_io_us = 0;
static unsigned long user_num_phys_ios = 0, diskqueue_us = 0;

static unsigned long recon_start_to_fetch_us = 0, recon_fetch_to_return_us = 0;
static unsigned long recon_return_to_submit_us = 0, recon_num_phys_ios = 0;
static unsigned long recon_phys_io_us = 0, recon_diskwait_us = 0, recon_io_overflow_count = 0;

static void printrec();

static void hist_add(hist, val)
int *hist;
int val;
{
  int i;

  if (!initialized) {
    for (i = 0; i < RF_HIST_NUM_BUCKETS; i++)
      hist[i] = 0;
    initialized = 1;
  }
  RF_HIST_ADD(hist, val);
}

static void hist_print(hist, string)
int *hist;
char *string;
{
  int i;
  if (!initialized) return;
  printf("\nHistogram of %s time (ms)\n", string);
  for (i=0; i<RF_HIST_NUM_BUCKETS; i++) {
     if (hist[i]) printf("[%4d-%4d] %4d\n",i*RF_HIST_RESOLUTION, (i+1)*RF_HIST_RESOLUTION-1, hist[i]);
  }
}

main(argc, argv)
int argc;
char **argv;
{
  FILE *fp;
  RF_AccTraceEntry_t rec;
  int user_reccount, recon_reccount, accounted_for_us;
  float avg_acc_time, t;
  int i, bigvals = 0, io_overflow_count = 0, print_all_recs = 0;
  int response_time_only = 0, kernelsrc = 0, dev_fd, rc;
  RF_AccTotals_t r_acc, *acc;
  char *devname;
  RF_Etimer_t timer;

  progname = argv[0];

  rf_ConfigureEtimer();
  argc--; argv++;
  while (argc && argv[0][0] == '-') {
    switch (argv[0][1]) {
      case 'k':
		kernelsrc = 1;
		devname = &argv[0][2];
		break;
      case 'v': verbose = 1; break;
      case 'p': print_all_recs = 1; break;
      case 'r': response_time_only = 1; break;
      default: printf("unknown option %s\n",argv[0]);
    }
    argc--; argv++;
  }
  if (kernelsrc) {
	if (devname[0] == '\0') {
		fprintf(stderr, "%s: missing device name\n", progname);
		fflush(stderr);
		exit(1);
	}
	dev_fd = open(devname, O_RDONLY);
	if (dev_fd < 0) {
		perror("devname");
		fflush(stderr);
		exit(1);
	}
	acc = &r_acc;
	rc = ioctl(dev_fd, RAIDFRAME_GET_ACCTOTALS, acc);
	if (rc) {
		perror("RAIDFRAME_GET_ACCTOTALS");
		fflush(stderr);
		exit(1);
	}
	RETRIEVE(recon_start_to_fetch_us);
	RETRIEVE(recon_fetch_to_return_us);
	RETRIEVE(recon_return_to_submit_us);
	RETRIEVE(recon_io_overflow_count);
	RETRIEVE(recon_phys_io_us);
	RETRIEVE(recon_num_phys_ios);
	RETRIEVE(recon_diskwait_us);
	RETRIEVE(recon_reccount);
	RETRIEVE(suspend_ovhd_us);
	RETRIEVE(map_us);
	RETRIEVE(lock_us);
	RETRIEVE(dag_create_us);
	RETRIEVE(dag_retry_us);
	RETRIEVE(exec_us);
	RETRIEVE(cleanup_us);
	accounted_for_us = suspend_ovhd_us + map_us + lock_us + dag_create_us
			+ dag_retry_us + exec_us + cleanup_us;
	RETRIEVE(exec_engine_us);
	RETRIEVE(xor_us);
	RETRIEVE(q_us);
	RETRIEVE(diskqueue_us);
	RETRIEVE(diskwait_us);
	RETRIEVE(phys_io_us);
	RETRIEVE(total_us);
	io_overflow_count = acc->phys_io_overflow_count;
	user_num_phys_ios = acc->num_phys_ios;
	RETRIEVE(user_reccount);
  } else { /* kernelsrc */
  if (!argc) fp = stdin;
  else if ((fp = fopen(argv[0], "r")) == NULL) {
    fprintf(stderr,"Unable to open file %s\n",argv[0]); exit(1);
  }
  user_reccount = recon_reccount = accounted_for_us = 0;
  while (fread(&rec, sizeof(RF_AccTraceEntry_t), 1, fp) == 1) {
    if (print_all_recs) printrec(&rec);
    if (rec.reconacc) {
      recon_start_to_fetch_us += rec.specific.recon.recon_start_to_fetch_us;
      recon_fetch_to_return_us += rec.specific.recon.recon_fetch_to_return_us;
      recon_return_to_submit_us += rec.specific.recon.recon_return_to_submit_us;
      recon_phys_io_us += rec.phys_io_us;
      recon_num_phys_ios += rec.num_phys_ios;
      recon_diskwait_us += rec.diskwait_us;
      recon_reccount++;
    } else {
      if (verbose) printf("tot %d dw %d\n",rec.total_us,rec.diskwait_us);
      hist_add(tot_hist, rec.total_us);   /* histogram of user io response time */
      hist_add(dw_hist, rec.diskwait_us); /* histogram of physical disk access time */

      /* count of physical ios which are too big.  often due to thermal recalibration */
      /* if bigvals > 0, you should probably ignore this data set */
      if (rec.diskwait_us > 100000) bigvals++;

      /* total time in trace */
      total_us        += rec.total_us;
      
      /* these numbers profile entire trace */
      /* since these components are executed sequentially, their sum should equal total_us */
      suspend_ovhd_us += rec.specific.user.suspend_ovhd_us;  accounted_for_us += rec.specific.user.suspend_ovhd_us;
      map_us          += rec.specific.user.map_us;           accounted_for_us += rec.specific.user.map_us;
      lock_us         += rec.specific.user.lock_us;          accounted_for_us += rec.specific.user.lock_us;
      dag_create_us   += rec.specific.user.dag_create_us;    accounted_for_us += rec.specific.user.dag_create_us;
      dag_retry_us    += rec.specific.user.dag_retry_us;     accounted_for_us += rec.specific.user.dag_retry_us;
      exec_us         += rec.specific.user.exec_us;          accounted_for_us += rec.specific.user.exec_us;
      cleanup_us      += rec.specific.user.cleanup_us;       accounted_for_us += rec.specific.user.cleanup_us;

      /* these numbers profile exec_us */
      /* since some of these components are executed concurrently, their sum does NOT equal exec_us */
      exec_engine_us  += rec.specific.user.exec_engine_us; /* overhead of processing graph */
      xor_us          += rec.xor_us; /* time spent in performing xor operations */
      q_us            += rec.q_us;   /* time spent computing "Q" */
      plog_us         += rec.plog_us; /* time spent inserting records into parity log */
      diskqueue_us    += rec.diskqueue_us; /* total time spent in disk queues */
      diskwait_us     += rec.diskwait_us;  /* total time spent in physical disk */

      phys_io_us += rec.phys_io_us;
      user_num_phys_ios += rec.num_phys_ios;

      user_reccount++;  /* count of total trace records processed */
    }

  }
  } /* kernelsrc */

  if (user_reccount) {
    avg_acc_time = F(total_us) / F(user_reccount);
    if (response_time_only) /* print num ios, response time */
      printf("%d %8.2f\n", user_reccount, avg_acc_time);
    else {
      printf("CPU speed:  %d MHz\n", rf_timer_ticks_per_second / 1000000);
      printf("Average Access Time: %8.2f us\n", avg_acc_time);
      printf("      Suspend Ovhd : %8.2f us (%4.1f %%)\n", (t = F(suspend_ovhd_us) / F(user_reccount)), 100*t/avg_acc_time);
      printf("      Mapping      : %8.2f us (%4.1f %%)\n", (t = F(map_us) / user_reccount), 100*t/avg_acc_time);
      printf("      Locking      : %8.2f us (%4.1f %%)\n", (t = F(lock_us) / user_reccount), 100*t/avg_acc_time);
      printf("      DAG Creation : %8.2f us (%4.1f %%)\n", (t = F(dag_create_us) / user_reccount), 100*t/avg_acc_time);
      printf("      DAG Retry    : %8.2f us (%4.1f %%)\n", (t = F(dag_retry_us) / user_reccount), 100*t/avg_acc_time);
      printf("      Cleanup      : %8.2f us (%4.1f %%)\n", (t = F(cleanup_us) / user_reccount), 100*t/avg_acc_time);
      printf("      DAG Execution: %8.2f us (%4.1f %%)\n", (t = F(exec_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     ******** DAG Execution Profile ********\n");
      printf("                     DAG Processing   : %8.2f us (%4.1f %%)\n", (t = F(exec_engine_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     Total Xor Time   : %8.2f us (%4.1f %%)\n", (t = F(xor_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     Total Q Time     : %8.2f us (%4.1f %%)\n", (t = F(q_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     Total Log Time   : %8.2f us (%4.1f %%)\n", (t = F(plog_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     Total Disk Queue : %8.2f us (%4.1f %%)\n", (t = F(diskqueue_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     Total Disk Phys  : %8.2f us (%4.1f %%)\n", (t = F(diskwait_us) / user_reccount), 100*t/avg_acc_time);
      printf("                     ******* summary disk statistics *******\n");
      if (io_overflow_count) printf("                     Num phys IOs     : %8.2, neglecting %d overflows\n", (float) user_num_phys_ios / (float) user_reccount, io_overflow_count);
      else printf("                     Avg num phys IOs : %8.2f\n", (float) user_num_phys_ios / (float) user_reccount);
      printf("                     Avg queueing time: %8.2f us (%4.1f %%)\n", (t = F(diskqueue_us) / user_num_phys_ios), 100*t/avg_acc_time);
      printf("                     Avg physical time: %8.2f us (%4.1f %%)\n", (t = F(phys_io_us) / user_num_phys_ios), 100*t/avg_acc_time);
      printf("                     Avg total time   : %8.2f us (%4.1f %%)\n", (t = F(phys_io_us + diskqueue_us) / user_num_phys_ios), 100*t/avg_acc_time);
      
      printf("\nTotal microseconds in trace: %d\n",total_us);
      printf("Total microseconds accounted for: %d (%0.1f %%)\n",accounted_for_us, 100*F(accounted_for_us) / F(total_us));
      printf("\nValues > 100 ms: %d\n",bigvals);
      
      hist_print(tot_hist, "total access");
      hist_print(dw_hist, "diskwait");
    }
  }
  if (recon_reccount) {
    printf("Average start->fetch delay  : %8.2f us\n",F(recon_start_to_fetch_us) / recon_reccount);
    printf("Average fetch->return delay : %8.2f us\n",F(recon_fetch_to_return_us) / recon_reccount);
    printf("Average return->submit delay: %8.2f us\n",F(recon_return_to_submit_us) / recon_reccount);
    printf("Average disk wait time      : %8.2f us\n",F(recon_diskwait_us) / recon_reccount);
    printf("Average num phys I/Os (sb 1): %8.2f\n",   F(recon_num_phys_ios) / recon_reccount);
  }
}


static void printrec(rec)
  RF_AccTraceEntry_t  *rec;
{
  static int recno = 0;
  int s2f, f2r, r2s;
  RF_Etimer_t timer;

  recno++;
  printf("Record %4d: ",recno);
  if (rec->reconacc) {
    s2f = rec->specific.recon.recon_start_to_fetch_us;
    f2r = rec->specific.recon.recon_fetch_to_return_us;
    r2s = rec->specific.recon.recon_return_to_submit_us;
    printf("(s->f %d f->r %d r->s %d) ",s2f, f2r, r2s);
  } else {
    printf("(susp %d map %d lk %d cre %d retry %d exec %d eexec %d cl %d) ",
	   rec->specific.user.suspend_ovhd_us,
	   rec->specific.user.map_us,
	   rec->specific.user.lock_us,
	   rec->specific.user.dag_create_us,
	   rec->specific.user.dag_retry_us,
	   rec->specific.user.exec_us,
	   rec->specific.user.exec_engine_us,
	   rec->specific.user.cleanup_us);
  }
  printf("xor %d q %d log %d dw %d tot %d nphys %d\n",
	 rec->xor_us, rec->q_us, rec->plog_us, rec->diskwait_us, rec->total_us, rec->num_phys_ios);
}