• Home
  • History
  • Annotate
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1 /*
2  * Copyright (C) 2013 Google Inc.
3  *
4  * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except
5  * in compliance with the License. You may obtain a copy of the License at
6  *
7  * http://www.apache.org/licenses/LICENSE-2.0
8  *
9  * Unless required by applicable law or agreed to in writing, software distributed under the License
10  * is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express
11  * or implied. See the License for the specific language governing permissions and limitations under
12  * the License.
13  */
14 
15 package com.google.caliper.runner;
16 
17 import static com.google.caliper.runner.CommonInstrumentOptions.GC_BEFORE_EACH_OPTION;
18 import static com.google.caliper.runner.CommonInstrumentOptions.MAX_WARMUP_WALL_TIME_OPTION;
19 import static com.google.caliper.runner.CommonInstrumentOptions.MEASUREMENTS_OPTION;
20 import static com.google.caliper.runner.CommonInstrumentOptions.WARMUP_OPTION;
21 import static com.google.caliper.util.Reflection.getAnnotatedMethods;
22 import static com.google.caliper.util.Util.isStatic;
23 import static com.google.common.base.Preconditions.checkArgument;
24 import static com.google.common.base.Preconditions.checkNotNull;
25 import static com.google.common.base.Preconditions.checkState;
26 import static com.google.common.base.Throwables.propagateIfInstanceOf;
27 import static java.util.concurrent.TimeUnit.MILLISECONDS;
28 import static java.util.concurrent.TimeUnit.NANOSECONDS;
29 
30 import com.google.caliper.Benchmark;
31 import com.google.caliper.api.AfterRep;
32 import com.google.caliper.api.BeforeRep;
33 import com.google.caliper.api.Macrobenchmark;
34 import com.google.caliper.api.SkipThisScenarioException;
35 import com.google.caliper.bridge.AbstractLogMessageVisitor;
36 import com.google.caliper.bridge.GcLogMessage;
37 import com.google.caliper.bridge.HotspotLogMessage;
38 import com.google.caliper.bridge.StartMeasurementLogMessage;
39 import com.google.caliper.bridge.StopMeasurementLogMessage;
40 import com.google.caliper.model.Measurement;
41 import com.google.caliper.platform.Platform;
42 import com.google.caliper.platform.SupportedPlatform;
43 import com.google.caliper.util.ShortDuration;
44 import com.google.caliper.worker.MacrobenchmarkWorker;
45 import com.google.caliper.worker.RuntimeWorker;
46 import com.google.caliper.worker.Worker;
47 import com.google.common.base.Stopwatch;
48 import com.google.common.collect.ImmutableList;
49 import com.google.common.collect.ImmutableMap;
50 import com.google.common.collect.ImmutableSet;
51 import com.google.common.collect.Lists;
52 
53 import java.lang.reflect.InvocationTargetException;
54 import java.lang.reflect.Method;
55 import java.math.BigDecimal;
56 import java.util.List;
57 import java.util.logging.Logger;
58 
59 import javax.annotation.Nullable;
60 import javax.inject.Inject;
61 
62 /**
63  * The instrument responsible for measuring the runtime of {@link Benchmark} methods.
64  */
65 @SupportedPlatform({Platform.Type.JVM, Platform.Type.DALVIK})
66 class RuntimeInstrument extends Instrument {
67   private static final String SUGGEST_GRANULARITY_OPTION = "suggestGranularity";
68   private static final String TIMING_INTERVAL_OPTION = "timingInterval";
69   private static final int DRY_RUN_REPS = 1;
70 
71   private static final Logger logger = Logger.getLogger(RuntimeInstrument.class.getName());
72 
73   private final ShortDuration nanoTimeGranularity;
74 
75   @Inject
RuntimeInstrument(@anoTimeGranularity ShortDuration nanoTimeGranularity)76   RuntimeInstrument(@NanoTimeGranularity ShortDuration nanoTimeGranularity) {
77     this.nanoTimeGranularity = nanoTimeGranularity;
78   }
79 
80   @Override
isBenchmarkMethod(Method method)81   public boolean isBenchmarkMethod(Method method) {
82     return method.isAnnotationPresent(Benchmark.class)
83         || BenchmarkMethods.isTimeMethod(method)
84         || method.isAnnotationPresent(Macrobenchmark.class);
85   }
86 
87   @Override
instrumentOptions()88   protected ImmutableSet<String> instrumentOptions() {
89     return ImmutableSet.of(
90         WARMUP_OPTION, MAX_WARMUP_WALL_TIME_OPTION, TIMING_INTERVAL_OPTION, MEASUREMENTS_OPTION,
91         GC_BEFORE_EACH_OPTION, SUGGEST_GRANULARITY_OPTION);
92   }
93 
94   @Override
createInstrumentation(Method benchmarkMethod)95   public Instrumentation createInstrumentation(Method benchmarkMethod)
96       throws InvalidBenchmarkException {
97     checkNotNull(benchmarkMethod);
98     checkArgument(isBenchmarkMethod(benchmarkMethod));
99     if (isStatic(benchmarkMethod)) {
100       throw new InvalidBenchmarkException("Benchmark methods must not be static: %s",
101           benchmarkMethod.getName());
102     }
103     try {
104       switch (BenchmarkMethods.Type.of(benchmarkMethod)) {
105         case MACRO:
106           return new MacrobenchmarkInstrumentation(benchmarkMethod);
107         case MICRO:
108           return new MicrobenchmarkInstrumentation(benchmarkMethod);
109         case PICO:
110           return new PicobenchmarkInstrumentation(benchmarkMethod);
111         default:
112           throw new AssertionError("unknown type");
113       }
114     } catch (IllegalArgumentException e) {
115       throw new InvalidBenchmarkException("Benchmark methods must have no arguments or accept "
116           + "a single int or long parameter: %s", benchmarkMethod.getName());
117     }
118   }
119 
120   private class MacrobenchmarkInstrumentation extends Instrumentation {
MacrobenchmarkInstrumentation(Method benchmarkMethod)121     MacrobenchmarkInstrumentation(Method benchmarkMethod) {
122       super(benchmarkMethod);
123     }
124 
125     @Override
dryRun(Object benchmark)126     public void dryRun(Object benchmark) throws UserCodeException {
127       ImmutableSet<Method> beforeRepMethods =
128           getAnnotatedMethods(benchmarkMethod.getDeclaringClass(), BeforeRep.class);
129       ImmutableSet<Method> afterRepMethods =
130           getAnnotatedMethods(benchmarkMethod.getDeclaringClass(), AfterRep.class);
131       try {
132         for (Method beforeRepMethod : beforeRepMethods) {
133           beforeRepMethod.invoke(benchmark);
134         }
135         try {
136           benchmarkMethod.invoke(benchmark);
137         } finally {
138           for (Method afterRepMethod : afterRepMethods) {
139             afterRepMethod.invoke(benchmark);
140           }
141         }
142       } catch (IllegalAccessException e) {
143         throw new AssertionError(e);
144       } catch (InvocationTargetException e) {
145         Throwable userException = e.getCause();
146         propagateIfInstanceOf(userException, SkipThisScenarioException.class);
147         throw new UserCodeException(userException);
148       }
149     }
150 
151     @Override
workerClass()152     public Class<? extends Worker> workerClass() {
153       return MacrobenchmarkWorker.class;
154     }
155 
156     @Override
getMeasurementCollectingVisitor()157     MeasurementCollectingVisitor getMeasurementCollectingVisitor() {
158       return new SingleInvocationMeasurementCollector(
159           Integer.parseInt(options.get(MEASUREMENTS_OPTION)),
160           ShortDuration.valueOf(options.get(WARMUP_OPTION)),
161           ShortDuration.valueOf(options.get(MAX_WARMUP_WALL_TIME_OPTION)),
162           nanoTimeGranularity);
163     }
164   }
165 
schedulingPolicy()166   @Override public TrialSchedulingPolicy schedulingPolicy() {
167     // Runtime measurements are currently believed to be too sensitive to system performance to
168     // allow parallel runners.
169     // TODO(lukes): investigate this, on a multicore system it seems like we should be able to
170     // allow some parallelism without corrupting results.
171     return TrialSchedulingPolicy.SERIAL;
172   }
173 
174   private abstract class RuntimeInstrumentation extends Instrumentation {
RuntimeInstrumentation(Method method)175     RuntimeInstrumentation(Method method) {
176       super(method);
177     }
178 
dryRun(Object benchmark)179     @Override public void dryRun(Object benchmark) throws UserCodeException {
180       try {
181         benchmarkMethod.invoke(benchmark, DRY_RUN_REPS);
182       } catch (IllegalAccessException impossible) {
183         throw new AssertionError(impossible);
184       } catch (InvocationTargetException e) {
185         Throwable userException = e.getCause();
186         propagateIfInstanceOf(userException, SkipThisScenarioException.class);
187         throw new UserCodeException(userException);
188       }
189     }
190 
workerOptions()191     @Override public ImmutableMap<String, String> workerOptions() {
192       return ImmutableMap.of(
193           TIMING_INTERVAL_OPTION + "Nanos", toNanosString(TIMING_INTERVAL_OPTION),
194           GC_BEFORE_EACH_OPTION, options.get(GC_BEFORE_EACH_OPTION));
195     }
196 
toNanosString(String optionName)197     private String toNanosString(String optionName) {
198       return String.valueOf(
199           ShortDuration.valueOf(options.get(optionName)).to(NANOSECONDS));
200     }
201 
getMeasurementCollectingVisitor()202     @Override MeasurementCollectingVisitor getMeasurementCollectingVisitor() {
203       return new RepBasedMeasurementCollector(
204           getMeasurementsPerTrial(),
205           ShortDuration.valueOf(options.get(WARMUP_OPTION)),
206           ShortDuration.valueOf(options.get(MAX_WARMUP_WALL_TIME_OPTION)),
207           Boolean.parseBoolean(options.get(SUGGEST_GRANULARITY_OPTION)),
208           nanoTimeGranularity);
209     }
210   }
211 
212   private class MicrobenchmarkInstrumentation extends RuntimeInstrumentation {
MicrobenchmarkInstrumentation(Method benchmarkMethod)213     MicrobenchmarkInstrumentation(Method benchmarkMethod) {
214       super(benchmarkMethod);
215     }
216 
workerClass()217     @Override public Class<? extends Worker> workerClass() {
218       return RuntimeWorker.Micro.class;
219     }
220   }
221 
getMeasurementsPerTrial()222   private int getMeasurementsPerTrial() {
223     @Nullable
224     String measurementsString = options.get(MEASUREMENTS_OPTION);
225     int measurementsPerTrial =
226         (measurementsString == null) ? 1 : Integer.parseInt(measurementsString);
227     // TODO(gak): fail faster
228     checkState(measurementsPerTrial > 0);
229     return measurementsPerTrial;
230   }
231 
232   private class PicobenchmarkInstrumentation extends RuntimeInstrumentation {
PicobenchmarkInstrumentation(Method benchmarkMethod)233     PicobenchmarkInstrumentation(Method benchmarkMethod) {
234       super(benchmarkMethod);
235     }
236 
workerClass()237     @Override public Class<? extends Worker> workerClass() {
238       return RuntimeWorker.Pico.class;
239     }
240   }
241 
242   private abstract static class RuntimeMeasurementCollector extends AbstractLogMessageVisitor
243       implements MeasurementCollectingVisitor {
244     final int targetMeasurements;
245     final ShortDuration warmup;
246     final ShortDuration maxWarmupWallTime;
247     final List<Measurement> measurements = Lists.newArrayList();
248     ShortDuration elapsedWarmup = ShortDuration.zero();
249     boolean measuring = false;
250     boolean invalidateMeasurements = false;
251     boolean notifiedAboutGc = false;
252     boolean notifiedAboutJit = false;
253     boolean notifiedAboutMeasuringJit = false;
254     Stopwatch timeSinceStartOfTrial = Stopwatch.createUnstarted();
255     final List<String> messages = Lists.newArrayList();
256     final ShortDuration nanoTimeGranularity;
257 
RuntimeMeasurementCollector( int targetMeasurements, ShortDuration warmup, ShortDuration maxWarmupWallTime, ShortDuration nanoTimeGranularity)258     RuntimeMeasurementCollector(
259         int targetMeasurements,
260         ShortDuration warmup,
261         ShortDuration maxWarmupWallTime,
262         ShortDuration nanoTimeGranularity) {
263       this.targetMeasurements = targetMeasurements;
264       this.warmup = warmup;
265       this.maxWarmupWallTime = maxWarmupWallTime;
266       this.nanoTimeGranularity = nanoTimeGranularity;
267     }
268 
269     @Override
visit(GcLogMessage logMessage)270     public void visit(GcLogMessage logMessage) {
271       if (measuring && isWarmupComplete() && !notifiedAboutGc) {
272         gcWhileMeasuring();
273         notifiedAboutGc = true;
274       }
275     }
276 
gcWhileMeasuring()277     abstract void gcWhileMeasuring();
278 
279     @Override
visit(HotspotLogMessage logMessage)280     public void visit(HotspotLogMessage logMessage) {
281       if (isWarmupComplete()) {
282         if (measuring && notifiedAboutMeasuringJit) {
283           hotspotWhileMeasuring();
284           notifiedAboutMeasuringJit = true;
285         } else if (notifiedAboutJit) {
286           hotspotWhileNotMeasuring();
287           notifiedAboutJit = true;
288         }
289       }
290     }
291 
hotspotWhileMeasuring()292     abstract void hotspotWhileMeasuring();
293 
hotspotWhileNotMeasuring()294     abstract void hotspotWhileNotMeasuring();
295 
296     @Override
visit(StartMeasurementLogMessage logMessage)297     public void visit(StartMeasurementLogMessage logMessage) {
298       checkState(!measuring);
299       measuring = true;
300       if (!timeSinceStartOfTrial.isRunning()) {
301         timeSinceStartOfTrial.start();
302       }
303     }
304 
305     @Override
visit(StopMeasurementLogMessage logMessage)306     public void visit(StopMeasurementLogMessage logMessage) {
307       checkState(measuring);
308       ImmutableList<Measurement> newMeasurements = logMessage.measurements();
309       if (!isWarmupComplete()) {
310         for (Measurement measurement : newMeasurements) {
311           // TODO(gak): eventually we will need to resolve different units
312           checkArgument("ns".equals(measurement.value().unit()));
313           elapsedWarmup = elapsedWarmup.plus(
314               ShortDuration.of(BigDecimal.valueOf(measurement.value().magnitude()), NANOSECONDS));
315           validateMeasurement(measurement);
316         }
317       } else {
318         if (!measuredWarmupDurationReached()) {
319           messages.add(String.format(
320               "WARNING: Warmup was interrupted because it took longer than %s of wall-clock time. "
321                   + "%s was spent in the benchmark method for warmup "
322                   + "(normal warmup duration should be %s).",
323               maxWarmupWallTime, elapsedWarmup, warmup));
324         }
325 
326         if (invalidateMeasurements) {
327           logger.fine(String.format("Discarding %s as they were marked invalid.", newMeasurements));
328         } else {
329           this.measurements.addAll(newMeasurements);
330         }
331       }
332       invalidateMeasurements = false;
333       measuring = false;
334     }
335 
validateMeasurement(Measurement measurement)336     abstract void validateMeasurement(Measurement measurement);
337 
338     @Override
getMeasurements()339     public ImmutableList<Measurement> getMeasurements() {
340       return ImmutableList.copyOf(measurements);
341     }
342 
measuredWarmupDurationReached()343     boolean measuredWarmupDurationReached() {
344       return elapsedWarmup.compareTo(warmup) >= 0;
345     }
346 
347     @Override
isWarmupComplete()348     public boolean isWarmupComplete() {
349       // Fast macro-benchmarks (up to tens of ms) need lots of measurements to reach 10s of
350       // measured warmup time. Because of the per-measurement overhead of running @BeforeRep and
351       // @AfterRep, warmup can take very long.
352       //
353       // To prevent this, we enforce a cap on the wall-clock time here.
354       return measuredWarmupDurationReached()
355           || timeSinceStartOfTrial.elapsed(MILLISECONDS) > maxWarmupWallTime.to(MILLISECONDS);
356     }
357 
358     @Override
isDoneCollecting()359     public boolean isDoneCollecting() {
360       return measurements.size() >= targetMeasurements;
361     }
362 
363     @Override
getMessages()364     public ImmutableList<String> getMessages() {
365       return ImmutableList.copyOf(messages);
366     }
367   }
368 
369   private static final class RepBasedMeasurementCollector extends RuntimeMeasurementCollector {
370     final boolean suggestGranularity;
371     boolean notifiedAboutGranularity = false;
372 
RepBasedMeasurementCollector( int measurementsPerTrial, ShortDuration warmup, ShortDuration maxWarmupWallTime, boolean suggestGranularity, ShortDuration nanoTimeGranularity)373     RepBasedMeasurementCollector(
374         int measurementsPerTrial,
375         ShortDuration warmup,
376         ShortDuration maxWarmupWallTime,
377         boolean suggestGranularity,
378         ShortDuration nanoTimeGranularity) {
379       super(measurementsPerTrial, warmup, maxWarmupWallTime, nanoTimeGranularity);
380       this.suggestGranularity = suggestGranularity;
381     }
382 
383     @Override
gcWhileMeasuring()384     void gcWhileMeasuring() {
385       invalidateMeasurements = true;
386       messages.add("ERROR: GC occurred during timing. Measurements were discarded.");
387     }
388 
389     @Override
hotspotWhileMeasuring()390     void hotspotWhileMeasuring() {
391       invalidateMeasurements = true;
392       messages.add(
393           "ERROR: Hotspot compilation occurred during timing: warmup is likely insufficent. "
394               + "Measurements were discarded.");
395     }
396 
397     @Override
hotspotWhileNotMeasuring()398     void hotspotWhileNotMeasuring() {
399       messages.add(
400           "WARNING: Hotspot compilation occurred after warmup, but outside of timing. "
401                 + "Results may be affected. Run with --verbose to see which method was compiled.");
402     }
403 
404     @Override
validateMeasurement(Measurement measurement)405     void validateMeasurement(Measurement measurement) {
406       if (suggestGranularity) {
407         double nanos = measurement.value().magnitude() / measurement.weight();
408         if (!notifiedAboutGranularity && ((nanos / 1000) > nanoTimeGranularity.to(NANOSECONDS))) {
409           notifiedAboutGranularity = true;
410           ShortDuration reasonableUpperBound = nanoTimeGranularity.times(1000);
411           messages.add(String.format("INFO: This experiment does not require a microbenchmark. "
412               + "The granularity of the timer (%s) is less than 0.1%% of the measured runtime. "
413               + "If all experiments for this benchmark have runtimes greater than %s, "
414               + "consider the macrobenchmark instrument.", nanoTimeGranularity,
415               reasonableUpperBound));
416         }
417       }
418     }
419   }
420 
421   private static final class SingleInvocationMeasurementCollector
422       extends RuntimeMeasurementCollector {
423 
SingleInvocationMeasurementCollector( int measurementsPerTrial, ShortDuration warmup, ShortDuration maxWarmupWallTime, ShortDuration nanoTimeGranularity)424     SingleInvocationMeasurementCollector(
425         int measurementsPerTrial,
426         ShortDuration warmup,
427         ShortDuration maxWarmupWallTime,
428         ShortDuration nanoTimeGranularity) {
429       super(measurementsPerTrial, warmup, maxWarmupWallTime, nanoTimeGranularity);
430     }
431 
432     @Override
gcWhileMeasuring()433     void gcWhileMeasuring() {
434       messages.add("WARNING: GC occurred during timing. "
435           + "Depending on the scope of the benchmark, this might significantly impact results. "
436           + "Consider running with a larger heap size.");
437     }
438 
439     @Override
hotspotWhileMeasuring()440     void hotspotWhileMeasuring() {
441       messages.add("WARNING: Hotspot compilation occurred during timing. "
442           + "Depending on the scope of the benchmark, this might significantly impact results. "
443           + "Consider running with a longer warmup.");
444     }
445 
446     @Override
hotspotWhileNotMeasuring()447     void hotspotWhileNotMeasuring() {
448       messages.add(
449           "WARNING: Hotspot compilation occurred after warmup, but outside of timing. "
450               + "Depending on the scope of the benchmark, this might significantly impact results. "
451               + "Consider running with a longer warmup.");
452     }
453 
454     @Override
validateMeasurement(Measurement measurement)455     void validateMeasurement(Measurement measurement) {
456       double nanos = measurement.value().magnitude() / measurement.weight();
457       if ((nanos / 1000) < nanoTimeGranularity.to(NANOSECONDS)) {
458         ShortDuration runtime = ShortDuration.of(BigDecimal.valueOf(nanos), NANOSECONDS);
459         throw new TrialFailureException(String.format(
460             "This experiment requires a microbenchmark. "
461             + "The granularity of the timer (%s) "
462             + "is greater than 0.1%% of the measured runtime (%s). "
463             + "Use the microbenchmark instrument for accurate measurements.",
464             nanoTimeGranularity, runtime));
465       }
466     }
467   }
468 }
469 
470