jackrabbit-oak-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From ju...@apache.org
Subject svn commit: r1575050 - in /jackrabbit/oak/trunk: oak-core/src/main/java/org/apache/jackrabbit/oak/stats/ oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/delegate/ oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/repository/ oak-jcr/src/main/java...
Date Thu, 06 Mar 2014 21:29:28 GMT
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;



Mime
View raw message