/*@@ @file Output.c @date July 6 2003 @author Gabrielle Allen @desc Functions to report the timers @enddesc @@*/ #include #include #include #include #include #include #include #include #include #include #ifdef CCTK_MPI # include #endif /******************************************************************** ********************* Local Data Types *********************** ********************************************************************/ struct timer_stats { char ** restrict names; /* timer names */ CCTK_REAL * restrict secs_avg; /* global average */ CCTK_REAL * restrict secs_min; /* global minimum */ CCTK_REAL * restrict secs_max; /* global maximum */ int ntimers; }; /******************************************************************** ********************* Local Routine Prototypes ********************* ********************************************************************/ static int min(int x, int y); static void Output (CCTK_ARGUMENTS); static void PrintTimes (CCTK_ARGUMENTS); static void OutputAllTimers (CCTK_ARGUMENTS); static void OutputAllTimersTogether (CCTK_ARGUMENTS); static void OutputAllTimersReadable (CCTK_ARGUMENTS); static void PrintTopTimers (CCTK_ARGUMENTS); static int CollectTimerInfo (cGH const * restrict const cctkGH, struct timer_stats * restrict const timers); static char *QuoteForCSV (const char*); static char *QuoteForTSV (const char*); /******************************************************************** ********************* Scheduled Routine Prototypes *************** ********************************************************************/ void TimerReport_OutputEvery(CCTK_ARGUMENTS); void TimerReport_OutputTerminate(CCTK_ARGUMENTS); void TimerReport_Checkpoint(CCTK_ARGUMENTS); /******************************************************************** ********************* Other Routine Prototypes ********************* ********************************************************************/ /******************************************************************** ********************* Local Data ***************************** ********************************************************************/ static const char *const sep = "======================================================================"; /******************************************************************** ******************** External Routines ************************ ********************************************************************/ /*@@ @routine TimerReport_OutputEvery @date 2008-11-12 @author Erik Schnetter @desc Output the timer table periodically @enddesc @@*/ void TimerReport_OutputEvery(CCTK_ARGUMENTS) { DECLARE_CCTK_ARGUMENTS; DECLARE_CCTK_PARAMETERS; if (next || out_at == cctk_iteration || (out_every && cctk_iteration%out_every == 0)) { CCTK_VInfo(CCTK_THORNSTRING, "Timer Report at iteration %d time %g", cctk_iteration, (double)cctk_time); Output(CCTK_PASS_CTOC); if (next) { CCTK_ParameterSet("next", CCTK_THORNSTRING, "no"); } } } /*@@ @routine TimerReport_OutputTerminate @date 2008-11-12 @author Erik Schnetter @desc Output the timer table periodically @enddesc @@*/ void TimerReport_OutputTerminate(CCTK_ARGUMENTS) { DECLARE_CCTK_ARGUMENTS; DECLARE_CCTK_PARAMETERS; CCTK_VInfo(CCTK_THORNSTRING, "Timer Report before terminating at iteration %d time %g", cctk_iteration, (double)cctk_time); Output(CCTK_PASS_CTOC); } /*@@ @routine TimerReport_Checkpoint @date April 10 2004 @author Erik Schnetter @desc Output the timer table if before_checkpoint is set @enddesc @@*/ void TimerReport_Checkpoint(CCTK_ARGUMENTS) { DECLARE_CCTK_ARGUMENTS; DECLARE_CCTK_PARAMETERS; if (before_checkpoint && (checkpoint_every && cctk_iteration%checkpoint_every == 0)) { CCTK_VInfo(CCTK_THORNSTRING, "Timer Report before checkpointing at iteration %d, time %g", cctk_iteration, (double)cctk_time); Output(CCTK_PASS_CTOC); } } /******************************************************************** ******************** Internal Routines ************************ ********************************************************************/ static int min(int x, int y) { return x 0) { PrintTopTimers(CCTK_PASS_CTOC); } } static void PrintTimes (CCTK_ARGUMENTS) { DECLARE_CCTK_ARGUMENTS; DECLARE_CCTK_PARAMETERS; int myproc; FILE *file; char *filename; const int filename_length = 10000; const char *flags; static int first_time = 1; if (CCTK_EQUALS (out_filename, "")) { /* Print to stdout. */ CCTK_SchedulePrintTimes(NULL); } else { /* Print to a file. */ myproc = CCTK_MyProc(cctkGH); filename = malloc(filename_length); Util_snprintf(filename, filename_length, "%s/%s.%06d.txt", out_dir, out_filename, myproc); /* truncate or append */ flags = first_time && IO_TruncateOutputFiles(cctkGH) ? "w" : "a"; first_time = 0; file = fopen(filename, flags); if (file) { /* Print the schedule to the file */ fprintf(file, "Timer Report at iteration %d time %g:\n\n", cctk_iteration, (double) cctk_time); CCTK_SchedulePrintTimesToFile(NULL, file); fprintf(file, "\n********************************************************************************\n"); fclose(file); } else { CCTK_VWarn(1, __LINE__, __FILE__, CCTK_THORNSTRING, "Could not open timer report output file \"%s\"", filename); } 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; int i; assert(ntimers >= 0); Util_asprintf(&filename, "%s/%s.%06d.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 simulation time\n"); for (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%.15g", cctk_iteration, (double)cctk_time); for (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 { const char *name = CCTK_TimerName(i); if (name == NULL) name = "(null)"; CCTK_VWarn(1, __LINE__, __FILE__, CCTK_THORNSTRING, "Clock \"%s\" not found for timer #%d \"%s\"", all_timers_clock, i, name); timer_secs = -1; } } fprintf(file, "\t%.15g", timer_secs); } 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; } static void OutputAllTimersTogether (CCTK_ARGUMENTS) { DECLARE_CCTK_ARGUMENTS; DECLARE_CCTK_PARAMETERS; struct timer_stats timers; if (!CollectTimerInfo (cctkGH, &timers)) return; if (CCTK_MyProc(cctkGH) == 0) { static int first_time = 1; static int last_ntimers = -1; char *filename, *filename_csv, *filename_tsv; Util_asprintf(&filename, "%s/%s.txt", out_dir, "AllTimers"); Util_asprintf(&filename_csv, "%s/%s.csv", out_dir, "AllTimers"); Util_asprintf(&filename_tsv, "%s/%s.tsv", out_dir, "AllTimers"); /* truncate or append */ const char * const flags = first_time && IO_TruncateOutputFiles(cctkGH) ? "w" : "a"; FILE * const file = fopen(filename, flags); FILE * const file_csv = fopen(filename_csv, flags); FILE * const file_tsv = fopen(filename_tsv, flags); if (file) { if (first_time) { fprintf(file, "# Clock %s\n", all_timers_clock); fprintf(file, "# Unit seconds\n"); char *const all_timers_clock_csv = QuoteForCSV(all_timers_clock); fprintf(file_csv, "\"Clock %s\",", all_timers_clock_csv); fprintf(file_csv, "\"Unit seconds\"\n"); free (all_timers_clock_csv); char *const all_timers_clock_tsv = QuoteForTSV(all_timers_clock); fprintf(file_tsv, "Clock %s\t", all_timers_clock_tsv); fprintf(file_tsv, "Unit seconds\n"); free (all_timers_clock_tsv); } /* 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 * method here works as long as timers are never deleted. */ if (last_ntimers != timers.ntimers) { fprintf(file, "# Column 1 iteration\n"); fprintf(file, "# Column 2 simulation time\n"); fprintf(file, "# For all following columns:\n"); fprintf(file, "# Column 3n average of all processes\n"); fprintf(file, "# Column 3n+1 minimum of all processes\n"); fprintf(file, "# Column 3n+2 maximum of all processes\n"); fprintf(file_csv, "\"iteration\","); fprintf(file_csv, "\"simulation time\""); fprintf(file_tsv, "iteration\t"); fprintf(file_tsv, "simulation time"); for (int i = 0; i < timers.ntimers; i++) { const char * const name = timers.names[i]; fprintf(file, "# Column %d %s\n", 3*i+3, name ? name : ""); char *const name_csv = QuoteForCSV(name ? name : ""); fprintf(file_csv, ",\"%s (average)\",\"%s (minimum)\",\"%s (maximum)\"", name_csv, name_csv, name_csv); free (name_csv); char *const name_tsv = QuoteForTSV(name ? name : ""); fprintf(file_tsv, "\t%s (average)\t%s (minimum)\t%s (maximum)", name_tsv, name_tsv, name_tsv); free (name_tsv); } fprintf(file_csv, "\n"); fprintf(file_tsv, "\n"); } fprintf(file, "%d\t%.15g", cctk_iteration, (double)cctk_time); fprintf(file_csv, "%d,%.15g", cctk_iteration, (double)cctk_time); fprintf(file_tsv, "%d\t%.15g", cctk_iteration, (double)cctk_time); for (int i = 0; i < timers.ntimers; i++) { fprintf(file, "\t%.15g %.15g %.15g", (double)timers.secs_avg[i], (double)timers.secs_min[i], (double)timers.secs_max[i]); fprintf(file_csv, ",%.15g,%.15g,%.15g", (double)timers.secs_avg[i], (double)timers.secs_min[i], (double)timers.secs_max[i]); fprintf(file_tsv, "\t%.15g\t%.15g\t%.15g", (double)timers.secs_avg[i], (double)timers.secs_min[i], (double)timers.secs_max[i]); } fprintf(file, "\n"); fprintf(file_csv, "\n"); fprintf(file_tsv, "\n"); fclose(file); fclose(file_csv); fclose(file_tsv); } else { CCTK_VWarn(1, __LINE__, __FILE__, CCTK_THORNSTRING, "Could not open timer report output files \"%s\" and \"%s\"", filename, filename_csv); } free(filename); free(filename_csv); free(filename_tsv); first_time = 0; last_ntimers = timers.ntimers; } /* if root processor */ for (int n=0; nsecs_avg[idx2] - compare_timers->secs_avg[idx1]; if (d > 0) return +1; else if (d < 0) return -1; else return 0; } static void PrintTopTimers (CCTK_ARGUMENTS) { DECLARE_CCTK_ARGUMENTS; DECLARE_CCTK_PARAMETERS; /* Collect timing information from all processes */ struct timer_stats timers; if (! CollectTimerInfo (cctkGH, &timers)) { return; } /* Output the times only on the root process (because they are not reduced onto the other processes anyway) */ if (CCTK_MyProc(cctkGH) != 0) { return; } /* Sort timers (by average) */ int idx[timers.ntimers]; for (int i=0; i total_idx); CCTK_REAL const max_time = timers.secs_max[idx[total_idx]]; int const digits = floor(log10(max_time) + 1.0e-4) + 1; /* Output timing results */ for (int i=0; intimers = 0; timers->names = NULL; timers->secs_avg = NULL; timers->secs_min = NULL; timers->secs_max = NULL; free(all_timernames); free(my_timernames); return 1; } /* Construct global list of timers: sort, then unique */ /* TODO: sort the processes' timers separately (and in parallel), then merge them */ int sort_index[total_ntimers]; for (int i=0; i 0) { unique_timers = 1; /* first timer is always unique */ for (int i=1; intimers = unique_timers; assert(timers->ntimers >= 0); timers->names = malloc(timers->ntimers * sizeof *timers->names ); timers->secs_avg = malloc(timers->ntimers * sizeof *timers->secs_avg); timers->secs_min = malloc(timers->ntimers * sizeof *timers->secs_min); timers->secs_max = malloc(timers->ntimers * sizeof *timers->secs_max); assert(timers->ntimers==0 || timers->names ); assert(timers->ntimers==0 || timers->secs_avg); assert(timers->ntimers==0 || timers->secs_min); assert(timers->ntimers==0 || timers->secs_max); for (int n=0; nnames[n] = strdup(all_timernames[sort_index[n]]); } /* Reduce timer values */ for (int n=0; nntimers; ++n) { double count = 0.0; double sum = 0.0; double minval = HUGE_VAL; double maxval = 0.0; /* Reduce over all processes */ for (int p=0; pnames[n], all_timernames[name_offset+i]) == 0) break; } if (i < all_ntimers[p]) { /* Found the timer */ double const value = all_timervalues[value_displacements[p]+i]; count += 1; sum += value; minval = fmin(minval, value); maxval = fmax(maxval, value); } else { /* Timer does not exist on this process -- ignore */ } } if (count == 0) { /* Special case to make result look nicer */ timers->secs_avg[n] = -1; /* instead of nan */ timers->secs_min[n] = -1; /* instead of infinity */ timers->secs_max[n] = maxval; /* zero */ } else { timers->secs_avg[n] = sum / count; timers->secs_min[n] = minval; timers->secs_max[n] = maxval; } } free(all_timernames); free(my_timernames); return 1; } /* Quote a string so that it can be output as CSV entry. Return a newly allocated string that must be freed by the caller. */ static char *QuoteForCSV (const char *const string) { const int len = strlen(string); /* Allocate sufficient space */ char *const res = malloc(2*len+3); char *q = res; /* Begin with a quote */ *q++ = '"'; /* Copy string into result, quoting as necessary */ for (const char *p = string; *p; ++p) { /* Quote all quote characters by doubling them (so <"hi" there> becomes <""hi"" there> */ if (*p == '"') *q++ = '"'; *q++ = *p; } /* End with a quote */ *q++ = '"'; *q = '\0'; return res; } /* Quote a string so that it can be output as TSV entry. Return a newly allocated string that must be freed by the caller. */ static char *QuoteForTSV (const char *const string) { const int len = strlen(string); /* Allocate sufficient space */ char *const res = malloc(len+1); char *q = res; /* Copy string into result, replacing tabs as necessary */ for (const char *p = string; *p; ++p) { if (*p == '\t') { *q++ = ' '; } else { *q++ = *p; } } *q = '\0'; return res; }