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;
