Serialize console prints with the print_lock
[akaros.git] / user / benchutil / measure.c
1 /* Copyright (c) 2013 The Regents of the University of California
2  * Barret Rhoden <brho@cs.berkeley.edu>
3  * See LICENSE for details.
4  *
5  * Userspace functions for various measurements.
6  *
7  * For now, this is built into parlib.  We can pull it out in the future.  Many
8  * of the larger functions are in flux. */
9
10 #include <math.h>
11 #include <stdio.h>
12 #include <stdlib.h>
13 #include <sys/param.h>
14 #ifdef __ros__
15 #include <parlib/tsc-compat.h>
16 #include <benchutil/measure.h>
17 #endif /* __ros__ */
18
19 /* Basic stats computation and printing.
20  *
21  * All of these expect a 2D collection of samples, where the first array is an
22  * array of arrays of samples.  The first array's members are something like
23  * per-thread samples, where each thread fills in its
24  * data[thread_id][sample_number].  The samples should be ordered in
25  * chronological order.  Ultimately, the sample needs to produce a uint64_t
26  * (e.g. TSC tick). */
27
28 static void init_stats(struct sample_stats *stats)
29 {
30         stats->avg_time = 0;
31         stats->var_time = 0;
32         stats->max_time = 0;
33         stats->min_time = UINT64_MAX;
34         stats->lat_50 = 0;
35         stats->lat_75 = 0;
36         stats->lat_90 = 0;
37         stats->lat_99 = 0;
38         stats->total_samples = 0;
39 }
40
41 /* Could have options for printing for how many rows we want, how much we want
42  * to trim the max/min, and how many samples per bin. */
43 void compute_stats(void **data, int nr_i, int nr_j, struct sample_stats *stats)
44 {
45         uint64_t sample_time, hist_max_time, hist_min_time,
46                  lat_max_time, lat_min_time;
47         size_t hist_idx, lat_idx, hist_bin_sz, lat_bin_sz;
48         float accum_samples = 0.0, coef_var;
49         unsigned int *hist_times;
50         unsigned int *lat_times;
51         unsigned int nr_hist_bins = 75;         /* looks reasonable when printed */
52         unsigned int nr_lat_bins = 500;         /* affects granularity of lat perc */
53         unsigned int max_dots_per_row = 45;     /* looks good with 80-wide col */
54         unsigned int max_hist_bin = 0;
55         #define HI_COEF_VAR 1.0
56
57         init_stats(stats);
58         /* First pass, figure out the min, max, avg, etc. */
59         for (int i = 0; i < nr_i; i++) {
60                 for (int j = 0; j < nr_j; j++) {
61                         /* get_sample returns 0 on success.  o/w, skip the sample */
62                         if (stats->get_sample(data, i, j, &sample_time))
63                                 continue;       /* depending on semantics, we could break */
64                         stats->total_samples++;
65                         stats->avg_time += sample_time;
66                         stats->max_time = sample_time > stats->max_time ? sample_time
67                                                                         : stats->max_time;
68                         stats->min_time = sample_time < stats->min_time ? sample_time
69                                                                         : stats->min_time;
70                 }
71         }
72         if (stats->total_samples < 2) {
73                 printf("Not enough samples (%llu) for avg and var\n",
74                        stats->total_samples);
75                 return;
76         }
77         stats->avg_time /= stats->total_samples;
78         /* Second pass, compute the variance.  Want to do this before the
79          * histograms, so we can trim the serious outliers */
80         for (int i = 0; i < nr_i; i++) {
81                 for (int j = 0; j < nr_j; j++) {
82                         if (stats->get_sample(data, i, j, &sample_time))
83                                 continue;
84                         /* var: (sum_i=1..n { (x_i - xbar)^2 }) / (n - 1) */
85                         stats->var_time += (sample_time - stats->avg_time) *
86                                            (sample_time - stats->avg_time);
87                 }
88         }
89         stats->var_time /= stats->total_samples - 1;
90         /* We have two histogram structures.  The main one is for printing, and the
91          * other is for computing latency percentiles.  The only real diff btw the
92          * two is the number of bins.  The latency one has a lot more, for finer
93          * granularity, and the regular one has fewer for better printing.
94          *
95          * Both have the same max and min bin values.  Any excesses get put in the
96          * smallest or biggest bin.  This keeps the granularity reasonable in the
97          * face of very large outliers.  Normally, I trim off anything outside 3
98          * stddev.
99          * 
100          * High variation will throw off our histogram bins, so we adjust.  A
101          * coef_var > 1 is considered high variance.  The numbers I picked are just
102          * heuristics to catch SMM interference and make the output look nice. */
103         coef_var = sqrt(stats->var_time) / stats->avg_time;
104         if (coef_var > HI_COEF_VAR) {
105                 hist_max_time = stats->avg_time * 3;
106                 hist_min_time = stats->avg_time / 3;
107         } else {        /* 'normal' data */
108                 /* trimming the printable hist at 3 stddevs, which for normal data is
109                  * 99.7% of the data.  For most any data, it gets 89% (Chebyshev's
110                  * inequality) */
111                 hist_max_time = stats->avg_time + 3 * sqrt(stats->var_time);
112                 hist_min_time = stats->avg_time - 3 * sqrt(stats->var_time);
113                 if (hist_min_time > hist_max_time)
114                         hist_min_time = 0;
115         }
116         lat_max_time = hist_max_time;
117         lat_min_time = hist_min_time;
118         hist_bin_sz = (hist_max_time - hist_min_time) / nr_hist_bins + 1;
119         lat_bin_sz = (lat_max_time - lat_min_time) / nr_lat_bins + 1;
120         hist_times = malloc(sizeof(unsigned int) * nr_hist_bins);
121         lat_times = malloc(sizeof(unsigned int) * nr_lat_bins);
122         if (!hist_times || !lat_times) {
123                 perror("compute_stats failed to alloc hist/lat arrays:");
124                 free(hist_times);
125                 free(lat_times);
126                 return;
127         }
128         memset(hist_times, 0, sizeof(unsigned int) * nr_hist_bins);
129         memset(lat_times, 0, sizeof(unsigned int) * nr_lat_bins);
130         /* third pass, fill the bins for the histogram and latencies */
131         for (int i = 0; i < nr_i; i++) {
132                 for (int j = 0; j < nr_j; j++) {
133                         if (stats->get_sample(data, i, j, &sample_time))
134                                 continue;
135                         /* need to shift, offset by min_time.  anything too small is 0 and
136                          * will go into the first bin.  anything too large will go into the
137                          * last bin. */
138                         lat_idx = sample_time < lat_min_time
139                                   ? 0
140                                   : (sample_time - lat_min_time) / lat_bin_sz;
141                         lat_idx = MIN(lat_idx, nr_lat_bins - 1);
142                         lat_times[lat_idx]++;
143                         hist_idx = sample_time < hist_min_time
144                                    ? 0
145                                    : (sample_time - hist_min_time) / hist_bin_sz;
146                         hist_idx = MIN(hist_idx, nr_hist_bins - 1);
147                         hist_times[hist_idx]++;
148                         /* useful for formatting the ***s */
149                         max_hist_bin = (hist_times[hist_idx] > max_hist_bin)
150                                        ? hist_times[hist_idx]
151                                        : max_hist_bin;
152                 }
153         }
154         /* Compute latency percentiles */
155         for (int i = 0; i < nr_lat_bins; i++) {
156                 accum_samples += lat_times[i];
157                 /* (i + 1), since we've just accumulated one bucket's worth */
158                 if (!stats->lat_50 && accum_samples / stats->total_samples > 0.50)
159                         stats->lat_50 = (i + 1) * lat_bin_sz + lat_min_time;
160                 if (!stats->lat_75 && accum_samples / stats->total_samples > 0.75)
161                         stats->lat_75 = (i + 1) * lat_bin_sz + lat_min_time;
162                 if (!stats->lat_90 && accum_samples / stats->total_samples > 0.90)
163                         stats->lat_90 = (i + 1) * lat_bin_sz + lat_min_time;
164                 if (!stats->lat_99 && accum_samples / stats->total_samples > 0.99)
165                         stats->lat_99 = (i + 1) * lat_bin_sz + lat_min_time;
166         }
167         for (int i = 0; i < nr_hist_bins; i++) {
168                 uint64_t interval_start = i * hist_bin_sz + hist_min_time;
169                 uint64_t interval_end = (i + 1) * hist_bin_sz + hist_min_time;
170                 /* customize the first and last entries */
171                 if (i == 0)
172                         interval_start = MIN(interval_start, stats->min_time);
173                 if (i == nr_hist_bins - 1) {
174                         interval_end = MAX(interval_end, stats->max_time);
175                         /* but not at the sake of formatting! (8 spaces) */
176                         interval_end = MIN(interval_end, 99999999);
177                 }
178                 printf("    [%8llu - %8llu] %7d: ", interval_start, interval_end,
179                        hist_times[i]);
180                 /* nr_dots = hist_times[i] * nr_dots_per_sample
181                  *         = hist_times[i] * (max_num_dots / max_hist_bin) */
182                 int nr_dots = hist_times[i] * max_dots_per_row / max_hist_bin;
183                 for (int j = 0; j < nr_dots; j++)
184                         printf("*");
185                 printf("\n");
186         }
187         printf("\n");
188         printf("Samples per dot: %d\n", max_hist_bin / max_dots_per_row);
189         printf("Total samples: %llu\n", stats->total_samples);
190         printf("Avg time   : %llu\n", stats->avg_time);
191         printf("Stdev time : %f\n", sqrt(stats->var_time));
192         printf("Coef Var   : %f\n", coef_var);
193         if (coef_var > HI_COEF_VAR)
194                 printf("\tHigh coeff of var with serious outliers, adjusted bins\n");
195         /* numbers are overestimates by at most a lat bin */
196         printf("50/75/90/99: %d / %d / %d / %d (-<%ld)\n", stats->lat_50,
197                stats->lat_75, stats->lat_90, stats->lat_99, lat_bin_sz);
198         printf("Min / Max  : %llu / %llu\n", stats->min_time, stats->max_time);
199         printf("\n");
200         free(hist_times);
201         free(lat_times);
202 }
203
204 /* Prints the throughput of certain events over nr_steps of interval time.  Will
205  * print the overall throughput of the entire time (total events / steps),
206  * and print out each step up to nr_print_steps.
207  *
208  * Assumes a 2D data structure, where the events in each data[i][] (for a
209  * specific i) are in order.  The 'nr_i'es are typically threads or something
210  * similar.  nr_j would be how many samples per thread.  The func ptr should
211  * return the time of the data[i][j]'th event via *sample and return 0 on
212  * success, and any other value for 'no data'.  If start_time is 0, we'll start
213  * the clock right before the first event. */
214 void print_throughput(void **data, unsigned int nr_steps, uint64_t interval,
215                       unsigned int nr_print_steps, uint64_t start_time,
216                       int nr_i, int nr_j,
217                       int (*get_sample)(void **data, int i, int j,
218                                         uint64_t *sample))
219 {
220         uint64_t time_now, sample;
221         /* next_sample[] tracks each thread's next lock that was acquired */
222         unsigned int *next_sample;
223         unsigned int *step_events;
224         unsigned int most_step_events = 1;
225         unsigned int max_dots_per_row = 45;     /* looks good with 80-wide col */
226         unsigned int total_events = 0;
227
228         if (!nr_steps)
229                 return;
230         nr_print_steps = MIN(nr_print_steps, nr_steps);
231         next_sample = malloc(sizeof(unsigned int) * nr_i);
232         step_events = malloc(sizeof(unsigned int) * nr_steps);
233         if (!next_sample || !step_events) {
234                 perror("print_throughput failed alloc:");
235                 free(next_sample);
236                 free(step_events);
237                 return;
238         }
239         memset(next_sample, 0, sizeof(unsigned int) * nr_i);
240         memset(step_events, 0, sizeof(unsigned int) * nr_steps);
241         if (start_time) {
242                 time_now = start_time;
243         } else {
244                 time_now = UINT64_MAX;
245                 /* Set the replay to start right before the first event */
246                 for (int i = 0; i < nr_i; i++) {
247                         if (get_sample(data, i, 0, &sample))
248                                 continue;
249                         time_now = MIN(time_now, sample);
250                 }
251                 if (time_now != 0)
252                         time_now--;
253         }
254         for (int k = 0; k < nr_steps; k++) {
255                 time_now += interval;
256                 /* for every 'thread', we'll figure out how many events occurred, and
257                  * advance next_sample to track the next one to consider */
258                 for (int i = 0; i < nr_i; i++) {
259                         /* count nr locks that have happened, advance per thread tracker */
260                         for ( ; next_sample[i] < nr_j; next_sample[i]++) {
261                                 /* skip this thread if it has no more data */
262                                 if (get_sample(data, i, next_sample[i], &sample))
263                                         continue;
264                                 /* break when we found one that hasn't happened yet */
265                                 if (!(sample <= time_now))
266                                         break;
267                                 step_events[k]++;
268                         }
269                 }
270                 total_events += step_events[k];
271                 /* for dynamically scaling the *'s */
272                 most_step_events = MAX(most_step_events, step_events[k]);
273         }
274         if (nr_print_steps)
275                 printf("Events per dot: %d\n", most_step_events / max_dots_per_row);
276         for (int k = 0; k < nr_print_steps; k++) {
277                 /* Last step isn't accurate, will only be partially full */
278                 if (k == nr_steps - 1)
279                         break;
280                 printf("%6d: ", k);
281                 printf("%6d ", step_events[k]);
282                 /* nr_dots = step_events[k] * nr_dots_per_event
283                  *         = step_events[k] * (max_dots_per_row / most_step_events) */
284                 int nr_dots = step_events[k] * max_dots_per_row / most_step_events;
285                 for (int i = 0; i < nr_dots; i++)
286                         printf("*");
287                 printf("\n");
288         }
289         printf("Total events: %d, Avg events/step: %d\n", total_events,
290                total_events / nr_steps);
291         free(next_sample);
292         free(step_events);
293 }