/* * The contents of this file are subject to the terms of the Common Development and * Distribution License (the License). You may not use this file except in compliance with the * License. * * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the * specific language governing permission and limitations under the License. * * When distributing Covered Software, include this CDDL Header Notice in each file and include * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL * Header, with the fields enclosed by brackets [] replaced by your own identifying * information: "Portions Copyright [year] [name of copyright owner]". * * Copyright 2016 ForgeRock AS. */ package com.forgerock.opendj.ldap.tools; import static com.forgerock.opendj.cli.MultiColumnPrinter.column; import static com.forgerock.opendj.cli.MultiColumnPrinter.separatorColumn; import static com.forgerock.opendj.ldap.tools.ToolsMessages.INFO_TOOL_WARMING_UP; import static java.util.concurrent.TimeUnit.MILLISECONDS; import java.lang.management.GarbageCollectorMXBean; import java.lang.management.ManagementFactory; import java.util.ArrayList; import java.util.Collections; import java.util.List; import java.util.SortedMap; import java.util.concurrent.Executors; import java.util.concurrent.ScheduledExecutorService; import java.util.concurrent.TimeUnit; import com.codahale.metrics.Counter; import com.codahale.metrics.Gauge; import com.codahale.metrics.Histogram; import com.codahale.metrics.Meter; import com.codahale.metrics.MetricFilter; import com.codahale.metrics.MetricRegistry; import com.codahale.metrics.RatioGauge; import com.codahale.metrics.ScheduledReporter; import com.codahale.metrics.Timer; import com.forgerock.opendj.cli.ConsoleApplication; import com.forgerock.opendj.cli.MultiColumnPrinter; import org.mpierce.metrics.reservoir.hdrhistogram.HdrHistogramReservoir; /** * Statistics thread base implementation. *

* The goal of this class is to compute and print rate tool general statistics. */ class StatsThread extends Thread { static final String STAT_ID_PREFIX = "org.forgerock.opendj."; private static final String TIME_NOW = STAT_ID_PREFIX + "current_time"; private static final String RECENT_THROUGHPUT = STAT_ID_PREFIX + "recent_throughput"; private static final String AVERAGE_THROUGHPUT = STAT_ID_PREFIX + "average_throughput"; private static final String RECENT_RESPONSE_TIME_MS = STAT_ID_PREFIX + "recent_response_time"; private static final String AVERAGE_RESPONSE_TIME_MS = STAT_ID_PREFIX + "average_response_time"; private static final String PERCENTILES = STAT_ID_PREFIX + "percentiles"; private static final String ERROR_PER_SECOND = STAT_ID_PREFIX + "error_per_second"; public static final double MS_IN_S = TimeUnit.SECONDS.toMillis(1); public static final double NS_IN_MS = TimeUnit.MILLISECONDS.toNanos(1); private abstract class RateReporter extends ScheduledReporter { final MultiColumnPrinter printer; private RateReporter() { super(registry, "", MetricFilter.ALL, TimeUnit.SECONDS, TimeUnit.MILLISECONDS); printer = createPrinter(); } abstract MultiColumnPrinter createPrinter(); abstract void printTitle(); @Override @SuppressWarnings({ "rawtypes", "unchecked" }) public void report(final SortedMap gauges, final SortedMap counters, final SortedMap histograms, final SortedMap meters, final SortedMap timers) { int percentileIndex = 0; for (final MultiColumnPrinter.Column column : printer.getColumns()) { final String statKey = column.getId(); if (gauges.containsKey(statKey)) { printer.printData(((Gauge) gauges.get(statKey)).getValue()); } else if (statKey.startsWith(PERCENTILES)) { final double quantile = percentiles[percentileIndex++] / 100.0; printer.printData( histograms.get(PERCENTILES).getSnapshot().getValue(quantile) / MILLISECONDS.toNanos(1)); } else { printer.printData("-"); } } } } private final class ConsoleRateReporter extends RateReporter { private static final int STANDARD_WIDTH = 8; private List additionalColumns; @Override void printTitle() { final int throughputRawSpan = 2; final int responseTimeRawSpan = 2 + percentiles.length; final int additionalStatsRawSpan = 1 + additionalColumns.size(); printer.printDashedLine(); printer.printTitleSection("Throughput", throughputRawSpan); printer.printTitleSection("Response Time", responseTimeRawSpan); printer.printTitleSection(additionalStatsRawSpan > 1 ? "Additional" : "", additionalStatsRawSpan); printer.printTitleSection("(ops/second)", throughputRawSpan); printer.printTitleSection("(milliseconds)", responseTimeRawSpan); printer.printTitleSection(additionalStatsRawSpan > 1 ? "Statistics" : "", additionalStatsRawSpan); printer.printTitleLine(); printer.printDashedLine(); } @Override MultiColumnPrinter createPrinter() { final List columns = new ArrayList<>(); // Throughput (ops/sec) columns.add(separatorColumn()); columns.add(column(RECENT_THROUGHPUT, "recent", STANDARD_WIDTH, 1)); columns.add(column(AVERAGE_THROUGHPUT, "average", STANDARD_WIDTH, 1)); // Response Time (ms) columns.add(separatorColumn()); columns.add(column(RECENT_RESPONSE_TIME_MS, "recent", STANDARD_WIDTH, 3)); columns.add(column(AVERAGE_RESPONSE_TIME_MS, "average", STANDARD_WIDTH, 3)); for (double percentile : percentiles) { columns.add(column(PERCENTILES + percentile, percentile + "%", STANDARD_WIDTH, 2)); } // Additional stats columns.add(separatorColumn()); columns.add(column(ERROR_PER_SECOND, "err/sec", STANDARD_WIDTH, 1)); additionalColumns = registerAdditionalColumns(); if (!additionalColumns.isEmpty()) { columns.addAll(additionalColumns); } columns.add(separatorColumn()); return MultiColumnPrinter.builder(app.getOutputStream(), columns) .format(true) .titleAlignment(MultiColumnPrinter.Alignment.CENTER) .build(); } } private final class CsvRateReporter extends RateReporter { @Override void printTitle() { printer.printTitleLine(); } @Override MultiColumnPrinter createPrinter() { final List columns = new ArrayList<>(); columns.add(column(TIME_NOW, "Time (seconds)", 3)); columns.add(column(RECENT_THROUGHPUT, "Recent throughput (ops/second)", 1)); columns.add(column(AVERAGE_THROUGHPUT, "Average throughput (ops/second)", 1)); columns.add(column(RECENT_RESPONSE_TIME_MS, "Recent response time (milliseconds)", 3)); columns.add(column(AVERAGE_RESPONSE_TIME_MS, "Average response time (milliseconds)", 3)); for (double percentile : percentiles) { columns.add(column( PERCENTILES + percentile, percentile + "% response time (milliseconds)", 2)); } columns.add(column(ERROR_PER_SECOND, "Errors/second", 1)); columns.addAll(registerAdditionalColumns()); return MultiColumnPrinter.builder(app.getOutputStream(), columns) .columnSeparator(",") .build(); } } /** A timer to prevent adding temporary variables in {@link StatsThread#run()}. **/ private static abstract class StatsTimer { private long startTimeMeasure; private long elapsed; abstract long getInstantTime(); private void start() { startTimeMeasure = getInstantTime(); } private long reset() { final long time = getInstantTime(); elapsed = time - this.startTimeMeasure; this.startTimeMeasure = time; return elapsed; } private long elapsed() { return elapsed; } } /** A counter to prevent adding temporary variables in {@link StatsThread#run()}. **/ static final class IntervalCounter extends Counter { private long lastIntervalCount; private long lastTotalCount; long refreshIntervalCount() { final long totalCount = getCount(); lastIntervalCount = totalCount - lastTotalCount; lastTotalCount = totalCount; return lastIntervalCount; } long getLastIntervalCount() { return lastIntervalCount; } long getLastTotalCount() { return lastTotalCount; } } static final IntervalCounter newIntervalCounter() { return new IntervalCounter(); } final MetricRegistry registry = new MetricRegistry(); private final Histogram responseTimes = new Histogram(new HdrHistogramReservoir()); private final StatsTimer gcTimerMs = new StatsTimer() { private final List gcBeans = ManagementFactory.getGarbageCollectorMXBeans(); @Override long getInstantTime() { long gcDurationMs = 0; for (final GarbageCollectorMXBean bean : gcBeans) { gcDurationMs += bean.getCollectionTime(); } return gcDurationMs; } }; private final StatsTimer timerMs = new StatsTimer() { @Override long getInstantTime() { return System.currentTimeMillis(); } }; IntervalCounter waitDurationNsCount; IntervalCounter successCount; private IntervalCounter operationCount; private IntervalCounter errorCount; private IntervalCounter durationMsCount; private final ConsoleApplication app; private final double[] percentiles; private final PerformanceRunner performanceRunner; private final RateReporter reporter; private long startTimeMs; private volatile boolean warmingUp; private final ScheduledExecutorService statThreadScheduler = Executors.newSingleThreadScheduledExecutor(); StatsThread(final PerformanceRunner performanceRunner, final ConsoleApplication application) { super("Stats Thread"); resetStats(); this.performanceRunner = performanceRunner; this.app = application; this.percentiles = performanceRunner.getPercentiles(); this.reporter = app.isScriptFriendly() ? new CsvRateReporter() : new ConsoleRateReporter(); registerStats(); } /** Resets both general and recent statistic indicators. */ final void resetStats() { errorCount = newIntervalCounter(); operationCount = newIntervalCounter(); successCount = newIntervalCounter(); waitDurationNsCount = newIntervalCounter(); durationMsCount = newIntervalCounter(); resetAdditionalStats(); } private void registerStats() { if (app.isScriptFriendly()) { registry.register(TIME_NOW, new RatioGauge() { @Override protected Ratio getRatio() { return Ratio.of(System.currentTimeMillis() - startTimeMs, MS_IN_S); } }); } registry.register(RECENT_THROUGHPUT, new RatioGauge() { @Override protected Ratio getRatio() { return Ratio.of(successCount.getLastIntervalCount() + errorCount.getLastIntervalCount(), durationMsCount.getLastIntervalCount() / MS_IN_S); } }); registry.register(AVERAGE_THROUGHPUT, new RatioGauge() { @Override protected Ratio getRatio() { return Ratio.of(successCount.getLastTotalCount() + errorCount.getLastTotalCount(), durationMsCount.getLastTotalCount() / MS_IN_S); } }); registry.register(RECENT_RESPONSE_TIME_MS, new RatioGauge() { @Override protected Ratio getRatio() { return Ratio.of((waitDurationNsCount.getLastIntervalCount() / NS_IN_MS) - gcTimerMs.elapsed(), successCount.getLastIntervalCount() + errorCount.getLastIntervalCount()); } }); registry.register(AVERAGE_RESPONSE_TIME_MS, new RatioGauge() { @Override protected Ratio getRatio() { return Ratio.of((waitDurationNsCount.getLastTotalCount() / NS_IN_MS) - gcTimerMs.getInstantTime(), successCount.getLastTotalCount() + errorCount.getLastTotalCount()); } }); registry.register(ERROR_PER_SECOND, new RatioGauge() { @Override protected Ratio getRatio() { return Ratio.of(errorCount.getLastIntervalCount(), durationMsCount.getLastIntervalCount() / MS_IN_S); } }); registry.register(PERCENTILES, responseTimes); } void startReporting() throws InterruptedException { warmUp(); init(); final long statsIntervalMs = performanceRunner.getStatsInterval(); statThreadScheduler.scheduleAtFixedRate(this, statsIntervalMs, statsIntervalMs, TimeUnit.MILLISECONDS); } private void warmUp() throws InterruptedException { final long warmUpDurationMs = performanceRunner.getWarmUpDurationMs(); if (warmUpDurationMs > 0) { if (!app.isScriptFriendly()) { app.println(INFO_TOOL_WARMING_UP.get(warmUpDurationMs / TimeUnit.SECONDS.toMillis(1))); } Thread.sleep(warmUpDurationMs); resetStats(); } warmingUp = false; } private void init() { reporter.printTitle(); timerMs.start(); gcTimerMs.start(); startTimeMs = System.currentTimeMillis(); } public void stopRecording(final boolean stoppedByError) { statThreadScheduler.shutdown(); if (!stoppedByError) { // If stats thread is printing stats, wait for it to finish and print a last line of stats. try { statThreadScheduler.awaitTermination(50, TimeUnit.MILLISECONDS); } catch (InterruptedException ignored) { // Do nothing. } run(); } } /** Performs stat snapshots and reports results to application. */ @Override public void run() { durationMsCount.inc(timerMs.reset() - gcTimerMs.reset()); durationMsCount.refreshIntervalCount(); operationCount.refreshIntervalCount(); successCount.refreshIntervalCount(); errorCount.refreshIntervalCount(); waitDurationNsCount.refreshIntervalCount(); reporter.report(); } void addResponseTime(final long responseTimeNs) { // The computed response time might be negative if the difference between the two // System.nanoTime() calls (Just before sending the request and right after receiving the response) // is incoherent. See OPENDJ-2968 for more details. if (!warmingUp && responseTimeNs >= 0) { responseTimes.update(responseTimeNs); waitDurationNsCount.inc(responseTimeNs); } } void incrementFailedCount() { errorCount.inc(); } void incrementSuccessCount() { successCount.inc(); } void incrementOperationCount() { operationCount.inc(); } /** Child classes which manage additional stats need to override this method. */ List registerAdditionalColumns() { return Collections.emptyList(); } /** Do nothing by default, child classes which manage additional stats need to override this method. */ void resetAdditionalStats() { } }