quick demo microbenchmark of sampling (systematic and random) applied to a Timer metric

BasicSamplingPerfTest.java

package com.yammer.metrics.tests;

import org.junit.Test;

import com.yammer.metrics.ThreadLocalRandom;
import com.yammer.metrics.Timer;
import com.yammer.metrics.Timer.Context;

/**
 * Quick demo of sampling. Execute using "-XX:+PrintCompilation -verbose:gc" to verify that JIT and GC don't occur during the measurement phase of this
 * microbenchmark.
 */
public class BasicSamplingPerfTest {
    private static final int MEASURED_ITERATIONS = 150000; // spend a reasonable amount of time executing
    private static final float SAMPLE_PROBABILITY = 0.01f; // when sampling, measure 1% of events

    private Timer unsampledTimer = new Timer();
    private Timer systematicTimer = new Timer();
    private Timer randomTimer = new Timer();
    private int busyWork = 0; // used to perform "work" in the hotspot implementation

    // translate probability into the [-MAX_INT, MAX_INT] range
    private int probabilityVsMaxInt = (int) ((float) (Integer.MAX_VALUE * ((2.0f * SAMPLE_PROBABILITY) - 1.0f)));
    // convert probability into an interval (loses precision but ok for this demo)
    private int probabilityAsInterval = (int) (1.0f / SAMPLE_PROBABILITY);

    @Test
    public void test() {
        // warmup, discard measurements
        for (int i = 0; i < 10; i++) {
            sampledSystematic(systematicTimer);
            sampledRandom(randomTimer);
            unsampled(unsampledTimer);
        }

        // now measure
        System.out.println("starting measurement phase");
        long systematic = 0L;
        long random = 0L;
        long unsampled = 0L;
        for (int i = 0; i < 10; i++) {
            systematic += sampledSystematic(systematicTimer);
            random += sampledRandom(randomTimer);
            unsampled += unsampled(unsampledTimer);
        }

        System.out.println("measurement phase complete (useless output = " + busyWork + ").  Times:"); // log val to ensure we don't optimize it out
        System.out.println("unsampled = " + (unsampled / 1000000) + " ms (times = " + unsampledTimer.getCount() + ")");
        System.out.println("sampledSystematic = " + (systematic / 1000000) + " ms (times = " + systematicTimer.getCount() + ")");
        System.out.println("sampledRandom = " + (random / 1000000) + " ms (times = " + randomTimer.getCount() + ")");
    }

    // the unsampled, normal case
    private long unsampled(Timer timer) {
        long start = System.nanoTime();
        for (int i = 0; i < MEASURED_ITERATIONS; i++) {
            timedHotSpot(timer);
        }
        return (System.nanoTime() - start);
    }

    // recording only ~1% of events using systematic sampling
    private long sampledSystematic(Timer timer) {
        long start = System.nanoTime();
        for (int i = 0; i < MEASURED_ITERATIONS; i++) {
            if (i % probabilityAsInterval == 0) {
                timedHotSpot(timer);
            } else {
                untimedHotSpot();
            }
        }
        return (System.nanoTime() - start);
    }

    // recording only ~1% of events using simple random sampling
    private long sampledRandom(Timer timer) {
        long start = System.nanoTime();
        for (int i = 0; i < MEASURED_ITERATIONS; i++) {
            if (ThreadLocalRandom.current().nextInt() <= probabilityVsMaxInt) {
                timedHotSpot(timer);
            } else {
                untimedHotSpot();
            }
        }
        return (System.nanoTime() - start);
    }

    // our hot spot implementation
    private void untimedHotSpot() {
        for (int i = 0; i < 500; i++) {
            busyWork = (busyWork * 33) + i;
        }
    }

    // and the timer-wrapped version
    private void timedHotSpot(Timer timer) {
        Context context = timer.time();
        untimedHotSpot();
        context.stop();
    }

}