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
15package com.google.caliper.runner;
16
17import static com.google.caliper.runner.CommonInstrumentOptions.GC_BEFORE_EACH_OPTION;
18import static com.google.caliper.runner.CommonInstrumentOptions.MAX_WARMUP_WALL_TIME_OPTION;
19import static com.google.caliper.runner.CommonInstrumentOptions.MEASUREMENTS_OPTION;
20import static com.google.caliper.runner.CommonInstrumentOptions.WARMUP_OPTION;
21import static com.google.caliper.util.Reflection.getAnnotatedMethods;
22import static com.google.caliper.util.Util.isStatic;
23import static com.google.common.base.Preconditions.checkArgument;
24import static com.google.common.base.Preconditions.checkNotNull;
25import static com.google.common.base.Preconditions.checkState;
26import static com.google.common.base.Throwables.propagateIfInstanceOf;
27import static java.util.concurrent.TimeUnit.MILLISECONDS;
28import static java.util.concurrent.TimeUnit.NANOSECONDS;
29
30import com.google.caliper.Benchmark;
31import com.google.caliper.api.AfterRep;
32import com.google.caliper.api.BeforeRep;
33import com.google.caliper.api.Macrobenchmark;
34import com.google.caliper.api.SkipThisScenarioException;
35import com.google.caliper.bridge.AbstractLogMessageVisitor;
36import com.google.caliper.bridge.GcLogMessage;
37import com.google.caliper.bridge.HotspotLogMessage;
38import com.google.caliper.bridge.StartMeasurementLogMessage;
39import com.google.caliper.bridge.StopMeasurementLogMessage;
40import com.google.caliper.model.Measurement;
41import com.google.caliper.platform.Platform;
42import com.google.caliper.platform.SupportedPlatform;
43import com.google.caliper.util.ShortDuration;
44import com.google.caliper.worker.MacrobenchmarkWorker;
45import com.google.caliper.worker.RuntimeWorker;
46import com.google.caliper.worker.Worker;
47import com.google.common.base.Stopwatch;
48import com.google.common.collect.ImmutableList;
49import com.google.common.collect.ImmutableMap;
50import com.google.common.collect.ImmutableSet;
51import com.google.common.collect.Lists;
52
53import java.lang.reflect.InvocationTargetException;
54import java.lang.reflect.Method;
55import java.math.BigDecimal;
56import java.util.List;
57import java.util.logging.Logger;
58
59import javax.annotation.Nullable;
60import 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})
66class 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
76  RuntimeInstrument(@NanoTimeGranularity ShortDuration nanoTimeGranularity) {
77    this.nanoTimeGranularity = nanoTimeGranularity;
78  }
79
80  @Override
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
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
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 {
121    MacrobenchmarkInstrumentation(Method benchmarkMethod) {
122      super(benchmarkMethod);
123    }
124
125    @Override
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
152    public Class<? extends Worker> workerClass() {
153      return MacrobenchmarkWorker.class;
154    }
155
156    @Override
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
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 {
175    RuntimeInstrumentation(Method method) {
176      super(method);
177    }
178
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
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
197    private String toNanosString(String optionName) {
198      return String.valueOf(
199          ShortDuration.valueOf(options.get(optionName)).to(NANOSECONDS));
200    }
201
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 {
213    MicrobenchmarkInstrumentation(Method benchmarkMethod) {
214      super(benchmarkMethod);
215    }
216
217    @Override public Class<? extends Worker> workerClass() {
218      return RuntimeWorker.Micro.class;
219    }
220  }
221
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 {
233    PicobenchmarkInstrumentation(Method benchmarkMethod) {
234      super(benchmarkMethod);
235    }
236
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
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
270    public void visit(GcLogMessage logMessage) {
271      if (measuring && isWarmupComplete() && !notifiedAboutGc) {
272        gcWhileMeasuring();
273        notifiedAboutGc = true;
274      }
275    }
276
277    abstract void gcWhileMeasuring();
278
279    @Override
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
292    abstract void hotspotWhileMeasuring();
293
294    abstract void hotspotWhileNotMeasuring();
295
296    @Override
297    public void visit(StartMeasurementLogMessage logMessage) {
298      checkState(!measuring);
299      measuring = true;
300      if (!timeSinceStartOfTrial.isRunning()) {
301        timeSinceStartOfTrial.start();
302      }
303    }
304
305    @Override
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
336    abstract void validateMeasurement(Measurement measurement);
337
338    @Override
339    public ImmutableList<Measurement> getMeasurements() {
340      return ImmutableList.copyOf(measurements);
341    }
342
343    boolean measuredWarmupDurationReached() {
344      return elapsedWarmup.compareTo(warmup) >= 0;
345    }
346
347    @Override
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
359    public boolean isDoneCollecting() {
360      return measurements.size() >= targetMeasurements;
361    }
362
363    @Override
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
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
384    void gcWhileMeasuring() {
385      invalidateMeasurements = true;
386      messages.add("ERROR: GC occurred during timing. Measurements were discarded.");
387    }
388
389    @Override
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
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
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
424    SingleInvocationMeasurementCollector(
425        int measurementsPerTrial,
426        ShortDuration warmup,
427        ShortDuration maxWarmupWallTime,
428        ShortDuration nanoTimeGranularity) {
429      super(measurementsPerTrial, warmup, maxWarmupWallTime, nanoTimeGranularity);
430    }
431
432    @Override
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
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
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
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