tests/org.eclipse.ui.monitoring.tests/src/org/eclipse/ui/internal/monitoring/EventLoopMonitorThreadManualTests.java

/*******************************************************************************
 * Copyright (C) 2014, 2019 Google Inc and others.
 *
 * This program and the accompanying materials
 * are made available under the terms of the Eclipse Public License 2.0
 * which accompanies this distribution, and is available at
 * https://www.eclipse.org/legal/epl-2.0/
 *
 * SPDX-License-Identifier: EPL-2.0
 *
 * Contributors:
 *	   Steve Foreman (Google) - initial API and implementation
 *	   Marcus Eng (Google)
 *	   Sergey Prigogin (Google)
 *	   Simon Scholz <simon.scholz@vogella.com> - Bug 443391
 *     Christoph Läubrich - change to new preference store API
 *******************************************************************************/
package org.eclipse.ui.internal.monitoring;

import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertNotNull;
import static org.junit.Assert.assertTrue;

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadMXBean;
import java.util.ArrayDeque;
import java.util.ArrayList;
import java.util.LinkedList;
import java.util.List;
import java.util.Queue;
import java.util.Random;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;

import org.eclipse.jface.preference.IPreferenceStore;
import org.eclipse.swt.widgets.Display;
import org.eclipse.ui.monitoring.PreferenceConstants;
import org.junit.After;
import org.junit.Before;
import org.junit.Test;

/**
 * A test that measures performance overhead of {@link EventLoopMonitorThread}.
 * This test is not included into {@link MonitoringTestSuite} due to its low reliability
 * and the amount of time it takes.
 */
public class EventLoopMonitorThreadManualTests {
	/** Change to {@code true} to enable printing of detailed information to the console. */
	private static final boolean PRINT_TO_CONSOLE = false;

	// Test Parameters
	/** Time each measurement should run for. This will affect the number of samples collected. */
	protected static final double TARGET_RUNNING_TIME_PER_MEASUREMENT = 5.0; // seconds

	/** Maximum allowable relative increase due to taking traces of the UI thread. */
	protected static final double MAX_RELATIVE_INCREASE_ONE_STACK_PERCENT = 2.5; // %

	/** Maximum allowable relative increase per thread due to taking traces of all threads. */
	protected static final double MAX_RELATIVE_INCREASE_PER_EXTRA_THREAD_PERCENT = 0.3; // %

	/** Number of times to repeat the control measurement. This should always be at least 2. */
	protected static final int NUM_CONTROL_MEASUREMENTS = 5;

	/** Number of times to repeat the UI stack sampling measurement. */
	protected static final int NUM_UI_STACK_MEASUREMENTS = 5;

	/** Number of times to repeat the all stacks sampling measurement. */
	protected static final int NUM_ALL_STACKS_MEASUREMENTS = 5;

	// Calibration Tuning Parameters
	/**
	 * Number of work units to integrate over while calibrating. This parameter is used to adjust
	 * how much work is done to capture some jitter but too large of value will oscillate with large
	 * events (e.g. GC) instead of converging.
	 */
	protected static final long WORK_INTEGRATION_ITERATIONS = 70000; // iterations

	/**
	 * Number of consecutive iterations below the error threshold (defined by
	 * {@link #CAL_MAX_RELATIVE_ERROR}) before accepting a calibration result. Due to occasional
	 * jitter (e.g. OS scheduling, GC, etc), large values may not ever converge.
	 */
	protected static final int MIN_CONVERGING_ITERATIONS = 256; // iterations

	/**
	 * Number of outliers, relative to samples, to tolerate while calculating convergence during
	 * calibration. Tolerated points are ignored (e.g. not factored into the rolling average).
	 */
	protected static final double MAX_OUTLIER_RATIO = 0.03;

	/**
	 * Weight of new elements added to the exponential averaging of the mean during calibration.
	 * The optimal value is [2/(N-1)] where N is the desired number of samples to average.
	 */
	protected static final double CAL_EMA_ALPHA = 2.0 / (MIN_CONVERGING_ITERATIONS - 1.0);

	/**
	 * Max relative error between each new estimated mean and the previous estimate.
	 * Once the relative error stabilizes below this threshold for long enough (defined by
	 * {@link #MIN_CONVERGING_ITERATIONS} iterations) the calibration is complete.
	 */
	protected static final double CAL_MAX_RELATIVE_ERROR = 0.003;

	/**
	 * Pseudo-random Noise LFSR generator polynomial, degree = 64. Polynomial for maximum sequence
	 * length by Wayne Stahnke, Primitive Polynomials Modulo Two,
	 * http://www.ams.org/journals/mcom/1973-27-124/S0025-5718-1973-0327722-7/S0025-5718-1973-0327722-7.pdf
	 *
	 * <p>
	 * At 80ns/call, the sequence will have a period of &gt;23382 years (== (2^63-1) * 80ns)
	 */
	protected static final long PN63_GENERATOR_POLY = (3L << 62) | 1;

	@Before
	public void setUp() {
		MonitoringPlugin.getPreferenceStore().setValue(PreferenceConstants.MONITORING_ENABLED, false);
	}

	@After
	public void tearDown() {
		MonitoringPlugin.getPreferenceStore().setToDefault(PreferenceConstants.MONITORING_ENABLED);
	}

	protected static long pn63(long pnSequence) {
		int nextBit = 0;
		for (int i = 0; i < 64; ++i) {
			if (((PN63_GENERATOR_POLY >> i) & 1) == 1) {
				nextBit ^= (pnSequence >> i) & 1;
			}
		}

		return (pnSequence << 1) | nextBit;
	}

	protected static long doWork(long pnSeqeuence, long iterations) {
		LinkedList<String> messages = new LinkedList<>();

		for (long i = 0; i < iterations; ++i) {
			pnSeqeuence = pn63(pnSeqeuence);

			if (i % 10000 == 0) {
				messages.add("10000!");
			} else if (i % 1000 == 0) {
				for (int c = messages.size() / 2; c >= 0; --c) {
					messages.removeFirst();
				}
			} else if (i % 100 == 0) {
				messages.add(String.format("Iteration %d", i));
			}
		}

		for (String s : messages) {
			pnSeqeuence ^= s.hashCode();
		}

		return pnSeqeuence;
	}

	/**
	 * Performance test for {@link EventLoopMonitorThread}. This test verifies that the monitoring
	 * doesn't interfere too much with the real work being done.
	 */
	@Test
	public void testFixedWork() throws Exception{
		final Display display = Display.getDefault();
		assertNotNull("No SWT Display available.", display);

		final MockUiFreezeEventLogger logger = new MockUiFreezeEventLogger();
		final CountDownLatch backgroundJobsDone = new CountDownLatch(1);
		Queue<Thread> threads = startBackgroundThreads(backgroundJobsDone);

		double nsPerWork = calibrate(display);
		final long numIterations = Math.round(1e9 * TARGET_RUNNING_TIME_PER_MEASUREMENT / nsPerWork);

		final double[] tWork = {0};
		final long[] workOutput = {0};
		final Runnable doFixedAmountOfWork = () -> {
			long start = System.nanoTime();
			long result = doWork(start, numIterations);
			tWork[0] = System.nanoTime() - start;
			workOutput[0] ^= result;
		};

		// Fetch the total number of threads.
		ThreadMXBean jvmThreadManager = ManagementFactory.getThreadMXBean();
		boolean dumpLockedMonitors = jvmThreadManager.isObjectMonitorUsageSupported();
		boolean dumpLockedSynchronizers = jvmThreadManager.isSynchronizerUsageSupported();
		int totalThreadCount =
				jvmThreadManager.dumpAllThreads(dumpLockedMonitors, dumpLockedSynchronizers).length;

		List<Double> controlResults = new ArrayList<>(NUM_CONTROL_MEASUREMENTS);
		List<Double> uiStackResults = new ArrayList<>(NUM_UI_STACK_MEASUREMENTS);
		List<Double> allStacksResults = new ArrayList<>(NUM_ALL_STACKS_MEASUREMENTS);
		double expectedRunningTime = 0.0;
		double maxRunningTime = 0.0;

		/*
		 * This could be made more precise by measuring the control loop many times, calculating
		 * the mean and standard deviation, measuring each of the test case a few times, calculating
		 * the probability of the result, and comparing that probability to some acceptable bound.
		 */
		if (PRINT_TO_CONSOLE) {
			System.out.println(String.format("Starting %d control measurements without monitoring.",
					NUM_CONTROL_MEASUREMENTS));
		}
		for (int i = 1; i <= NUM_CONTROL_MEASUREMENTS; ++i) {
			display.syncExec(doFixedAmountOfWork);
			if (PRINT_TO_CONSOLE) {
				System.out.println(String.format("Control measurement %d/%d finished. tWork = %fs",
					i, NUM_CONTROL_MEASUREMENTS, tWork[0] / 1e9));
			}
			controlResults.add(tWork[0]);
			expectedRunningTime += tWork[0] / NUM_CONTROL_MEASUREMENTS;
			if (tWork[0] > maxRunningTime) {
				maxRunningTime = tWork[0];
			}
		}

		// Calculate error bound between mean and max control runs.
		double controlDiff = Math.abs((maxRunningTime - expectedRunningTime) / expectedRunningTime);
		double maxRelativeIncreaseOneStackAllowed =
			(MAX_RELATIVE_INCREASE_ONE_STACK_PERCENT / 100.) * (1 + controlDiff);
		double maxRelativeIncreaseAllStacksAllowed =
				((MAX_RELATIVE_INCREASE_ONE_STACK_PERCENT + MAX_RELATIVE_INCREASE_PER_EXTRA_THREAD_PERCENT
				* (totalThreadCount - 1)) / 100.) * (1 + controlDiff);

		Thread monitor1 = createAndStartMonitoringThread(display, false);
		double worstRelativeDiffOneThread = Double.MIN_NORMAL;
		if (PRINT_TO_CONSOLE) {
			System.out.println(
					String.format("Starting %d measurements while collecting UI thread stacks.",
					NUM_UI_STACK_MEASUREMENTS));
		}
		for (int i = 1; i <= NUM_UI_STACK_MEASUREMENTS; ++i) {
			display.syncExec(doFixedAmountOfWork);
			uiStackResults.add(tWork[0]);
			double relativeDiffOneThread = (tWork[0] - expectedRunningTime) / expectedRunningTime;
			if (relativeDiffOneThread > worstRelativeDiffOneThread) {
				worstRelativeDiffOneThread = relativeDiffOneThread;
			}
			if (PRINT_TO_CONSOLE) {
				System.out.println(String.format(
						"Measurement %d of %d took %.3fs. Relative increase = %.3f%% "
						+ "(allowed < %.3f%%).",
						i, NUM_UI_STACK_MEASUREMENTS, tWork[0] / 1e9, relativeDiffOneThread * 100,
						maxRelativeIncreaseOneStackAllowed * 100));
			}
			assertTrue(
				String.format("Relative overhead of monitoring surpassed threshold for "
					+ "measurement %d of %d. It took %.3fs with a relative increase of %.3f%% "
					+ "(allowed < %.3f%%).",
					i, NUM_UI_STACK_MEASUREMENTS, tWork[0] / 1e9, relativeDiffOneThread * 100,
					maxRelativeIncreaseOneStackAllowed * 100),
				relativeDiffOneThread <= maxRelativeIncreaseOneStackAllowed);
		}
		killMonitorThread(monitor1, display);

		Thread monitor2 = createAndStartMonitoringThread(display, true);
		double worstRelativeDiffAllThreads = Double.MIN_NORMAL;
		if (PRINT_TO_CONSOLE) {
			System.out.println(
					String.format("Starting %d measurements while collecting all thread stacks.",
					NUM_ALL_STACKS_MEASUREMENTS));
		}
		for (int i = 1; i <= NUM_ALL_STACKS_MEASUREMENTS; ++i) {
			display.syncExec(doFixedAmountOfWork);
			allStacksResults.add(tWork[0]);
			double relativeDiffAllThreads = (tWork[0] - expectedRunningTime) / expectedRunningTime;
			if (relativeDiffAllThreads > worstRelativeDiffAllThreads) {
				worstRelativeDiffAllThreads = relativeDiffAllThreads;
			}
			if (PRINT_TO_CONSOLE) {
				System.out.println(String.format(
						"Measurement %d of %d took %.3fs, Relative increase = %.3f%% "
						+ "(allowed < %.3f%%).",
						i, NUM_ALL_STACKS_MEASUREMENTS, tWork[0] / 1e9, relativeDiffAllThreads * 100,
						maxRelativeIncreaseAllStacksAllowed * 100));
			}
			assertTrue(
				String.format("Relative overhead of monitoring with stack traces of all threads "
					+ "surpassed threshold for measurement %d of %d. It took %.3fs with a relative "
					+ "increase of %.3f%% (allowed < %.3f%%).",
					i, NUM_ALL_STACKS_MEASUREMENTS, tWork[0] / 1e9, relativeDiffAllThreads * 100,
					maxRelativeIncreaseAllStacksAllowed * 100),
				relativeDiffAllThreads <= maxRelativeIncreaseAllStacksAllowed);
		}
		killMonitorThread(monitor2, display);

		backgroundJobsDone.countDown();

		if (PRINT_TO_CONSOLE) {
			// Tabulate final results while waiting for monitor to finish.
			double controlMean = 0;
			double controlMin = Double.MAX_VALUE;
			double controlMax = Double.MIN_NORMAL;
			double controlM2 = 0;
			for (int n = 0; n < controlResults.size(); ) {
				double v = controlResults.get(n) / 1e9;
				controlResults.set(n, v);
				++n;
				double delta = v - controlMean;
				controlMean += delta / n;
				controlM2 += delta * (v - controlMean);
				controlMin = Math.min(controlMin, v);
				controlMax = Math.max(controlMax, v);
			}
			double controlStD = Math.sqrt(controlM2 / controlResults.size());

			double uiStackMean = 0;
			double uiStackMin = Double.MAX_VALUE;
			double uiStackMax = Double.MIN_NORMAL;
			double uiStackM2 = 0;
			for (int n = 0; n < uiStackResults.size(); ) {
				double v = uiStackResults.get(n) / 1e9;
				uiStackResults.set(n, v);
				++n;
				double delta = v - uiStackMean;
				uiStackMean += delta / n;
				uiStackM2 += delta * (v - uiStackMean);
				uiStackMin = Math.min(uiStackMin, v);
				uiStackMax = Math.max(uiStackMax, v);
			}

			double allStacksMean = 0;
			double allStacksMin = Double.MAX_VALUE;
			double allStacksMax = Double.MIN_NORMAL;
			double allStacksM2 = 0;
			for (int n = 0; n < allStacksResults.size(); ) {
				double v = allStacksResults.get(n) / 1e9;
				allStacksResults.set(n, v);
				++n;
				double delta = v - allStacksMean;
				allStacksMean += delta / n;
				allStacksM2 += delta * (v - allStacksMean);
				allStacksMin = Math.min(allStacksMin, v);
				allStacksMax = Math.max(allStacksMax, v);
			}

			// Ensure that the work cannot be optimized away completely.
			System.out.println(String.format("Work result = %016X", workOutput[0]));

			if (!(worstRelativeDiffOneThread <= maxRelativeIncreaseOneStackAllowed)) {
				System.out.println(" * Monitoring UI thread slowed down work too much");
			}
			if (!(worstRelativeDiffAllThreads <= maxRelativeIncreaseAllStacksAllowed)) {
				System.out.println(" * Monitoring all threads slowed down work too much");
			}
			if (logger.getLoggedEvents().size() != NUM_UI_STACK_MEASUREMENTS + NUM_ALL_STACKS_MEASUREMENTS) {
				System.out.println(String.format(" * Didn't get expected freeze events (got %d/%d)",
						logger.getLoggedEvents().size(),
						NUM_UI_STACK_MEASUREMENTS + NUM_ALL_STACKS_MEASUREMENTS));
			}

			System.out.println("\nRaw results (in seconds): ");
			System.out.println(String.format(
					" * Control    (min = %f max = %f avg = %f stD = %f): %s",
					controlMin, controlMax, controlMean, controlStD, joinItems(controlResults)));
			System.out.println(String.format(
					" * UI stack   (min = %f max = %f avg = %f stD = %f, vsC = %f): %s",
					uiStackMin, uiStackMax, uiStackMean, Math.sqrt(uiStackM2 / uiStackResults.size()),
					Math.abs(uiStackMean - controlMean) / controlStD, joinItems(uiStackResults)));
			System.out.println(String.format(
					" * All stacks (min = %f max = %f avg = %f stD = %f, vsC = %f): %s",
					allStacksMin, allStacksMax, allStacksMean, Math.sqrt(allStacksM2 / allStacksResults.size()),
					Math.abs(allStacksMean - controlMean) / controlStD,
					joinItems(allStacksResults)));
		}

		// Join all threads.
		while (!threads.isEmpty()) {
			Thread t = threads.poll();
			try {
				t.join();
			} catch (InterruptedException e) {
				threads.offer(t); // Retry.
			}
		}

		assertEquals("Did not log expected number of freeze events,",
				NUM_UI_STACK_MEASUREMENTS + NUM_ALL_STACKS_MEASUREMENTS,
				logger.getLoggedEvents().size());
		assertTrue(String.format("Relative overhead of monitoring with stack traces of the UI "
				+ "thread was %.3f%% (allowed < %.3f%%).",
				worstRelativeDiffOneThread * 100,
				maxRelativeIncreaseOneStackAllowed * 100),
				worstRelativeDiffOneThread <= maxRelativeIncreaseOneStackAllowed);
		assertTrue(String.format("Relative overhead of monitoring with stack traces of all "
				+ "threads was %.3f%% (allowed < %.3f%%).",
				worstRelativeDiffAllThreads * 100,
				maxRelativeIncreaseAllStacksAllowed * 100),
				worstRelativeDiffAllThreads <= maxRelativeIncreaseAllStacksAllowed);
	}

	private Thread createAndStartMonitoringThread(Display display, boolean dumpAll) throws Exception {
		// Let the monitoring thread to go to sleep twice before considering it ready.
		CountDownLatch monitorStarted = new CountDownLatch(2);
		Thread monitor = createTestMonitor(dumpAll, monitorStarted);
		startMonitoring(display, monitor, monitorStarted);
		return monitor;
	}

	private void killMonitorThread(final Thread thread, Display display) throws Exception {
		display.syncExec(() -> shutdownThread(thread));

		thread.join();
	}

	protected static EventLoopMonitorThread.Parameters createDefaultParameters() {
		IPreferenceStore preferences = MonitoringPlugin.getPreferenceStore();
		EventLoopMonitorThread.Parameters params = new EventLoopMonitorThread.Parameters();

		params.longEventWarningThreshold =
				preferences.getInt(PreferenceConstants.LONG_EVENT_WARNING_THRESHOLD_MILLIS);
		params.longEventErrorThreshold =
				preferences.getInt(PreferenceConstants.LONG_EVENT_ERROR_THRESHOLD_MILLIS);
		params.maxStackSamples = preferences.getInt(PreferenceConstants.MAX_STACK_SAMPLES);
		params.deadlockThreshold =
				preferences.getInt(PreferenceConstants.DEADLOCK_REPORTING_THRESHOLD_MILLIS);
		params.uiThreadFilter = preferences.getString(PreferenceConstants.UI_THREAD_FILTER);
		params.noninterestingThreadFilter =
				preferences.getString(PreferenceConstants.NONINTERESTING_THREAD_FILTER);

		params.checkParameters();
		return params;
	}

	protected Thread createTestMonitor(boolean dumpAllThreads, final CountDownLatch monitorStarted)
			throws Exception {
		EventLoopMonitorThread.Parameters args = createDefaultParameters();
		if (dumpAllThreads) {
			args.longEventErrorThreshold = args.longEventWarningThreshold;
		}

		return new EventLoopMonitorThread(args) {
			@Override
			protected void sleepForMillis(long nanoseconds) {
				monitorStarted.countDown();
				super.sleepForMillis(nanoseconds);
			}
		};
	}

	protected Queue<Thread> startBackgroundThreads(final CountDownLatch backgroundJobsDone) {
		final Runnable backgroundTaskRunnable = () -> {
			final double dutyCycle = 0.10;

			final double min = 100; // ns
			final double max = 1e9; // ns
			final double skew = 0.1; // the degree to which the values cluster around the mode
			final double bias = -1e5; // bias the mode to approach the min (< 0) vs max (> 0)

			double range = max - min;
			double mid = min + range / 2.0;
			double biasFactor = Math.exp(bias);
			Random rng = new Random();

			while (true) {
				double rv = rng.nextGaussian();
				double runFor = mid + (range * (biasFactor / (biasFactor + Math.exp(-rv / skew)) - 0.5));

				long endTime = System.nanoTime() + (long) runFor;
				do {
					doWork(rng.nextInt(), (int) runFor);
				} while (endTime - System.nanoTime() > 0);

				double sleepScale = Math.abs(rng.nextGaussian() / dutyCycle);
				try {
					if (backgroundJobsDone.await((int) Math.round(runFor * sleepScale),
							TimeUnit.NANOSECONDS)) {
						return;
					}
				} catch (InterruptedException e) {
					// Wake up.
				}
			}
		};

		final Runnable backgroundIdle = () -> {
			while (true) {
				try {
					backgroundJobsDone.await();
					return;
				} catch (InterruptedException e) {
					// Wake up.
				}
			}
		};

		Random rng = new Random();
		int activeThreads = Thread.activeCount();
		int numBackgroundTasks = activeThreads <= 2 ? 5 + rng.nextInt(5) : 1;
		int numBackgroundIdlers = 8 + rng.nextInt(30);
		if (PRINT_TO_CONSOLE) {
			System.out.println(String.format("Starting %d background tasks and %d background idlers",
					numBackgroundTasks, numBackgroundIdlers));
		}
		Queue<Thread> threads = new ArrayDeque<>(numBackgroundIdlers + numBackgroundTasks);
		for (int i = 0; i < numBackgroundTasks; i++) {
			Thread t = new Thread(backgroundTaskRunnable);
			threads.add(t);
			t.start();
		}

		for (int i = 0; i < numBackgroundIdlers; i++) {
			Thread t = new Thread(backgroundIdle);
			threads.add(t);
			t.start();
		}
		return threads;
	}

	protected void startMonitoring(final Display display, final Thread monitorThread,
			CountDownLatch eventsRegistered) throws Exception {
		display.syncExec(() -> {
			monitorThread.start();

			// If we're still running when display gets disposed, shutdown the thread.
			display.disposeExec(() -> shutdownThread(monitorThread));
		});

		for (boolean eventsReady = false; !eventsReady;) {
			while (display.readAndDispatch()) { // Keep invoking events.
			}

			eventsReady |= eventsRegistered.await(1, TimeUnit.MILLISECONDS);
		}
	}

	protected void shutdownThread(Thread monitor) {
		((EventLoopMonitorThread) monitor).shutdown();
	}

	/**
	 * Returns nanoseconds/unitWork
	 */
	protected double calibrate(final Display display) {
		if (PRINT_TO_CONSOLE) {
			System.out.println("Starting calibration...");
		}
		final double[] tWork = {0};
		display.syncExec(() -> tWork[0] = measureAvgTimePerWorkItem());
		if (PRINT_TO_CONSOLE) {
			System.out.println(String.format("Calibration finished. tWorkUnit = %fns", tWork[0]));
		}
		return tWork[0];
	}

	protected double measureAvgTimePerWorkItem() {
		int consecutiveGood = 0;
		int outliers = 0;
		int hash = 0;
		double avgAbsRelErr = 0;

		double numSamplesAveraged = 2.0 / CAL_EMA_ALPHA + 1.0;

		// Ensure everything is in memory, JITed, and ready to go.
		doWork(0, 1000);

		// Initialize a meaningful mean
		long start = System.nanoTime();
		long result = doWork(0, WORK_INTEGRATION_ITERATIONS);
		double mean = System.nanoTime() - start;
		double oldMean;

		long n = 0;
		long startWallTime = System.currentTimeMillis();
		long nextPrintAt = startWallTime + 5000; // 5s
		while (++n < Long.MAX_VALUE
				&& (consecutiveGood < MIN_CONVERGING_ITERATIONS || avgAbsRelErr > CAL_MAX_RELATIVE_ERROR)) {
			start = System.nanoTime();
			result = doWork(result, WORK_INTEGRATION_ITERATIONS);
			long duration = System.nanoTime() - start;
			hash ^= result;

			double deltaDuration = duration - mean;
			oldMean = mean;
			mean += CAL_EMA_ALPHA * (deltaDuration - mean); // EMA
			double absRelErr = Math.abs((oldMean - mean) / mean);
			if (absRelErr < CAL_MAX_RELATIVE_ERROR) {
				consecutiveGood++;
				avgAbsRelErr = avgAbsRelErr * ((consecutiveGood - 1) / consecutiveGood)
						+ (absRelErr / consecutiveGood);
			} else if (outliers < (int) (MAX_OUTLIER_RATIO * Math.min(n, numSamplesAveraged))) {
				++outliers;
			} else {
				consecutiveGood = 1;
				outliers = 0;
				avgAbsRelErr = absRelErr;
			}

			if (nextPrintAt - System.currentTimeMillis() < 0) {
				nextPrintAt += 2000; // 2s
				if (PRINT_TO_CONSOLE) {
					System.out.println(String.format(
						"Still calibrating... n = %3d\t\ttWork = %f ns\t\tRelErr = %f\t\tOutliers = %d/%d",
						n, 2.0 * mean / WORK_INTEGRATION_ITERATIONS, avgAbsRelErr, outliers,
						(int) (MAX_OUTLIER_RATIO * Math.min(n, numSamplesAveraged))));
				}
			}
		}

		double tWork = 2.0 * mean / WORK_INTEGRATION_ITERATIONS;

		// Passing the hash to println method ensures that it cannot be optimized away completely.
		System.out.println(String.format("Measurement converged in %d ms (%d loops) "
				+ "tWork = %.3fns, relErr = %f, outliers = %d",
				System.currentTimeMillis() - startWallTime,
				n,
				tWork,
				avgAbsRelErr,
				outliers,
				hash));
		return tWork;
	}

	private String joinItems(List<Double> items) {
		StringBuilder mergedItems = new StringBuilder();

		for (double item : items) {
			if (mergedItems.length() != 0) {
				mergedItems.append(',');
			}
			mergedItems.append(item);
		}

		return mergedItems.toString();
	}

}