folly: print nice time suffixes in benchmark output
[folly.git] / folly / Benchmark.cpp
1 /*
2  * Copyright 2012 Facebook, Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License");
5  * you may not use this file except in compliance with the License.
6  * You may obtain a copy of the License at
7  *
8  *   http://www.apache.org/licenses/LICENSE-2.0
9  *
10  * Unless required by applicable law or agreed to in writing, software
11  * distributed under the License is distributed on an "AS IS" BASIS,
12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13  * See the License for the specific language governing permissions and
14  * limitations under the License.
15  */
16
17 // @author Andrei Alexandrescu (andrei.alexandrescu@fb.com)
18
19 #include "Benchmark.h"
20 #include "Foreach.h"
21 #include "json.h"
22 #include "String.h"
23
24 #include <algorithm>
25 #include <boost/regex.hpp>
26 #include <cmath>
27 #include <iostream>
28 #include <limits>
29 #include <utility>
30 #include <vector>
31
32 using namespace std;
33
34 DEFINE_bool(benchmark, false, "Run benchmarks.");
35 DEFINE_bool(json, false, "Output in JSON format.");
36
37 DEFINE_string(bm_regex, "",
38               "Only benchmarks whose names match this regex will be run.");
39
40 DEFINE_int64(bm_min_usec, 100,
41              "Minimum # of microseconds we'll accept for each benchmark.");
42
43 DEFINE_int32(bm_max_secs, 1,
44              "Maximum # of seconds we'll spend on each benchmark.");
45
46
47 namespace folly {
48
49 BenchmarkSuspender::NanosecondsSpent BenchmarkSuspender::nsSpent;
50
51 typedef function<uint64_t(unsigned int)> BenchmarkFun;
52 static vector<tuple<const char*, const char*, BenchmarkFun>> benchmarks;
53
54 // Add the global baseline
55 BENCHMARK(globalBenchmarkBaseline) {
56   asm volatile("");
57 }
58
59 void detail::addBenchmarkImpl(const char* file, const char* name,
60                               BenchmarkFun fun) {
61   benchmarks.emplace_back(file, name, std::move(fun));
62 }
63
64 /**
65  * Given a point, gives density at that point as a number 0.0 < x <=
66  * 1.0. The result is 1.0 if all samples are equal to where, and
67  * decreases near 0 if all points are far away from it. The density is
68  * computed with the help of a radial basis function.
69  */
70 static double density(const double * begin, const double *const end,
71                       const double where, const double bandwidth) {
72   assert(begin < end);
73   assert(bandwidth > 0.0);
74   double sum = 0.0;
75   FOR_EACH_RANGE (i, begin, end) {
76     auto d = (*i - where) / bandwidth;
77     sum += exp(- d * d);
78   }
79   return sum / (end - begin);
80 }
81
82 /**
83  * Computes mean and variance for a bunch of data points. Note that
84  * mean is currently not being used.
85  */
86 static pair<double, double>
87 meanVariance(const double * begin, const double *const end) {
88   assert(begin < end);
89   double sum = 0.0, sum2 = 0.0;
90   FOR_EACH_RANGE (i, begin, end) {
91     sum += *i;
92     sum2 += *i * *i;
93   }
94   auto const n = end - begin;
95   return make_pair(sum / n, sqrt((sum2 - sum * sum / n) / n));
96 }
97
98 /**
99  * Computes the mode of a sample set through brute force. Assumes
100  * input is sorted.
101  */
102 static double mode(const double * begin, const double *const end) {
103   assert(begin < end);
104   // Lower bound and upper bound for result and their respective
105   // densities.
106   auto
107     result = 0.0,
108     bestDensity = 0.0;
109
110   // Get the variance so we pass it down to density()
111   auto const sigma = meanVariance(begin, end).second;
112   if (!sigma) {
113     // No variance means constant signal
114     return *begin;
115   }
116
117   FOR_EACH_RANGE (i, begin, end) {
118     assert(i == begin || *i >= i[-1]);
119     auto candidate = density(begin, end, *i, sigma * sqrt(2.0));
120     if (candidate > bestDensity) {
121       // Found a new best
122       bestDensity = candidate;
123       result = *i;
124     } else {
125       // Density is decreasing... we could break here if we definitely
126       // knew this is unimodal.
127     }
128   }
129
130   return result;
131 }
132
133 /**
134  * Given a bunch of benchmark samples, estimate the actual run time.
135  */
136 static double estimateTime(double * begin, double * end) {
137   assert(begin < end);
138
139   // Current state of the art: get the minimum. After some
140   // experimentation, it seems taking the minimum is the best.
141
142   return *min_element(begin, end);
143
144   // What follows after estimates the time as the mode of the
145   // distribution.
146
147   // Select the awesomest (i.e. most frequent) result. We do this by
148   // sorting and then computing the longest run length.
149   sort(begin, end);
150
151   // Eliminate outliers. A time much larger than the minimum time is
152   // considered an outlier.
153   while (end[-1] > 2.0 * *begin) {
154     --end;
155     if (begin == end) {
156       LOG(INFO) << *begin;
157     }
158     assert(begin < end);
159   }
160
161   double result = 0;
162
163   /* Code used just for comparison purposes */ {
164     unsigned bestFrequency = 0;
165     unsigned candidateFrequency = 1;
166     double candidateValue = *begin;
167     for (auto current = begin + 1; ; ++current) {
168       if (current == end || *current != candidateValue) {
169         // Done with the current run, see if it was best
170         if (candidateFrequency > bestFrequency) {
171           bestFrequency = candidateFrequency;
172           result = candidateValue;
173         }
174         if (current == end) {
175           break;
176         }
177         // Start a new run
178         candidateValue = *current;
179         candidateFrequency = 1;
180       } else {
181         // Cool, inside a run, increase the frequency
182         ++candidateFrequency;
183       }
184     }
185   }
186
187   result = mode(begin, end);
188
189   return result;
190 }
191
192 static double runBenchmarkGetNSPerIteration(const BenchmarkFun& fun,
193                                             const double globalBaseline) {
194   // They key here is accuracy; too low numbers means the accuracy was
195   // coarse. We up the ante until we get to at least minNanoseconds
196   // timings.
197   static uint64_t resolutionInNs = 0, coarseResolutionInNs = 0;
198   if (!resolutionInNs) {
199     timespec ts;
200     CHECK_EQ(0, clock_getres(detail::DEFAULT_CLOCK_ID, &ts));
201     CHECK_EQ(0, ts.tv_sec) << "Clock sucks.";
202     CHECK_LT(0, ts.tv_nsec) << "Clock too fast for its own good.";
203     CHECK_EQ(1, ts.tv_nsec) << "Clock too coarse, upgrade your kernel.";
204     resolutionInNs = ts.tv_nsec;
205   }
206   // We choose a minimum minimum (sic) of 100,000 nanoseconds, but if
207   // the clock resolution is worse than that, it will be larger. In
208   // essence we're aiming at making the quantization noise 0.01%.
209   static const auto minNanoseconds =
210     max(FLAGS_bm_min_usec * 1000UL, min(resolutionInNs * 100000, 1000000000UL));
211
212   // We do measurements in several epochs and take the minimum, to
213   // account for jitter.
214   static const unsigned int epochs = 1000;
215   // We establish a total time budget as we don't want a measurement
216   // to take too long. This will curtail the number of actual epochs.
217   const uint64_t timeBudgetInNs = FLAGS_bm_max_secs * 1000000000;
218   timespec global;
219   CHECK_EQ(0, clock_gettime(CLOCK_REALTIME, &global));
220
221   double epochResults[epochs] = { 0 };
222   size_t actualEpochs = 0;
223
224   for (; actualEpochs < epochs; ++actualEpochs) {
225     for (unsigned int n = 1; n < (1UL << 30); n *= 2) {
226       auto const nsecs = fun(n);
227       if (nsecs < minNanoseconds) {
228         continue;
229       }
230       // We got an accurate enough timing, done. But only save if
231       // smaller than the current result.
232       epochResults[actualEpochs] = max(0.0, double(nsecs) / n - globalBaseline);
233       // Done with the current epoch, we got a meaningful timing.
234       break;
235     }
236     timespec now;
237     CHECK_EQ(0, clock_gettime(CLOCK_REALTIME, &now));
238     if (detail::timespecDiff(now, global) >= timeBudgetInNs) {
239       // No more time budget available.
240       ++actualEpochs;
241       break;
242     }
243   }
244
245   // If the benchmark was basically drowned in baseline noise, it's
246   // possible it became negative.
247   return max(0.0, estimateTime(epochResults, epochResults + actualEpochs));
248 }
249
250 struct ScaleInfo {
251   double boundary;
252   const char* suffix;
253 };
254
255 static const ScaleInfo kTimeSuffixes[] {
256   { 365.25 * 24 * 3600, "years" },
257   { 24 * 3600, "days" },
258   { 3600, "hr" },
259   { 60, "min" },
260   { 1, "s" },
261   { 1E-3, "ms" },
262   { 1E-6, "us" },
263   { 1E-9, "ns" },
264   { 1E-12, "ps" },
265   { 1E-15, "fs" },
266   { 0, NULL },
267 };
268
269 static const ScaleInfo kMetricSuffixes[] {
270   { 1E24, "Y" },  // yotta
271   { 1E21, "Z" },  // zetta
272   { 1E18, "X" },  // "exa" written with suffix 'X' so as to not create
273                   //   confusion with scientific notation
274   { 1E15, "P" },  // peta
275   { 1E12, "T" },  // terra
276   { 1E9, "G" },   // giga
277   { 1E6, "M" },   // mega
278   { 1E3, "K" },   // kilo
279   { 1, "" },
280   { 1E-3, "m" },  // milli
281   { 1E-6, "u" },  // micro
282   { 1E-9, "n" },  // nano
283   { 1E-12, "p" }, // pico
284   { 1E-15, "f" }, // femto
285   { 1E-18, "a" }, // atto
286   { 1E-21, "z" }, // zepto
287   { 1E-24, "y" }, // yocto
288   { 0, NULL },
289 };
290
291 static string humanReadable(double n, unsigned int decimals,
292                             const ScaleInfo* scales) {
293   if (std::isinf(n) || std::isnan(n)) {
294     return folly::to<string>(n);
295   }
296
297   const double absValue = fabs(n);
298   const ScaleInfo* scale = scales;
299   while (absValue < scale[0].boundary && scale[1].suffix != NULL) {
300     ++scale;
301   }
302
303   const double scaledValue = n / scale->boundary;
304   return stringPrintf("%.*f%s", decimals, scaledValue, scale->suffix);
305 }
306
307 static string readableTime(double n, unsigned int decimals) {
308   return humanReadable(n, decimals, kTimeSuffixes);
309 }
310
311 static string metricReadable(double n, unsigned int decimals) {
312   return humanReadable(n, decimals, kMetricSuffixes);
313 }
314
315 static void printBenchmarkResultsAsTable(
316   const vector<tuple<const char*, const char*, double> >& data) {
317   // Width available
318   static const uint columns = 76;
319
320   // Compute the longest benchmark name
321   size_t longestName = 0;
322   FOR_EACH_RANGE (i, 1, benchmarks.size()) {
323     longestName = max(longestName, strlen(get<1>(benchmarks[i])));
324   }
325
326   // Print a horizontal rule
327   auto separator = [&](char pad) {
328     puts(string(columns, pad).c_str());
329   };
330
331   // Print header for a file
332   auto header = [&](const char* file) {
333     separator('=');
334     printf("%-*srelative  time/iter  iters/s\n",
335            columns - 28, file);
336     separator('=');
337   };
338
339   double baselineNsPerIter = numeric_limits<double>::max();
340   const char* lastFile = "";
341
342   for (auto& datum : data) {
343     auto file = get<0>(datum);
344     if (strcmp(file, lastFile)) {
345       // New file starting
346       header(file);
347       lastFile = file;
348     }
349
350     string s = get<1>(datum);
351     if (s == "-") {
352       separator('-');
353       continue;
354     }
355     bool useBaseline /* = void */;
356     if (s[0] == '%') {
357       s.erase(0, 1);
358       useBaseline = true;
359     } else {
360       baselineNsPerIter = get<2>(datum);
361       useBaseline = false;
362     }
363     s.resize(columns - 29, ' ');
364     auto nsPerIter = get<2>(datum);
365     auto secPerIter = nsPerIter / 1E9;
366     auto itersPerSec = 1 / secPerIter;
367     if (!useBaseline) {
368       // Print without baseline
369       printf("%*s           %9s  %7s\n",
370              static_cast<int>(s.size()), s.c_str(),
371              readableTime(secPerIter, 2).c_str(),
372              metricReadable(itersPerSec, 2).c_str());
373     } else {
374       // Print with baseline
375       auto rel = baselineNsPerIter / nsPerIter * 100.0;
376       printf("%*s %7.2f%%  %9s  %7s\n",
377              static_cast<int>(s.size()), s.c_str(),
378              rel,
379              readableTime(secPerIter, 2).c_str(),
380              metricReadable(itersPerSec, 2).c_str());
381     }
382   }
383   separator('=');
384 }
385
386 static void printBenchmarkResultsAsJson(
387   const vector<tuple<const char*, const char*, double> >& data) {
388   dynamic d = dynamic::object;
389   for (auto& datum: data) {
390     d[std::get<1>(datum)] = std::get<2>(datum) * 1000.;
391   }
392
393   printf("%s\n", toPrettyJson(d).c_str());
394 }
395
396 static void printBenchmarkResults(
397   const vector<tuple<const char*, const char*, double> >& data) {
398
399   if (FLAGS_json) {
400     printBenchmarkResultsAsJson(data);
401   } else {
402     printBenchmarkResultsAsTable(data);
403   }
404 }
405
406 void runBenchmarks() {
407   CHECK(!benchmarks.empty());
408
409   vector<tuple<const char*, const char*, double>> results;
410   results.reserve(benchmarks.size() - 1);
411
412   std::unique_ptr<boost::regex> bmRegex;
413   if (!FLAGS_bm_regex.empty()) {
414     bmRegex.reset(new boost::regex(FLAGS_bm_regex));
415   }
416
417   // PLEASE KEEP QUIET. MEASUREMENTS IN PROGRESS.
418
419   auto const globalBaseline = runBenchmarkGetNSPerIteration(
420     get<2>(benchmarks.front()), 0);
421   FOR_EACH_RANGE (i, 1, benchmarks.size()) {
422     double elapsed = 0.0;
423     if (!strcmp(get<1>(benchmarks[i]), "-") == 0) { // skip separators
424       if (bmRegex && !boost::regex_search(get<1>(benchmarks[i]), *bmRegex)) {
425         continue;
426       }
427       elapsed = runBenchmarkGetNSPerIteration(get<2>(benchmarks[i]),
428                                               globalBaseline);
429     }
430     results.emplace_back(get<0>(benchmarks[i]),
431                          get<1>(benchmarks[i]), elapsed);
432   }
433
434   // PLEASE MAKE NOISE. MEASUREMENTS DONE.
435
436   printBenchmarkResults(results);
437 }
438
439 } // namespace folly