static void avg(char *prog, char *file) { rusage_t joule; char cmd[1024]; sprintf(cmd, "luac -o %s.luac %s", file, file); system(cmd); sprintf(cmd, "%s.luac", file); char **argv; char *joule_argv[] = {prog, "-c", cmd, NULL}; char *lua_argv[] = {prog, cmd, NULL}; argv = strcmp(prog, "lua") == 0 ? lua_argv : joule_argv; long total, user, system, mem; total = user = system = mem = 0; int i; for (i = 0; i < NTIMES; i++) { systime(argv, &joule); total += USECS(&joule.ru_utime) + USECS(&joule.ru_stime); user += USECS(&joule.ru_utime); system += USECS(&joule.ru_stime); mem += joule.ru_maxrss; } unlink(cmd); printf("%27s,", file); printf("%10ld,%10ld,%10ld,%10ld\n", total/NTIMES, user/NTIMES, system/NTIMES, mem/NTIMES); }
/*! * @brief Compares two timers. * * This function indicates whether time 1 is less than time 2. * * @param time1 Time to compare * @param time2 Time that time1 will be compared against. * * @return 1 if time1 < time2, 0 otherwise. */ static int less_than(struct timeval * time1, struct timeval * time2) { if(USECS(*time1) < USECS(*time2)) { return 1; } return 0; }
/*! * @brief Compares two timers. * * This function indicates whether time 1 is greater than time 2. * * @param time1 Time to compare * @param time2 Time that time1 will be compared against. * * @return 1 if time1 > time2, 0 otherwise. */ static int greater_than(struct timeval * time1, struct timeval * time2) { if(USECS(*time1) > USECS(*time2)) { return 1; } return 0; }
/*! * @brief Finds the average. * * Given a total time andf the number of times summed, this finds the average * * @param total Total time to be averaged * @param num_times Number of times summed in total. * @param average The average time will be returned here. * * @return 0 if successful */ static void average(struct timeval * total, short num_times, struct timeval * average) { long average_usecs; /* Find the average. */ average_usecs = USECS(*total) / num_times; average->tv_sec = average_usecs / CARRY_USEC; average->tv_usec = average_usecs % CARRY_USEC; }
/*! * @brief Displays rate info about the timer. * * This function prints a load of information about the rate of a timer's start times * to the console. * * @param timer The timer for which info should be shown. * @param show_all After the average, etc. show all periods, 1 per line. Set false if * only a summary of the times is needed. * * @return 0 if successful */ void timing_print_rate_info(TIMING_TIMER_T * timer, bool show_all) { int i; struct timeval lowest_elapsed_time = {100000000, 0}; int lowest_elapsed_time_index = 0; struct timeval highest_elapsed_time = {0, 0}; int highest_elapsed_time_index = 0; int rate; unsigned long std_dev = 0; int elapsed_usec; int average_usec; struct timeval elapsed_time = {0, 0}; struct timeval total_elapsed_time = {0, 0}; struct timeval average_elapsed_time = {0, 0}; struct timeval delta; /* Since we are looking at the start times for rate information, we need two times stored * for one period, three times for two periods, etc. */ int num_periods = timer->num_times_recorded - 1; /* There's no point in continuing if there is insufficient information available * to show period information. */ if(num_periods <= 0) { tracemsg(_a("Rate info: %d timer start/stops is insufficient for rate analysis."), timer->num_times_recorded); return; } tracemsg(_a("Rate info: number of periods captured: %d"), num_periods); /* Go figure out some info about the timers captured. */ for(i = 0; i < num_periods; i++) { /* Get elapsed_time between the two start times. */ subtract(&(timer->times[i].start_time), &(timer->times[i+1].start_time), &elapsed_time); /* Check elapsed time against highest. */ if(greater_than(&elapsed_time, &highest_elapsed_time)) { highest_elapsed_time.tv_sec = elapsed_time.tv_sec; highest_elapsed_time.tv_usec = elapsed_time.tv_usec; highest_elapsed_time_index = i; } /* Check elapsed time against lowest. */ if(less_than(&elapsed_time, &lowest_elapsed_time)) { lowest_elapsed_time.tv_sec = elapsed_time.tv_sec; lowest_elapsed_time.tv_usec = elapsed_time.tv_usec; lowest_elapsed_time_index = i; } /* Add this elapsed time to total. */ add(&elapsed_time, &total_elapsed_time, &total_elapsed_time); if(false) { tracemsg(_a(" result %4d: elapsed time %2lds, %6ld usec"), i, elapsed_time.tv_sec, elapsed_time.tv_usec); } } /* Figure out the average elapsed time. */ average(&total_elapsed_time, timer->num_times_recorded, &average_elapsed_time); rate = rate_per_sec(&average_elapsed_time); tracemsg(_a(" Average period %2lds, %6ld usec (%d/sec)"), average_elapsed_time.tv_sec, average_elapsed_time.tv_usec, rate); /* Figure out standard deviation for the set of periods. */ average_usec = USECS(average_elapsed_time); for(i = 0; i < num_periods; i++) { /* Get elapsed_time between the two start times. */ subtract(&(timer->times[i].start_time), &(timer->times[i+1].start_time), &elapsed_time); elapsed_usec = USECS(elapsed_time); std_dev += ((elapsed_usec - average_usec) * (elapsed_usec - average_usec)); } std_dev = std_dev / i; /* Rounding error shouldn't matter too much.*/ std_dev = square_root(std_dev); tracemsg(_a(" Approx std dev %6ld usec"), std_dev); /* For highest time recorded, figure out delta between this and average. */ subtract(&average_elapsed_time, &highest_elapsed_time, &delta); rate = rate_per_sec(&highest_elapsed_time); tracemsg(_a(" Highest period %2lds, %6ld usec (%3d/sec, delta from avg %lds, %6ld us, result %d)"), highest_elapsed_time.tv_sec, highest_elapsed_time.tv_usec, rate, delta.tv_sec, delta.tv_usec, highest_elapsed_time_index); /* Same for lowest. */ subtract(&lowest_elapsed_time, &average_elapsed_time, &delta); rate = rate_per_sec(&lowest_elapsed_time); tracemsg(_a(" Lowest period %2lds, %6ld usec (%3d/sec, delta from avg %lds, %6ld us, result %d)"), lowest_elapsed_time.tv_sec, lowest_elapsed_time.tv_usec, rate, delta.tv_sec, delta.tv_usec, lowest_elapsed_time_index); /* If told to show everything, dump all of the values to text in units of microseconds. * Put commas before and after each value to make this easier to import into excel or * whatever as CSV as there's some sort of timestamp prepended to every printk these days... */ if(show_all) { tracemsg(_a("")); tracemsg(_a(" All periods recorded (usecs):")); for(i = 0; i < num_periods; i++) { subtract(&(timer->times[i].start_time), &(timer->times[i+1].start_time), &elapsed_time); tracemsg(",%ld,\n", USECS(elapsed_time)); } } } /* End of rate info. */
/*! * @brief Displays info about the timer. * * This function prints a load of information about the captured timing information * to the console. * * @param timer The timer for which info should be shown. * @param show_all After the average, etc. show all elapsed times, 1 per line. * Set false if only a summary of the times is needed. * * @return 0 if successful */ void timing_print_info(TIMING_TIMER_T * timer, bool show_all) { int i; struct timeval lowest_elapsed_time = {100000000, 0}; int lowest_elapsed_time_index = 0; struct timeval highest_elapsed_time = {0, 0}; int highest_elapsed_time_index = 0; unsigned long std_dev = 0; int elapsed_usec; int average_usec; struct timeval elapsed_time = {0, 0}; struct timeval total_elapsed_time = {0, 0}; struct timeval average_elapsed_time = {0, 0}; struct timeval delta; if(timer != NULL) { if(timer->num_times_recorded == 0) { tracemsg(_a("\nTiming: no results captured.")); return; } tracemsg(_a("Timing: number of results captured: %d"), timer->num_times_recorded); /* Go figure out some info about the timers captured. */ for(i = 0; i < timer->num_times_recorded; i++) { /* Get elapsed_time. */ subtract(&(timer->times[i].start_time), &(timer->times[i].stop_time), &elapsed_time); /* Check elapsed time against highest. */ if(greater_than(&elapsed_time, &highest_elapsed_time)) { highest_elapsed_time.tv_sec = elapsed_time.tv_sec; highest_elapsed_time.tv_usec = elapsed_time.tv_usec; highest_elapsed_time_index = i; } /* Check elapsed time against lowest. */ if(less_than(&elapsed_time, &lowest_elapsed_time)) { lowest_elapsed_time.tv_sec = elapsed_time.tv_sec; lowest_elapsed_time.tv_usec = elapsed_time.tv_usec; lowest_elapsed_time_index = i; } /* Add this elapsed time to total. */ add(&elapsed_time, &total_elapsed_time, &total_elapsed_time); if(show_all) { tracemsg(_a(" result %4d: elapsed time %2lds, %6ld usec"), i, elapsed_time.tv_sec, elapsed_time.tv_usec); } } /* Figure out the average elapsed time. */ average(&total_elapsed_time, timer->num_times_recorded, &average_elapsed_time); tracemsg(_a("Average elapsed %2lds, %6ld usec"), average_elapsed_time.tv_sec, average_elapsed_time.tv_usec); /* Figure out standard deviation for the set of elapsed times. This needs to be * done after the average is calculated. */ average_usec = USECS(average_elapsed_time); for(i = 0; i < timer->num_times_recorded; i++) { /* Get elapsed_time between the start and stop. */ subtract(&(timer->times[i].start_time), &(timer->times[i].stop_time), &elapsed_time); elapsed_usec = USECS(elapsed_time); std_dev += ((elapsed_usec - average_usec) * (elapsed_usec - average_usec)); } std_dev = std_dev / i; /* Rounding error shouldn't matter too much.*/ std_dev = square_root(std_dev); tracemsg(_a(" Approx std dev %6ld usec"), std_dev); /* For highest time recorded, figure out delta between this and average. */ subtract(&average_elapsed_time, &highest_elapsed_time, &delta); tracemsg(_a("Highest elapsed %2lds, %6ld usec (delta from avg %lds, %6ldus, result %d)"), highest_elapsed_time.tv_sec, highest_elapsed_time.tv_usec, delta.tv_sec, delta.tv_usec, highest_elapsed_time_index); /* Same for lowest. */ subtract(&lowest_elapsed_time, &average_elapsed_time, &delta); tracemsg(_a(" Lowest elapsed %2lds, %6ld usec (delta from avg %lds, %6ldus, result %d)"), lowest_elapsed_time.tv_sec, lowest_elapsed_time.tv_usec, delta.tv_sec, delta.tv_usec, lowest_elapsed_time_index); } }
/*! * @brief Finds the rate at which something occurred. * * Given a period, this function determines the rate at which an event occurred. * * @param period Period for rate information * * @return rate corresponding to period, in events per second (rounded down). */ static int rate_per_sec(struct timeval * period) { return(CARRY_USEC / USECS(*period)); }