esmc_timer.c

CCSM Research Tools: Community Atmosphere Model (CAM)

	  break;
	
	default:
	  break;

	}
      }
#endif
      ++nevent;
    }
  }

#ifdef HAVE_PCL

  if (ncounter > 0) {
    int thread;         /* thread number */

    nbytes = numthreads * sizeof (PCL_DESCR_TYPE);
    if ((descr = (PCL_DESCR_TYPE *) malloc (nbytes)) == 0)
      return t_error ("malloc failure: %d items\n", numthreads);

    /*
    ** PCLinit must be called on a per-thread basis.  Therefore must make the call here
    ** rather than in t_initialize.  null timer list flags not initialized.
    ** Also, the critical section is necessary because PCLstart appears not to be
    ** thread-safe.
    */

#pragma omp parallel for
    
    for (thread = 0; thread < numthreads; thread++) {

      unsigned int flags;           /* mode flags needed by PCL */

#pragma omp critical

      {
	if ((ret = PCLinit (&descr[thread])) != PCL_SUCCESS)
	  return t_error ("unable to allocate PCL handle for thread %d. %s\n",
			  thread, t_pclstr (ret));

	/*
	** Always count user mode only
	*/
      
	flags = PCL_MODE_USER;

	if ((ret = PCLquery (descr[thread], counter_list, ncounter, flags)) != PCL_SUCCESS)
	  return t_error ("Bad return from PCLquery thread %d: %s\n", thread, t_pclstr (ret));

	if ((ret = PCLstart (descr[thread], counter_list, ncounter, flags)) != PCL_SUCCESS)
	  return t_error ("PCLstart failed thread=%d: %s\n", thread, t_pclstr (ret));
      }
    }
  }
#endif
  t_initialized = true;
#endif

  return 0;
}


static char *t_pclstr (int code)
{

#if ( defined DISABLE_TIMERS )
  return "";
#endif

#ifdef HAVE_PCL
  switch (code) {

  case PCL_SUCCESS: 
    return "Success";
    
  case PCL_NOT_SUPPORTED:
    return "Event not supported";
    
  case PCL_TOO_MANY_EVENTS:
    return "Too many events";
    
  case PCL_TOO_MANY_NESTINGS:
    return "More nesting levels than allowed";
    
  case PCL_ILL_NESTING:
    return "Bad nesting";
    
  case PCL_ILL_EVENT:
    return "Illegal event identifier";
    
  case PCL_MODE_NOT_SUPPORTED:
    return "Mode not supported";
    
  case PCL_FAILURE:
    return "Failure for unspecified reason";
    
  default:
    return "Unknown error code";
    
  }
#endif
    return "Unknown error code";
}

      
  


/*
** t_pr: print stats for all known timers to a file
**
** Input arguments:
**   procid: Designed for MPI jobs to give a unique output file name, 
**     normally the MPI logical process id.
**
** Return value: 0 (success) or -1 (failure)
*/

static int mhz;            /* processor clock rate (from pcl library) */

static int t_pr (ESMC_Log log, char *name, int procid)
{
  char outfile[11];        /* name of output file: timing.xxx */
			   
  int indent;              /* index over number indentation levels */
  int thread;              /* thread index */
  int ilstart;             /* index over indentation level */
  int n;

  double gttdcost;         /* cost of a single gettimeofday call */
  double deltat;           /* time difference between 2 calls to gettimeofday */
  struct Stats stats;      /* per timer stats */
  struct Stats threadsum;  /* timer sum over threads */
			   
  struct node *ptr, *tptr; /* linked list pointers */
			   
  FILE *fp;                /* output file pointer */

  struct timeval tp1, tp2; /* input to gettimeofday() */
  struct tms buf;          /* input to times() */

#if ( defined DISABLE_TIMERS )
  return 0;
#endif

  if ( ! t_initialized)
    return t_error ("t_pr: t_initialize has not been called\n");

  /*
  ** Only allow the master thread to print stats
  */

  if (get_thread_num () != 0)
    return 0;

  /*
  ** Estimate wallclock timer overhead: 4 times the cost of a call to gettimeofday
  ** (since each start/stop pair involves 4 such calls).
  */

  gettimeofday (&tp1, NULL);
  gettimeofday (&tp2, NULL);
  gttdcost = 1.e6*(tp2.tv_sec  - tp1.tv_sec) + (tp2.tv_usec - tp1.tv_usec);

  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Wallclock timer cost est.: %8.3f usec per start/stop pair\n", 
	      gttdcost*4.);

  /*
  ** CPU cost estimate: 2 times the cost of a call to times().  Subtract the
  ** cost of a single gettimeofday call to improve the estimate.
  */

  if (usrsysenabled) {

    gettimeofday (&tp1, NULL);
    (void) times (&buf);
    gettimeofday (&tp2, NULL);

    deltat = 1.e6*(tp2.tv_sec  - tp1.tv_sec) + (tp2.tv_usec - tp1.tv_usec);
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "CPU timer cost est.:       %8.3f usec per start/stop pair\n", 
		2.*deltat - gttdcost);
  }
    
  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "CPU accumulation interval is %g seconds\n",
           1./(float) ticks_per_sec);

#ifdef HAVE_PCL
  mhz = PCL_determine_mhz_rate();
  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Clock speed is %d MHz\n", mhz);
#endif

  for (thread = 0; thread < numthreads; thread++) {

    /*
    ** Only print heading for threads that have 1 or more items to report
    */

    if (timers[thread] == NULL) continue;
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "\nStats for thread %d:\n", thread);

    print_header (log, max_indent_level[thread]);

    for (ptr = timers[thread]; ptr != NULL; ptr = ptr->next) {
      if (ptr->onflg) {

	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Timer %s was not off.  No stats will be printed\n",
		 ptr->name);

      } else {

	fillstats (&stats, ptr);

	/*
	** Print stats indented.  If indent_level = AMBIGUOUS (a negative 
	** number) the name will be printed with no indentation.
	*/

	for (indent = 0; indent < ptr->indent_level; indent++)
	  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "  ");
	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%-15s", ptr->name);

	/*
	** If indent_level = AMBIGUOUS (a negative number) we want to loop 
	** from 0
	*/

	ilstart = MAX (0, ptr->indent_level);
	for (indent = ilstart; indent < max_indent_level[thread]; indent++)
	  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "  ");

	print_stats_line (log, &stats);
      }
    }

    if (usrsysenabled || wallenabled)
      ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "\nTIMER OVERHEAD (wallclock seconds) = %12.6f\n", 
	       overhead[thread]);

    if (pcl_cyclesenabled)
      ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "TIMER OVERHEAD (cycles) = %12.6e\n", 
	       (double) overhead_pcl[thread]);
  }

  /*
  ** Print a vertical summary if data exist for more than 1 thread.  The "2"
  ** passed to print_header is so we'll get an extra 4 spaces of indentation
  ** due to the thread number appended to the timer name.
  */

  if (numthreads > 0 && timers[1] != NULL) {
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "\nSame stats sorted by timer with thread number appended:\n");
    print_header (log, 2);

    /*
    ** Print stats for slave threads that match master
    */

    for (ptr = timers[0]; ptr != NULL; ptr = ptr->next) {

      char name[20];
      Boolean found = false;

      /*
      ** Don't bother printing summation stats when only the master thread
      ** invoked the timer
      */

      for (thread = 1; thread < numthreads; thread++)
	for (tptr = timers[thread]; tptr != NULL; tptr = tptr->next) {
	  if (STRMATCH (ptr->name, tptr->name))
	    found = true;
	}
      if ( ! found) continue;

      /*
      ** Initialize stats which sum over threads
      */

      memset (&threadsum, 0, sizeof (threadsum));

      if ( ! ptr->onflg) {
	fillstats (&stats, ptr);
	strcpy (name, ptr->name);
	strcat (name, ".0");
	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%-19s", name);
	print_stats_line (log, &stats);
	threadsum = stats;
      }

      /*
      ** loop over slave threads, printing stats for each and accumulating
      ** sum over threads when the name matches
      */

      for (thread = 1; thread < numthreads; thread++) {
	for (tptr = timers[thread]; tptr != NULL; tptr = tptr->next) {
	  if (STRMATCH (ptr->name, tptr->name)) {
	    if ( ! tptr->onflg) {
	      char num[5];

	      fillstats (&stats, tptr);
	      strcpy (name, tptr->name);
	      sprintf (num, ".%-3d", thread);
	      strcat (name, num);
	      ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%-19s", name);
	      print_stats_line (log, &stats);

	      threadsum.usr      += stats.usr;
	      threadsum.sys      += stats.sys;
	      threadsum.usrsys   += stats.usrsys;
	      threadsum.elapse   += stats.elapse;
	      threadsum.max_wtime = MAX (threadsum.max_wtime, stats.max_wtime);
	      threadsum.min_wtime = MIN (threadsum.min_wtime, stats.min_wtime);
	      threadsum.count    += stats.count;

	      for (n = 0; n < ncounter; n++)
		threadsum.pcl_result[n] += stats.pcl_result[n];
	    }
	    break; /* Go to the next thread */
	  }        /* if (STRMATCH (ptr->name, tptr->name) */
	}          /* loop thru linked list of timers for this thread */
      }            /* loop over slave threads */

      strcpy (name, ptr->name);
      strcat (name, ".sum");
      ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%-19s", name);
      print_stats_line (log, &threadsum);
      ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "\n");

    } /* loop through master timers */

    for (thread = 0; thread < max_seen_thread + 1; thread++) {
      if (usrsysenabled || wallenabled)
	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "OVERHEAD.%-3d (wallclock seconds) = %12.6f\n", 
		 thread, overhead[thread]);

      if (pcl_cyclesenabled)
	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "OVERHEAD.%-3d (cycles) = %12.6e\n", 
		 thread, (double) overhead_pcl[thread]);
    }

  } /* if (numthreads > 0 && timers[1] != NULL */

  return 0;
}

static void fillstats(struct Stats *stats, struct node *ptr)
{
  int n;

  stats->usr       = ptr->accum_utime / (float) ticks_per_sec;
  stats->sys       = ptr->accum_stime / (float) ticks_per_sec;
  stats->usrsys    = stats->usr + stats->sys;
  stats->elapse    = ptr->accum_wtime_sec + 1.e-6 * ptr->accum_wtime_usec;
  stats->max_wtime = ptr->max_wtime;
  stats->min_wtime = ptr->min_wtime;
  stats->count     = ptr->count;

  for (n = 0; n < ncounter; n++)
    stats->pcl_result[n] = ptr->accum_pcl_result[n];
}

static void print_stats_line(ESMC_Log log, struct Stats *stats)
{
  int index;
  int n;
  long long cycles;
  long long instr;
  long long flops;
  long long loadstore;
  long long l2cache;
  long long jump;

  float mflops;
  float ipc;
  float memfp;

  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%9ld ", stats->count);

  if (usrsysenabled)
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%9.3f %9.3f %9.3f ", stats->usr, stats->sys, stats->usrsys);

  if (wallenabled)
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%9.3f %9.3f %9.3f ", stats->elapse, stats->max_wtime, 
	     stats->min_wtime);
  
  for (n = 0; n < nevent; n++) {
    if (event[n]->name > pcl_start && event[n]->name < pcl_end) {
      index = event[n]->index;
      if (stats->pcl_result[index] > 1.e6)
	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%9.3e ", (double) stats->pcl_result[index]);
      else
	ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "%9ld ", (long) stats->pcl_result[index]);
    }
  }

  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "\n");
}

static void print_header (ESMC_Log log, int indent_level)
{
  int i;
  int n;

  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Name           ");
  for (i = 0; i < indent_level; i++)
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "  ");
  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Called    ");

  if (usrsysenabled)
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Usr       Sys       Usr+Sys   ");

  if (wallenabled)
    ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "Wallclock Max       Min       ");

  for (n = 0; n < nevent; n++)
    if (event[n]->name > pcl_start && event[n]->name <= pcl_end)
      ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, event[n]->string);

  ESMC_LogPrint(log, ESMC_LOGLEVEL_TIMER, "\n");
}


/*
** t_reset: reset all known timers to 0
**
** Return value: 0 (success) or -1 (failure)
*/

static int t_reset ()
{
  int n;             /* index over threads */
  struct node *ptr;  /* linked list index */

#if ( ! defined DISABLE_TIMERS )
  if ( ! t_initialized)
    return t_error ("t_reset: t_initialize has not been called\n");

  /*
  ** Only allow the master thread to reset timers
  */

  if (get_thread_num () != 0)
    return 0;

  for (n = 0; n < numthreads; n++) {
    for (ptr = timers[n]; ptr != NULL; ptr = ptr->next) {
      memset (timers[n], 0, sizeof (struct node));
      printf ("Reset accumulators for timer %s to zero\n", ptr->name);
    }
  }
#endif
  return 0;
}



/*
** t_setoption: set option value to true or false.
**
** Input arguments:
**   option: option to be set
**   val:    value to which option should be set
**
** Return value: 0 (success) or -1 (failure)
*/

static int t_setoption (OptionName option, Boolean val)
{
  int n;

#if ( defined DISABLE_TIMERS )
  return 0;
#endif

  if (t_initialized)
    return (t_error ("t_setoption: Options must be set BEFORE t_initialize\n"));

  for (n = 0; n < npossible; n++) {
    if (possible_event[n].name == option) {
      possible_event[n].enabled = val;

      if (val)
	printf ("t_setoption: option enabled:  %s\n", possible_event[n].string);
      else
	printf ("t_setoption: option disabled: %s\n", possible_event[n].string);

      return 0;
    }
  }

  return (t_error ("t_setoption: Option with enum index %d not available\n",
		     option));
}

/*
** t_stamp: Compute timestamp of usr, sys, and wallclock time (seconds)
**
** Output arguments:
**   wall: wallclock
**   usr:  user time
**   sys:  system time
**
** Return value: 0 (success) or -1 (failure)
*/

static int t_stamp (double *wall, double *usr, double *sys)
{
  struct timeval tp;         /* argument to gettimeofday */
  struct tms buf;            /* argument to times */

  *usr = 0;
  *sys = 0;

  if (times (&buf) == -1)