Hi, I think you need to use a higher clock-drift interval. IIUC, you currently use 1 second. but on some machines, the System.getTimeMillis() can be as inaccurate than 2 seconds.
however, since a long can hold up to more than 200 years of nano-seconds, I don't think we need an accurate system time measurement for the benchmarks. and I wouldn't use System.getTimeMillis() at all. also, using a background task, that executes every MS is IMO a overhead. regards, toby On Thu, Mar 6, 2014 at 1:29 PM, <[email protected]> wrote: > Author: jukka > Date: Thu Mar 6 21:29:28 2014 > New Revision: 1575050 > > URL: http://svn.apache.org/r1575050 > Log: > OAK-1418: Read performance regression > > Delegate time-keeping to a background task > > Added: > > jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/stats/Clock.java > (with props) > Modified: > > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java > > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/repository/RepositoryImpl.java > > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/RefreshStrategy.java > > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/SessionStats.java > > Added: > jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/stats/Clock.java > URL: > http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/stats/Clock.java?rev=1575050&view=auto > ============================================================================== > --- > jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/stats/Clock.java > (added) > +++ > jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/stats/Clock.java > Thu Mar 6 21:29:28 2014 > @@ -0,0 +1,95 @@ > +/* > + * Licensed to the Apache Software Foundation (ASF) under one or more > + * contributor license agreements. See the NOTICE file distributed with > + * this work for additional information regarding copyright ownership. > + * The ASF licenses this file to You under the Apache License, Version 2.0 > + * (the "License"); you may not use this file except in compliance with > + * the License. You may obtain a copy of the License at > + * > + * http://www.apache.org/licenses/LICENSE-2.0 > + * > + * Unless required by applicable law or agreed to in writing, software > + * distributed under the License is distributed on an "AS IS" BASIS, > + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. > + * See the License for the specific language governing permissions and > + * limitations under the License. > + */ > +package org.apache.jackrabbit.oak.stats; > + > +import java.util.concurrent.ScheduledExecutorService; > +import java.util.concurrent.TimeUnit; > + > +/** > + * Mechanism for keeping track of time at millisecond accuracy. > + */ > +public interface Clock { > + > + /** > + * Returns the current time in milliseconds. > + * > + * @see System#currentTimeMillis() > + * @return current time in milliseconds > + */ > + long getTime(); > + > + /** > + * Simple clock implementation based on {@link > System#currentTimeMillis()}, > + * which is known to be rather slow on some platforms. > + */ > + Clock SIMPLE = new Clock() { > + @Override > + public long getTime() { > + return System.currentTimeMillis(); > + } > + }; > + > + /** > + * Accurate clock implementation that uses interval timings from the > + * {@link System#nanoTime()} method to calculate an as accurate as > possible > + * time based on occasional calls to {@link System#currentTimeMillis()} > + * to prevent clock drift. > + */ > + Clock ACCURATE = new Clock() { > + private static final long NS_IN_MS = 1000000; > + private static final long NS_IN_S = NS_IN_MS * 1000; > + private volatile long ms = System.currentTimeMillis(); > + private volatile long ns = System.nanoTime(); > + @Override > + public long getTime() { > + long diff = System.nanoTime() - ns; > + if (diff < NS_IN_S) { > + return ms + diff / NS_IN_MS; > + } else { > + ms = System.currentTimeMillis(); > + ns = System.nanoTime(); > + return ms; > + } > + } > + }; > + > + /** > + * Fast clock implementation whose {@link #getTime()} method returns > + * instantaneously thanks to a background task that takes care of the > + * actual time-keeping work. > + */ > + public static class Fast implements Clock { > + > + private volatile long time = ACCURATE.getTime(); > + > + public Fast(ScheduledExecutorService executor) { > + executor.scheduleAtFixedRate(new Runnable() { > + @Override > + public void run() { > + time = ACCURATE.getTime(); > + } > + }, 1, 1, TimeUnit.MILLISECONDS); > + } > + > + @Override > + public long getTime() { > + return time; > + } > + > + } > + > +} > \ No newline at end of file > > Propchange: > jackrabbit/oak/trunk/oak-core/src/main/java/org/apache/jackrabbit/oak/stats/Clock.java > ------------------------------------------------------------------------------ > svn:eol-style = native > > Modified: > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java > URL: > http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java?rev=1575050&r1=1575049&r2=1575050&view=diff > ============================================================================== > --- > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java > (original) > +++ > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/SessionDelegate.java > Thu Mar 6 21:29:28 2014 > @@ -17,8 +17,9 @@ > package org.apache.jackrabbit.oak.jcr.delegate; > > import static com.google.common.base.Preconditions.checkNotNull; > -import static java.lang.System.currentTimeMillis; > -import static java.lang.System.nanoTime; > +import static java.util.concurrent.TimeUnit.MILLISECONDS; > +import static java.util.concurrent.TimeUnit.NANOSECONDS; > +import static java.util.concurrent.TimeUnit.SECONDS; > import static > org.apache.jackrabbit.api.stats.RepositoryStatistics.Type.SESSION_READ_COUNTER; > import static > org.apache.jackrabbit.api.stats.RepositoryStatistics.Type.SESSION_READ_DURATION; > import static > org.apache.jackrabbit.api.stats.RepositoryStatistics.Type.SESSION_WRITE_COUNTER; > @@ -51,6 +52,7 @@ import org.apache.jackrabbit.oak.jcr.ses > import org.apache.jackrabbit.oak.jcr.session.SessionStats; > import org.apache.jackrabbit.oak.jcr.session.operation.SessionOperation; > import org.apache.jackrabbit.oak.plugins.identifier.IdentifierManager; > +import org.apache.jackrabbit.oak.stats.Clock; > import org.apache.jackrabbit.oak.stats.StatisticManager; > import org.slf4j.Logger; > import org.slf4j.LoggerFactory; > @@ -87,14 +89,15 @@ public class SessionDelegate { > private final IdentifierManager idManager; > private final SessionStats sessionStats; > > + private final Clock clock; > + > // access time stamps and counters for statistics about this session > - private final long loginTimeMS = currentTimeMillis(); > - private final long loginTimeNS = nanoTime(); > - private long lastAccessTimeNS = loginTimeNS; > - private long readTimeNS = loginTimeNS; > - private long writeTimeNS = loginTimeNS; > - private long refreshTimeNS = loginTimeNS; > - private long saveTimeNS = loginTimeNS; > + private final long loginTime; > + private long accessTime; > + private long readTime = 0; > + private long writeTime = 0; > + private long refreshTime = 0; > + private long saveTime = 0; > private long readCount = 0; > private long writeCount = 0; > private long refreshCount = 0; > @@ -128,7 +131,8 @@ public class SessionDelegate { > @Nonnull ContentSession contentSession, > @Nonnull RefreshStrategy refreshStrategy, > @Nonnull ThreadLocal<Long> threadSaveCount, > - @Nonnull StatisticManager statisticManager) { > + @Nonnull StatisticManager statisticManager, > + @Nonnull Clock clock) { > this.contentSession = checkNotNull(contentSession); > this.refreshStrategy = checkNotNull(refreshStrategy); > this.threadSaveCount = checkNotNull(threadSaveCount); > @@ -136,6 +140,9 @@ public class SessionDelegate { > this.root = contentSession.getLatestRoot(); > this.idManager = new IdentifierManager(root); > this.sessionStats = new SessionStats(this); > + this.clock = checkNotNull(clock); > + this.loginTime = clock.getTime(); > + this.accessTime = loginTime; > checkNotNull(statisticManager); > readCounter = statisticManager.getCounter(SESSION_READ_COUNTER); > readDuration = statisticManager.getCounter(SESSION_READ_DURATION); > @@ -153,41 +160,36 @@ public class SessionDelegate { > return c == null ? 0 : c; > } > > - public long getNanosecondsSinceLastAccess() { > - return nanoTime() - lastAccessTimeNS; > - } > - > - public long getNanosecondsSinceLogin() { > - return nanoTime() - loginTimeNS; > + public long getSecondsSinceLogin() { > + return SECONDS.convert(clock.getTime() - loginTime, MILLISECONDS); > } > > public Date getLoginTime() { > - return new Date(loginTimeMS); > + return new Date(loginTime); > } > > - private Date getTime(long ns) { > - long nsSinceStart = ns - loginTimeNS; > - if (nsSinceStart > 0) { > - return new Date(loginTimeMS + nsSinceStart / 1000000); > + private Date getTime(long timestamp) { > + if (timestamp != 0) { > + return new Date(timestamp); > } else { > return null; > } > } > > public Date getReadTime() { > - return getTime(readTimeNS); > + return getTime(readTime); > } > > public Date getWriteTime() { > - return getTime(writeTimeNS); > + return getTime(writeTime); > } > > public Date getRefreshTime() { > - return getTime(refreshTimeNS); > + return getTime(refreshTime); > } > > public Date getSaveTime() { > - return getTime(saveTimeNS); > + return getTime(saveTime); > } > > public long getReadCount() { > @@ -236,7 +238,7 @@ public class SessionDelegate { > public synchronized <T> T perform(SessionOperation<T> sessionOperation) > throws RepositoryException { > // Synchronize to avoid conflicting refreshes from concurrent JCR > API calls > - long t0 = nanoTime(); > + long t0 = clock.getTime(); > if (sessionOpCount == 0) { > // Refresh and precondition checks only for non re-entrant > // session operations. Don't refresh if this operation is a > @@ -247,7 +249,8 @@ public class SessionDelegate { > && !sessionOperation.isLogout() > && (refreshAtNextAccess > || sessionSaveCount != getThreadSaveCount() > - || refreshStrategy.needsRefresh(t0 - > lastAccessTimeNS))) { > + || refreshStrategy.needsRefresh( > + SECONDS.convert(t0 - accessTime, > MILLISECONDS)))) { > refresh(true); > refreshAtNextAccess = false; > sessionSaveCount = getThreadSaveCount(); > @@ -261,17 +264,17 @@ public class SessionDelegate { > logOperationDetails(sessionOperation); > return result; > } finally { > - lastAccessTimeNS = t0; > - long dt = nanoTime() - t0; > + accessTime = t0; > + long dt = NANOSECONDS.convert(clock.getTime() - t0, > MILLISECONDS); > sessionOpCount--; > if (sessionOperation.isUpdate()) { > - writeTimeNS = t0; > + writeTime = t0; > writeCount++; > writeCounter.incrementAndGet(); > writeDuration.addAndGet(dt); > updateCount++; > } else { > - readTimeNS = t0; > + readTime = t0; > readCount++; > readCounter.incrementAndGet(); > readDuration.addAndGet(dt); > @@ -491,7 +494,7 @@ public class SessionDelegate { > * @throws RepositoryException > */ > public void save(String path) throws RepositoryException { > - saveTimeNS = nanoTime(); > + saveTime = clock.getTime(); > saveCount++; > try { > commit(root, path); > @@ -503,7 +506,7 @@ public class SessionDelegate { > } > > public void refresh(boolean keepChanges) { > - refreshTimeNS = nanoTime(); > + refreshTime = clock.getTime(); > refreshCount++; > if (keepChanges && hasPendingChanges()) { > root.rebase(); > @@ -556,7 +559,7 @@ public class SessionDelegate { > throw new RepositoryException("Cannot move node at " + > srcPath + " to " + destPath); > } > if (!transientOp) { > - saveTimeNS = nanoTime(); > + saveTime = clock.getTime(); > saveCount++; > commit(moveRoot); > refresh(true); > > Modified: > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/repository/RepositoryImpl.java > URL: > http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/repository/RepositoryImpl.java?rev=1575050&r1=1575049&r2=1575050&view=diff > ============================================================================== > --- > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/repository/RepositoryImpl.java > (original) > +++ > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/repository/RepositoryImpl.java > Thu Mar 6 21:29:28 2014 > @@ -47,6 +47,7 @@ import org.apache.jackrabbit.commons.Sim > import org.apache.jackrabbit.oak.api.ContentRepository; > import org.apache.jackrabbit.oak.api.ContentSession; > import org.apache.jackrabbit.oak.api.jmx.SessionMBean; > +import org.apache.jackrabbit.oak.stats.Clock; > import org.apache.jackrabbit.oak.stats.StatisticManager; > import org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate; > import org.apache.jackrabbit.oak.jcr.session.RefreshStrategy; > @@ -83,6 +84,8 @@ public class RepositoryImpl implements J > protected final Whiteboard whiteboard; > private final SecurityProvider securityProvider; > > + private final Clock clock; > + > /** > * {@link ThreadLocal} counter that keeps track of the save operations > * performed per thread so far. This is is then used to determine if > @@ -108,6 +111,7 @@ public class RepositoryImpl implements J > this.securityProvider = checkNotNull(securityProvider); > this.descriptors = determineDescriptors(); > this.statisticManager = new StatisticManager(whiteboard, > scheduledExecutor); > + this.clock = new Clock.Fast(scheduledExecutor); > } > > //---------------------------------------------------------< Repository > >--- > @@ -246,7 +250,7 @@ public class RepositoryImpl implements J > final ContentSession contentSession) { > return new SessionDelegate( > contentSession, refreshStrategy, > - threadSaveCount, statisticManager) { > + threadSaveCount, statisticManager, clock) { > // Defer session MBean registration to avoid cluttering the > // JMX name space with short lived sessions > ListenableScheduledFuture<Registration> registration = > scheduledExecutor.schedule( > > Modified: > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/RefreshStrategy.java > URL: > http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/RefreshStrategy.java?rev=1575050&r1=1575049&r2=1575050&view=diff > ============================================================================== > --- > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/RefreshStrategy.java > (original) > +++ > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/RefreshStrategy.java > Thu Mar 6 21:29:28 2014 > @@ -16,11 +16,9 @@ > * specific language governing permissions and limitations > * under the License. > */ > - > package org.apache.jackrabbit.oak.jcr.session; > > import static java.util.concurrent.TimeUnit.MINUTES; > -import static java.util.concurrent.TimeUnit.NANOSECONDS; > import static java.util.concurrent.TimeUnit.SECONDS; > > import org.slf4j.Logger; > @@ -46,10 +44,10 @@ public interface RefreshStrategy { > * individual refresh strategies passed to the constructor returns > * {@code true}. > * > - * @param nanosecondsSinceLastAccess nanoseconds since last access > + * @param secondsSinceLastAccess seconds since last access > * @return {@code true} if and only if the session needs to refresh. > */ > - boolean needsRefresh(long nanosecondsSinceLastAccess); > + boolean needsRefresh(long secondsSinceLastAccess); > > /** > * Composite of zero or more {@code RefreshStrategy} instances, > @@ -76,12 +74,12 @@ public interface RefreshStrategy { > * individual refresh strategies passed to the constructor returns > * {@code true}. > * > - * @param nanosecondsSinceLastAccess nanoseconds since last access > + * @param secondsSinceLastAccess seconds since last access > * @return {@code true} if and only if the session needs to refresh. > */ > - public boolean needsRefresh(long nanosecondsSinceLastAccess) { > + public boolean needsRefresh(long secondsSinceLastAccess) { > for (RefreshStrategy r : refreshStrategies) { > - if (r.needsRefresh(nanosecondsSinceLastAccess)) { > + if (r.needsRefresh(secondsSinceLastAccess)) { > return true; > } > } > @@ -102,12 +100,12 @@ public interface RefreshStrategy { > * activity. > */ > public Timed(long interval) { > - this.interval = NANOSECONDS.convert(interval, SECONDS); > + this.interval = interval; > } > > @Override > - public boolean needsRefresh(long nanosecondsSinceLastAccess) { > - return nanosecondsSinceLastAccess > interval; > + public boolean needsRefresh(long secondsSinceLastAccess) { > + return secondsSinceLastAccess > interval; > } > > } > @@ -118,7 +116,7 @@ public interface RefreshStrategy { > * > * TODO replace logging with JMX monitoring. See OAK-941 > */ > - public static class LogOnce implements RefreshStrategy { > + public static class LogOnce extends Timed { > > private static final Logger log = > LoggerFactory.getLogger(RefreshStrategy.class); > @@ -126,8 +124,6 @@ public interface RefreshStrategy { > private final Exception initStackTrace = > new Exception("The session was created here:"); > > - private final long interval; > - > private boolean warnIfIdle = true; > > /** > @@ -135,19 +131,19 @@ public interface RefreshStrategy { > * activity. > */ > public LogOnce(long interval) { > - this.interval = NANOSECONDS.convert(interval, SECONDS); > + super(interval); > } > > /** > * Log once > - * @param nanosecondsSinceLastAccess nanoseconds since last access > + * @param secondsSinceLastAccess seconds since last access > * @return {@code false} > */ > @Override > - public boolean needsRefresh(long nanosecondsSinceLastAccess) { > - if (nanosecondsSinceLastAccess > interval && warnIfIdle) { > + public boolean needsRefresh(long secondsSinceLastAccess) { > + if (super.needsRefresh(secondsSinceLastAccess) && warnIfIdle) { > log.warn("This session has been idle for " > - + MINUTES.convert(nanosecondsSinceLastAccess, > NANOSECONDS) > + + MINUTES.convert(secondsSinceLastAccess, SECONDS) > + " minutes and might be out of date. " + > "Consider using a fresh session or explicitly > refresh the session.", > initStackTrace); > > Modified: > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/SessionStats.java > URL: > http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/SessionStats.java?rev=1575050&r1=1575049&r2=1575050&view=diff > ============================================================================== > --- > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/SessionStats.java > (original) > +++ > jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/session/SessionStats.java > Thu Mar 6 21:29:28 2014 > @@ -25,7 +25,6 @@ import java.util.Collections; > import java.util.Date; > import java.util.Map; > import java.util.Map.Entry; > -import java.util.concurrent.TimeUnit; > import java.util.concurrent.atomic.AtomicReference; > > import javax.jcr.RepositoryException; > @@ -35,7 +34,6 @@ import org.apache.jackrabbit.oak.api.jmx > import org.apache.jackrabbit.oak.jcr.delegate.SessionDelegate; > > public class SessionStats implements SessionMBean { > - private static final long EPS = TimeUnit.MILLISECONDS.convert(1, > TimeUnit.SECONDS); > > private final Exception initStackTrace = new Exception("The session was > opened here:"); > > @@ -178,8 +176,8 @@ public class SessionStats implements Ses > } > > private double calculateRate(long count) { > - double dt = delegate.getNanosecondsSinceLogin() / 1000000; > - if (dt > EPS) { > + double dt = delegate.getSecondsSinceLogin(); > + if (dt > 0) { > return count / dt; > } else { > return Double.NaN; > >
