From: Robert Varga Date: Thu, 11 Sep 2014 14:25:58 +0000 (+0200) Subject: BUG-1813: fix DurationStatsTracker performance X-Git-Tag: release/helium~31 X-Git-Url: https://git.opendaylight.org/gerrit/gitweb?a=commitdiff_plain;h=1a4c03a2a3d9aea1605fa7de5a27b6aea6d2f1fe;p=yangtools.git BUG-1813: fix DurationStatsTracker performance This fixes the performance issues without affecting the behaviour in the contended case. This lowers the overhead by moving to an LongAdder, splitting out the duration/timestamp structure and moving the division into the read path. A follow-up patch will rework the code organization to allow for two different implementations, where this one is useful for highly-contented deployments. The other implementation will use synchronized block and be useful for things which are not likely to be contended. Change-Id: Ic8a1d5df9d1d64460670723bac7e644733237ef7 Signed-off-by: Robert Varga --- diff --git a/common/util/src/main/java/org/opendaylight/yangtools/util/DurationStatsTracker.java b/common/util/src/main/java/org/opendaylight/yangtools/util/DurationStatsTracker.java index 9a29dca6a8..033625c4c7 100644 --- a/common/util/src/main/java/org/opendaylight/yangtools/util/DurationStatsTracker.java +++ b/common/util/src/main/java/org/opendaylight/yangtools/util/DurationStatsTracker.java @@ -12,34 +12,43 @@ import static java.util.concurrent.TimeUnit.MICROSECONDS; import static java.util.concurrent.TimeUnit.MILLISECONDS; import static java.util.concurrent.TimeUnit.NANOSECONDS; import static java.util.concurrent.TimeUnit.SECONDS; - -import com.google.common.util.concurrent.AtomicDouble; import java.text.DecimalFormat; import java.text.DecimalFormatSymbols; import java.util.Date; import java.util.concurrent.TimeUnit; -import java.util.concurrent.atomic.AtomicLong; +import java.util.concurrent.atomic.AtomicLongFieldUpdater; +import java.util.concurrent.atomic.AtomicReferenceFieldUpdater; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; /** * Class that calculates and tracks time duration statistics. * * @author Thomas Pantelis + * @author Robert Varga */ public class DurationStatsTracker { - - private static final DecimalFormat decimalFormat; - - private final AtomicLong totalDurations = new AtomicLong(); - private final AtomicLong longestDuration = new AtomicLong(); - private volatile long timeOfLongestDuration; - private final AtomicLong shortestDuration = new AtomicLong(Long.MAX_VALUE); - private volatile long timeOfShortestDuration; - private final AtomicDouble averageDuration = new AtomicDouble(); + private static final AtomicReferenceFieldUpdater LONGEST_UPDATER = + AtomicReferenceFieldUpdater.newUpdater(DurationStatsTracker.class, DurationWithTime.class, "longest"); + private static final AtomicReferenceFieldUpdater SHORTEST_UPDATER = + AtomicReferenceFieldUpdater.newUpdater(DurationStatsTracker.class, DurationWithTime.class, "shortest"); + private static final AtomicLongFieldUpdater COUNT_UPDATER = + AtomicLongFieldUpdater.newUpdater(DurationStatsTracker.class, "count"); + private static final AtomicLongFieldUpdater SUM_UPDATER = + AtomicLongFieldUpdater.newUpdater(DurationStatsTracker.class, "sum"); + + private static final Logger LOG = LoggerFactory.getLogger(DurationStatsTracker.class); + private static final DecimalFormat DECIMAL_FORMAT; + + private volatile long sum = 0; + private volatile long count = 0; + private volatile DurationWithTime longest = null; + private volatile DurationWithTime shortest = null; static { final DecimalFormatSymbols symbols = DecimalFormatSymbols.getInstance(); symbols.setDecimalSeparator('.'); - decimalFormat = new DecimalFormat("0.00", symbols); + DECIMAL_FORMAT = new DecimalFormat("0.00", symbols); } /** @@ -48,30 +57,39 @@ public class DurationStatsTracker { * @param duration * the duration in nanoseconds. */ - public void addDuration(long duration) { - - double currentAve = averageDuration.get(); - long currentTotal = totalDurations.get(); - - long newTotal = currentTotal + 1; - - // Calculate moving cumulative average. - double newAve = currentAve * currentTotal / newTotal + (double) duration / (double) newTotal; - - averageDuration.compareAndSet(currentAve, newAve); - totalDurations.compareAndSet(currentTotal, newTotal); - - long longest = longestDuration.get(); - if (duration > longest) { - if (longestDuration.compareAndSet(longest, duration)) { - timeOfLongestDuration = System.currentTimeMillis(); + public void addDuration(final long duration) { + // First update the quick stats + SUM_UPDATER.addAndGet(this, duration); + COUNT_UPDATER.incrementAndGet(this); + + /* + * Now the hairy 'min/max' things. The notion of "now" we cache, + * so the first time we use it, we do not call it twice. We populate + * it lazily, though. + * + * The longest/shortest stats both are encapsulated in an object, + * so we update them atomically and we minimize the number of volatile + * operations. + */ + DurationWithTime current = shortest; + if (current == null || current.getDuration() > duration) { + final DurationWithTime newObj = new DurationWithTime(duration, System.currentTimeMillis()); + while (!SHORTEST_UPDATER.compareAndSet(this, current, newObj)) { + current = shortest; + if (current != null && current.getDuration() <= duration) { + break; + } } } - long shortest = shortestDuration.get(); - if (duration < shortest) { - if (shortestDuration.compareAndSet(shortest, duration)) { - timeOfShortestDuration = System.currentTimeMillis(); + current = longest; + if (current == null || current.getDuration() < duration) { + final DurationWithTime newObj = new DurationWithTime(duration, System.currentTimeMillis()); + while (!LONGEST_UPDATER.compareAndSet(this, current, newObj)) { + current = longest; + if (current != null && current.getDuration() >= duration) { + break; + } } } } @@ -80,55 +98,63 @@ public class DurationStatsTracker { * Returns the total number of tracked durations. */ public long getTotalDurations() { - return totalDurations.get(); + return count; + } + + private static long getDuration(final DurationWithTime current) { + return current == null ? 0L : current.getDuration(); + } + + private static long getTimeMillis(final DurationWithTime current) { + return current == null ? 0L : current.getTimeMillis(); } /** * Returns the longest duration in nanoseconds. */ public long getLongestDuration() { - return longestDuration.get(); + return getDuration(longest); } /** * Returns the shortest duration in nanoseconds. */ public long getShortestDuration() { - long shortest = shortestDuration.get(); - return shortest < Long.MAX_VALUE ? shortest : 0; + return getDuration(shortest); } /** * Returns the average duration in nanoseconds. */ public double getAverageDuration() { - return averageDuration.get(); + final long mySum = sum; + final long myCount = count; + + return myCount == 0 ? 0 : ((double) mySum) / myCount; } /** * Returns the time stamp of the longest duration. */ public long getTimeOfLongestDuration() { - return timeOfLongestDuration; + return getTimeMillis(longest); } /** * Returns the time stamp of the shortest duration. */ public long getTimeOfShortestDuration() { - return timeOfShortestDuration; + return getTimeMillis(shortest); } /** * Resets all statistics back to their defaults. */ - public void reset() { - totalDurations.set(0); - longestDuration.set(0); - timeOfLongestDuration = 0; - shortestDuration.set(Long.MAX_VALUE); - timeOfShortestDuration = 0; - averageDuration.set(0.0); + public synchronized void reset() { + longest = null; + shortest = null; + count = 0; + sum = 0; } /** @@ -136,7 +162,7 @@ public class DurationStatsTracker { * "12.34 ms". */ public String getDisplayableAverageDuration() { - return formatDuration(getAverageDuration(), 0); + return formatDuration(getAverageDuration(), null); } /** @@ -144,7 +170,7 @@ public class DurationStatsTracker { * date/time at which it occurred, e.g. "12.34 ms at 08/02/2014 12:30:24". */ public String getDisplayableShortestDuration() { - return formatDuration(getShortestDuration(), getTimeOfShortestDuration()); + return formatDuration(shortest); } /** @@ -152,42 +178,56 @@ public class DurationStatsTracker { * date/time at which it occurred, e.g. "12.34 ms at 08/02/2014 12:30:24". */ public String getDisplayableLongestDuration() { - return formatDuration(getLongestDuration(), getTimeOfLongestDuration()); + return formatDuration(longest); } /** * Returns formatted value of number, e.g. "12.34". Always is used dot as * decimal separator. */ - private static synchronized String formatDecimalValue(double value) { - return decimalFormat.format(value); + private static synchronized String formatDecimalValue(final double value) { + return DECIMAL_FORMAT.format(value); + } + + private static String formatDuration(final DurationWithTime current) { + if (current != null) { + return formatDuration(current.getDuration(), current.getTimeMillis()); + } else { + return formatDuration(0, null); + } } - private String formatDuration(double duration, long timeStamp) { - TimeUnit unit = chooseUnit((long) duration); - double value = duration / NANOSECONDS.convert(1, unit); + private static String formatDuration(final double duration, final Long timeStamp) { + final TimeUnit unit = chooseUnit((long) duration); + final double value = duration / NANOSECONDS.convert(1, unit); + + final StringBuilder sb = new StringBuilder(); + sb.append(formatDecimalValue(value)); + sb.append(' '); + sb.append(abbreviate(unit)); - return timeStamp > 0 ? String.format("%s %s at %3$tD %3$tT", formatDecimalValue(value), abbreviate(unit), - new Date(timeStamp)) : String.format("%s %s", formatDecimalValue(value), abbreviate(unit)); + if (timeStamp != null) { + sb.append(String.format(" at %1$tD %1$tT", new Date(timeStamp))); + } + + return sb.toString(); } - private static TimeUnit chooseUnit(long nanos) { - if (SECONDS.convert(nanos, NANOSECONDS) > 0) { + private static TimeUnit chooseUnit(final long nanos) { + // TODO: this could be inlined, as we are doing needless divisions + if (NANOSECONDS.toSeconds(nanos) > 0) { return SECONDS; } - - if (MILLISECONDS.convert(nanos, NANOSECONDS) > 0) { + if (NANOSECONDS.toMillis(nanos) > 0) { return MILLISECONDS; } - - if (MICROSECONDS.convert(nanos, NANOSECONDS) > 0) { + if (NANOSECONDS.toMicros(nanos) > 0) { return MICROSECONDS; } - return NANOSECONDS; } - private static String abbreviate(TimeUnit unit) { + private static String abbreviate(final TimeUnit unit) { switch (unit) { case NANOSECONDS: return "ns"; @@ -197,8 +237,15 @@ public class DurationStatsTracker { return "ms"; case SECONDS: return "s"; - default: - return ""; + case MINUTES: + return "m"; + case HOURS: + return "h"; + case DAYS: + return "d"; } + + LOG.warn("Unhandled time unit {}", unit); + return ""; } } diff --git a/common/util/src/main/java/org/opendaylight/yangtools/util/DurationWithTime.java b/common/util/src/main/java/org/opendaylight/yangtools/util/DurationWithTime.java new file mode 100644 index 0000000000..aa77678206 --- /dev/null +++ b/common/util/src/main/java/org/opendaylight/yangtools/util/DurationWithTime.java @@ -0,0 +1,29 @@ +/* + * Copyright (c) 2014 Cisco Systems, Inc. and others. All rights reserved. + * + * This program and the accompanying materials are made available under the + * terms of the Eclipse Public License v1.0 which accompanies this distribution, + * and is available at http://www.eclipse.org/legal/epl-v10.html + */ +package org.opendaylight.yangtools.util; + +/** + * Utility holder for a duration/time of occurance. + */ +final class DurationWithTime { + private final long duration; + private final long timeMillis; + + DurationWithTime(final long duration, final long timeMillis) { + this.duration = duration; + this.timeMillis = timeMillis; + } + + long getDuration() { + return duration; + } + + long getTimeMillis() { + return timeMillis; + } +} \ No newline at end of file