Add two features to TimerReport:

- Output all timers periodically to a file, in a format that is easy
  to parse

- Output the top N timers periodically to screen


git-svn-id: http://svn.cactuscode.org/arrangements/CactusUtils/TimerReport/trunk@20 d0051148-8e13-4bef-be1d-f6c572c85f9f

2 files changed, 203 insertions, 0 deletions

diff --git a/param.ccl b/param.ccl
index 3a31f7d..211f5ce 100644
--- a/param.ccl
+++ b/param.ccl
@@ -29,6 +29,21 @@ BOOLEAN next "On next iteration" STEERABLE=ALWAYS
 {
 } "no"
 
+BOOLEAN output_all_timers "Output a separate file containing all the Cactus timers" STEERABLE=ALWAYS
+{
+} "no"
+
+STRING all_timers_clock "Which clock to use for the all timers output" STEERABLE=ALWAYS
+{
+  ".*"   :: "any clock name allowed"
+} "gettimeofday"
+
+INT n_top_timers "How many timers to include in the top timer report" STEERABLE=ALWAYS
+{
+  0   :: "Do not print the report"
+  1:* :: "Any number of timers"
+} 0
+
 shares: IO
 
 USES STRING out_dir
diff --git a/src/Output.c b/src/Output.c
index 39fe709..ccf226e 100644
--- a/src/Output.c
+++ b/src/Output.c
@@ -10,6 +10,7 @@
 
 #include <stdio.h>
 #include <stdlib.h>
+#include <assert.h>
 
 #include "cctk.h"
 #include "cctk_Parameters.h"
@@ -32,6 +33,8 @@ CCTK_FILEVERSION(CactusUtils_TimerReport_Output_c);
  ********************************************************************/
 
 static void PrintTimes (CCTK_ARGUMENTS);
+static void OutputAllTimers (CCTK_ARGUMENTS);
+static void PrintTopTimers (CCTK_ARGUMENTS);
 
 /********************************************************************
  *********************  Scheduled Routine Prototypes  ***************
@@ -75,6 +78,12 @@ void TimerReport_Output(CCTK_ARGUMENTS)
                cctk_iteration, (double)cctk_time);
     PrintTimes(CCTK_PASS_CTOC);
 
+    if (output_all_timers)
+      OutputAllTimers(CCTK_PASS_CTOC);
+
+    if (n_top_timers > 0)
+      PrintTopTimers(CCTK_PASS_CTOC);
+
     if (next)
     {
       CCTK_ParameterSet("next", CCTK_THORNSTRING, "no");
@@ -159,3 +168,182 @@ static void PrintTimes (CCTK_ARGUMENTS)
     free(filename);
   }
 }
+
+static void OutputAllTimers (CCTK_ARGUMENTS)
+{
+  DECLARE_CCTK_ARGUMENTS;
+  DECLARE_CCTK_PARAMETERS;
+
+  FILE *file;
+  char *filename;
+  const char *flags;
+  static int first_time = 1;
+  int ntimers = CCTK_NumTimers();
+  cTimerData  *td = CCTK_TimerCreateData();
+  double timer_secs = -1;
+  static int last_ntimers = -1;
+
+  assert(ntimers >= 0);
+
+  Util_asprintf(&filename, "%s/%s.%04d.txt", 
+                out_dir, "AllTimers", CCTK_MyProc(cctkGH));
+
+  /* truncate or append */
+  flags = first_time && IO_TruncateOutputFiles(cctkGH) ? "w" : "a";
+
+  file = fopen(filename, flags);
+  if (file)
+  {
+    if (first_time)
+    {
+      fprintf(file, "# Clock %s\n", all_timers_clock);
+      fprintf(file, "# Unit seconds\n");
+    }
+    /* If the number of timers has changed, output the header
+     * containing the timer names again.  It would be better to track
+     * creation and deletion of timers in the flesh, but this always
+     * works as long as timers are never deleted. */
+    if (first_time || last_ntimers != ntimers)
+    {
+      fprintf(file, "# Column 1 iteration\n");
+      fprintf(file, "# Column 2 time\n");
+      for (int i = 0; i < ntimers; i++)
+      {
+        const char *name = CCTK_TimerName(i);
+          
+        if (name == NULL)
+          name = "";
+
+        fprintf(file, "# Column %d %s\n", i+3, name);
+      }
+    }
+
+    fprintf(file, "%d\t%f\t", cctk_iteration, cctk_time);
+
+    for (int i = 0; i < ntimers; i++)
+    {
+      CCTK_TimerI(i, td);
+        
+      {
+        const cTimerVal  *tv = CCTK_GetClockValue(all_timers_clock, td);
+
+        if (tv != NULL)
+        {
+          timer_secs = CCTK_TimerClockSeconds(tv);
+        }
+        else
+        {
+          CCTK_VWarn(0, __LINE__, __FILE__, CCTK_THORNSTRING,
+                     "Clock \"%s\" not found", all_timers_clock);
+        }
+      }
+        
+      fprintf(file, "%.15g", timer_secs);
+      if (i != ntimers - 1)
+        fprintf(file, "\t");
+    }
+    fprintf(file, "\n");
+    fclose(file);
+  }
+  else
+  {
+    CCTK_VWarn(1, __LINE__, __FILE__, CCTK_THORNSTRING,
+               "Could not open timer report output file \"%s\"", filename);
+  }
+  free(filename);
+  CCTK_TimerDestroyData(td);
+  first_time = 0;
+  last_ntimers = ntimers;
+  return;
+}
+
+typedef struct
+{
+  int timer;
+  double t;
+} timer_pair;
+
+static int compare(const void * a, const void * b)
+{
+  timer_pair *t1 = (timer_pair *) a;
+  timer_pair *t2 = (timer_pair *) b;
+
+  double d = t2->t - t1->t;
+
+  if (d > 0)
+    return 1;
+  else if (d == 0)
+    return 0;
+  else return -1;
+}
+
+
+static void PrintTopTimers (CCTK_ARGUMENTS)
+{
+  DECLARE_CCTK_ARGUMENTS;
+  DECLARE_CCTK_PARAMETERS;
+
+  int ntimers = CCTK_NumTimers();
+  cTimerData  *td = CCTK_TimerCreateData();
+  double timer_secs = -1;
+  timer_pair   timers[ntimers];
+  int topn = n_top_timers;
+  double total = 0;
+
+  char *sep = "======================================================================";
+
+  assert(ntimers >= 0);
+  for (int i = 0; i < ntimers; i++)
+  {
+    CCTK_TimerI(i, td);
+        
+    {
+      const cTimerVal  *tv = CCTK_GetClockValue(all_timers_clock, td);
+
+      if (tv != NULL)
+      {
+        timer_secs = CCTK_TimerClockSeconds(tv);
+      }
+      else
+      {
+        CCTK_VWarn(0, __LINE__, __FILE__, CCTK_THORNSTRING,
+                   "Clock \"%s\" not found", all_timers_clock);
+      }
+    }
+
+    timers[i].timer = i;
+    timers[i].t = timer_secs;
+  }
+
+  qsort(timers, ntimers, sizeof(timer_pair), compare);
+
+  CCTK_TimerDestroyData(td);
+
+  CCTK_VInfo(CCTK_THORNSTRING,
+             "Top timers at iteration %d time %g",
+             cctk_iteration, (double)cctk_time);
+
+  printf("%s\n", sep);
+  printf("%%      Time/s   Timer (%s)\n", all_timers_clock);
+  printf("%s\n", sep);
+
+  /* This should be the "CCTK total time" timer */
+  total = timers[0].t;
+
+  for (int i = 0; i < (ntimers >= topn ? topn : ntimers) ; i++)
+  {
+    double percent = 100.0 * timers[i].t / total;
+
+    char percent_string[10];
+    char time_string[10];
+
+    snprintf(percent_string, 6, "%.5f", percent);
+    snprintf(time_string, 8, "%.7f", timers[i].t);
+
+    printf("%s  %s  %s\n", percent_string, time_string, 
+           CCTK_TimerName(timers[i].timer));
+  }
+  printf("%s\n", sep);
+
+  return;
+}