Home | History | Annotate | Download | only in runner 
      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
     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