Author: mreutegg Date: Fri Jul 17 07:50:46 2020 New Revision: 1879987 URL: http://svn.apache.org/viewvc?rev=1879987&view=rev Log: OAK-9139: Log message on frozen node lookup by identifier
Apply changed proposed in https://github.com/apache/jackrabbit-oak/pull/241 Added: jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLogger.java (with props) jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLoggerTest.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 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=1879987&r1=1879986&r2=1879987&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 Fri Jul 17 07:50:46 2020 @@ -454,7 +454,15 @@ public class SessionDelegate { @Nullable public NodeDelegate getNodeByIdentifier(String id) { Tree tree = idManager.getTree(id); - return (tree == null || !tree.exists()) ? null : new NodeDelegate(this, tree); + if (tree == null || !tree.exists()) { + return null; + } else { + treeLookedUpByIdentifier(tree); + return new NodeDelegate(this, tree); + } + } + + protected void treeLookedUpByIdentifier(@NotNull Tree tree) { } /** 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=1879987&r1=1879986&r2=1879987&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 Fri Jul 17 07:50:46 2020 @@ -47,6 +47,7 @@ import org.apache.jackrabbit.api.securit import org.apache.jackrabbit.commons.SimpleValueFactory; import org.apache.jackrabbit.oak.api.ContentRepository; import org.apache.jackrabbit.oak.api.ContentSession; +import org.apache.jackrabbit.oak.api.Tree; import org.apache.jackrabbit.oak.api.blob.BlobAccessProvider; import org.apache.jackrabbit.oak.api.jmx.SessionMBean; import org.apache.jackrabbit.oak.commons.concurrent.ExecutorCloser; @@ -55,6 +56,7 @@ import org.apache.jackrabbit.oak.jcr.ses import org.apache.jackrabbit.oak.jcr.session.RefreshStrategy.Composite; import org.apache.jackrabbit.oak.jcr.session.SessionContext; import org.apache.jackrabbit.oak.jcr.session.SessionStats; +import org.apache.jackrabbit.oak.jcr.version.FrozenNodeLogger; import org.apache.jackrabbit.oak.plugins.observation.CommitRateLimiter; import org.apache.jackrabbit.oak.spi.gc.DelegatingGCMonitor; import org.apache.jackrabbit.oak.spi.gc.GCMonitor; @@ -127,6 +129,8 @@ public class RepositoryImpl implements J private final StatisticManager statisticManager; + private final FrozenNodeLogger frozenNodeLogger; + /** * Constructor used for backward compatibility. */ @@ -157,6 +161,7 @@ public class RepositoryImpl implements J this.fastQueryResultSize = fastQueryResultSize; this.mountInfoProvider = WhiteboardUtils.getService(whiteboard, MountInfoProvider.class); this.blobAccessProvider = WhiteboardUtils.getService(whiteboard, BlobAccessProvider.class); + this.frozenNodeLogger = new FrozenNodeLogger(clock, whiteboard); } //---------------------------------------------------------< Repository >--- @@ -312,6 +317,11 @@ public class RepositoryImpl implements J ScheduledFuture<?> scheduledTask = scheduledExecutor.schedule(registrationTask, 1, TimeUnit.MINUTES); @Override + protected void treeLookedUpByIdentifier(@NotNull Tree tree) { + frozenNodeLogger.lookupById(tree); + } + + @Override public void logout() { refreshOnGC.close(); // Cancel session MBean registration @@ -326,6 +336,7 @@ public class RepositoryImpl implements J public void shutdown() { statisticManager.dispose(); gcMonitorRegistration.unregister(); + frozenNodeLogger.close(); clock.close(); new ExecutorCloser(scheduledExecutor).close(); if (contentRepository instanceof Closeable) { Added: jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLogger.java URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLogger.java?rev=1879987&view=auto ============================================================================== --- jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLogger.java (added) +++ jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLogger.java Fri Jul 17 07:50:46 2020 @@ -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.jcr.version; + +import java.io.Closeable; + +import org.apache.jackrabbit.oak.api.PropertyState; +import org.apache.jackrabbit.oak.api.Tree; +import org.apache.jackrabbit.oak.api.Type; +import org.apache.jackrabbit.oak.spi.toggle.Feature; +import org.apache.jackrabbit.oak.spi.whiteboard.Whiteboard; +import org.apache.jackrabbit.oak.stats.Clock; +import org.jetbrains.annotations.NotNull; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + +import static com.google.common.base.Preconditions.checkNotNull; +import static org.apache.jackrabbit.JcrConstants.JCR_PRIMARYTYPE; +import static org.apache.jackrabbit.JcrConstants.NT_FROZENNODE; +import static org.apache.jackrabbit.oak.spi.toggle.Feature.newFeature; + +/** + * Logger facility for frozen node lookups by identifier. Calls to + * {@link #lookupById(Tree)} first check the feature toggle + * {@code oak.logFrozenNodeLookup} and then whether the given {@code Tree} is of + * type {@code nt:frozenNode} in which case the path of the tree is logged at + * INFO. Log messages are rate limited to one per second. If multiple frozen + * nodes are looked up by identifier with the period of one second, then only + * the first lookup is logged; the other lookups are not logged. + * Enabling DEBUG level for this class reveals the stack of the calling thread. + */ +public class FrozenNodeLogger implements Closeable { + + private static final Logger log = LoggerFactory.getLogger(FrozenNodeLogger.class); + + private static final long LOG_INTERVAL = Long.getLong("oak.frozenNodeLogger.minInterval", 1000); + + private static long NO_MESSAGE_UNTIL = 0; + + private final Clock clock; + + private final Feature feature; + + public FrozenNodeLogger(@NotNull Clock clock, + @NotNull Whiteboard whiteboard) { + this.clock = checkNotNull(clock); + this.feature = newFeature("OAK-9139_log_frozen_node_lookup", whiteboard); + } + + public final void lookupById(@NotNull Tree tree) { + if (!feature.isEnabled()) { + return; + } + PropertyState primaryType = tree.getProperty(JCR_PRIMARYTYPE); + if (primaryType != null + && !primaryType.isArray() + && primaryType.getValue(Type.STRING).equals(NT_FROZENNODE)) { + long now = clock.getTime(); + synchronized (FrozenNodeLogger.class) { + if (now >= NO_MESSAGE_UNTIL) { + NO_MESSAGE_UNTIL = now + LOG_INTERVAL; + logFrozenNode(tree); + } + } + } + } + + @Override + public void close() { + feature.close(); + } + + protected void logFrozenNode(Tree tree) { + log.info("Frozen node {} looked up by id", tree.getPath()); + if (log.isDebugEnabled()) { + log.debug("Frozen node lookup call stack", new Exception()); + } + } +} Propchange: jackrabbit/oak/trunk/oak-jcr/src/main/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLogger.java ------------------------------------------------------------------------------ svn:eol-style = native Added: jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLoggerTest.java URL: http://svn.apache.org/viewvc/jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLoggerTest.java?rev=1879987&view=auto ============================================================================== --- jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLoggerTest.java (added) +++ jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLoggerTest.java Fri Jul 17 07:50:46 2020 @@ -0,0 +1,127 @@ +/* + * 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.jcr.version; + +import java.lang.reflect.Field; +import java.util.concurrent.Callable; +import java.util.concurrent.atomic.AtomicLong; + +import org.apache.jackrabbit.oak.api.Tree; +import org.apache.jackrabbit.oak.api.Type; +import org.apache.jackrabbit.oak.plugins.memory.EmptyNodeState; +import org.apache.jackrabbit.oak.plugins.memory.MemoryNodeBuilder; +import org.apache.jackrabbit.oak.plugins.tree.TreeProvider; +import org.apache.jackrabbit.oak.plugins.tree.impl.TreeProviderService; +import org.apache.jackrabbit.oak.spi.toggle.FeatureToggle; +import org.apache.jackrabbit.oak.spi.whiteboard.DefaultWhiteboard; +import org.apache.jackrabbit.oak.spi.whiteboard.Whiteboard; +import org.apache.jackrabbit.oak.spi.whiteboard.WhiteboardUtils; +import org.apache.jackrabbit.oak.stats.Clock; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +import static org.apache.jackrabbit.JcrConstants.JCR_PRIMARYTYPE; +import static org.apache.jackrabbit.JcrConstants.NT_FOLDER; +import static org.apache.jackrabbit.JcrConstants.NT_FROZENNODE; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.fail; + +public class FrozenNodeLoggerTest { + + private final TreeProvider treeProvider = new TreeProviderService(); + + private final Whiteboard whiteboard = new DefaultWhiteboard(); + + private final Clock clock = new Clock.Virtual(); + + private final AtomicLong numMessages = new AtomicLong(); + + private final FrozenNodeLogger logger = new FrozenNodeLogger(clock, whiteboard) { + @Override + protected void logFrozenNode(Tree tree) { + numMessages.incrementAndGet(); + super.logFrozenNode(tree); + } + }; + + private final Tree emptyTree = treeProvider.createReadOnlyTree(EmptyNodeState.EMPTY_NODE); + + private final Tree folderTree = treeProvider.createReadOnlyTree( + new MemoryNodeBuilder(EmptyNodeState.EMPTY_NODE) + .setProperty(JCR_PRIMARYTYPE, NT_FOLDER, Type.NAME) + .getNodeState() + ); + + private final Tree frozenNodeTree = treeProvider.createReadOnlyTree( + new MemoryNodeBuilder(EmptyNodeState.EMPTY_NODE) + .setProperty(JCR_PRIMARYTYPE, NT_FROZENNODE, Type.NAME) + .getNodeState() + ); + + @Before + public void enableLogger() throws Exception { + FeatureToggle toggle = WhiteboardUtils.getService( + whiteboard, FeatureToggle.class); + assertNotNull(toggle); + toggle.setEnabled(true); + Field f = FrozenNodeLogger.class.getDeclaredField("NO_MESSAGE_UNTIL"); + f.setAccessible(true); + f.set(FrozenNodeLogger.class, 0); + } + + @After + public void after() { + logger.close(); + } + + @Test + public void emptyNode() { + assertMessages(() -> { logger.lookupById(emptyTree); return 0; }); + } + + @Test + public void folderNode() { + assertMessages(() -> { logger.lookupById(folderTree); return 0; }); + } + + @Test + public void frozenNode() { + assertMessages(() -> { logger.lookupById(frozenNodeTree); return 1; }); + } + + @Test + public void atMostOncePerSecond() throws Exception { + assertMessages(() -> { logger.lookupById(frozenNodeTree); return 1; }); + assertMessages(() -> { logger.lookupById(frozenNodeTree); return 0; }); + clock.waitUntil(clock.getTime() + 1000); + assertMessages(() -> { logger.lookupById(frozenNodeTree); return 1; }); + } + + private void assertMessages(Callable<Integer> r) { + long num = numMessages.get(); + int expected; + try { + expected = r.call(); + } catch (Exception e) { + fail(e.getMessage()); + expected = -1; + } + assertEquals(expected, numMessages.get() - num); + } +} Propchange: jackrabbit/oak/trunk/oak-jcr/src/test/java/org/apache/jackrabbit/oak/jcr/version/FrozenNodeLoggerTest.java ------------------------------------------------------------------------------ svn:eol-style = native
