From ed885b846b32746eaf5a240edd7fd897ac4b5917 Mon Sep 17 00:00:00 2001 From: Chris Vest Date: Tue, 15 Jan 2019 15:35:26 +0100 Subject: [PATCH] Add a feature toggle that will enable INFO level log output of the counts store update lock. In very rare cases we see threads getting stuck on this lock, and this will help with debugging those cases. --- .../impl/store/counts/CountsTracker.java | 2 +- .../store/kvstore/AbstractKeyValueStore.java | 33 +++---- .../impl/store/kvstore/LockWrapper.java | 91 +++++++++++++++++++ .../kvstore/UpdateLock.java} | 42 +++------ .../kvstore/AbstractKeyValueStoreTest.java | 7 +- ...ckPointerConstraintCreationDeadlockIT.java | 2 +- 6 files changed, 125 insertions(+), 52 deletions(-) create mode 100644 community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/LockWrapper.java rename community/kernel/src/main/java/org/neo4j/kernel/impl/{locking/LockWrapper.java => store/kvstore/UpdateLock.java} (51%) diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/store/counts/CountsTracker.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/counts/CountsTracker.java index a5abcd5acbafd..2ace6d2c0e8cf 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/store/counts/CountsTracker.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/counts/CountsTracker.java @@ -94,7 +94,7 @@ public CountsTracker( final LogProvider logProvider, FileSystemAbstraction fs, P public CountsTracker( final LogProvider logProvider, FileSystemAbstraction fs, PageCache pages, Config config, File baseFile, SystemNanoClock clock, VersionContextSupplier versionContextSupplier ) { - super( fs, pages, baseFile, new CountsTrackerRotationMonitor( logProvider ), + super( fs, pages, baseFile, new CountsTrackerRotationMonitor( logProvider ), logProvider.getLog( CountsTracker.class ).infoLogger(), new RotationTimerFactory( clock, config.get( counts_store_rotation_timeout ).toMillis() ), versionContextSupplier, 16, 16, HEADER_FIELDS ); } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStore.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStore.java index bfccb2a14b663..e17027fa5988b 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStore.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStore.java @@ -22,7 +22,6 @@ import java.io.File; import java.io.IOException; import java.util.Optional; -import java.util.concurrent.locks.ReadWriteLock; import java.util.concurrent.locks.ReentrantReadWriteLock; import java.util.stream.Collectors; import java.util.stream.StreamSupport; @@ -31,12 +30,12 @@ import org.neo4j.io.pagecache.PageCache; import org.neo4j.io.pagecache.impl.FileIsNotMappedException; import org.neo4j.io.pagecache.tracing.cursor.context.VersionContextSupplier; -import org.neo4j.kernel.impl.locking.LockWrapper; import org.neo4j.kernel.impl.store.UnderlyingStorageException; import org.neo4j.kernel.lifecycle.LifecycleAdapter; +import org.neo4j.logging.Logger; -import static org.neo4j.kernel.impl.locking.LockWrapper.readLock; -import static org.neo4j.kernel.impl.locking.LockWrapper.writeLock; +import static org.neo4j.kernel.impl.store.kvstore.LockWrapper.readLock; +import static org.neo4j.kernel.impl.store.kvstore.LockWrapper.writeLock; /** * The base for building a key value store based on rotating immutable @@ -48,10 +47,11 @@ @State( State.Strategy.CONCURRENT_HASH_MAP ) public abstract class AbstractKeyValueStore extends LifecycleAdapter { - private final ReadWriteLock updateLock = new ReentrantReadWriteLock( /*fair=*/true ); + private final UpdateLock updateLock = new UpdateLock(); private final Format format; final RotationStrategy rotationStrategy; private final RotationTimerFactory rotationTimerFactory; + private final Logger logger; volatile ProgressiveState state; private DataInitializer> stateInitializer; private final FileSystemAbstraction fs; @@ -59,7 +59,7 @@ public abstract class AbstractKeyValueStore extends LifecycleAdapter final int valueSize; private volatile boolean stopped; - public AbstractKeyValueStore( FileSystemAbstraction fs, PageCache pages, File base, RotationMonitor monitor, + public AbstractKeyValueStore( FileSystemAbstraction fs, PageCache pages, File base, RotationMonitor monitor, Logger logger, RotationTimerFactory timerFactory, VersionContextSupplier versionContextSupplier, int keySize, int valueSize, HeaderField... headerFields ) { @@ -72,6 +72,7 @@ public AbstractKeyValueStore( FileSystemAbstraction fs, PageCache pages, File ba monitor = RotationMonitor.NONE; } this.format = new Format( headerFields ); + this.logger = logger; this.rotationStrategy = rotation.value().create( fs, pages, format, monitor, base, rotation.parameters() ); this.rotationTimerFactory = timerFactory; this.state = new DeadState.Stopped<>( format, getClass().getAnnotation( State.class ).value(), @@ -173,7 +174,7 @@ public final File currentFile() @Override public final void init() throws IOException { - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { state = state.initialize( rotationStrategy ); } @@ -182,7 +183,7 @@ public final void init() throws IOException @Override public final void start() throws IOException { - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { state = state.start( stateInitializer ); } @@ -190,7 +191,7 @@ public final void start() throws IOException protected final Optional> updater( final long version ) { - try ( LockWrapper lock = readLock( updateLock ) ) + try ( LockWrapper lock = readLock( updateLock, logger ) ) { return state.optionalUpdater( version, lock.get() ); } @@ -198,7 +199,7 @@ protected final Optional> updater( final long version ) protected final EntryUpdater updater() { - try ( LockWrapper lock = readLock( updateLock ) ) + try ( LockWrapper lock = readLock( updateLock, logger ) ) { return state.unsafeUpdater( lock.get() ); } @@ -206,7 +207,7 @@ protected final EntryUpdater updater() protected final EntryUpdater resetter( long version ) { - try ( LockWrapper lock = writeLock( updateLock ) ) + try ( LockWrapper lock = writeLock( updateLock, logger ) ) { ProgressiveState current = state; return current.resetter( lock.get(), new RotationTask( version ) ); @@ -227,7 +228,7 @@ protected final EntryUpdater resetter( long version ) */ protected final PreparedRotation prepareRotation( final long version ) { - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { ProgressiveState prior = state; if ( prior.storedVersion() == version && !prior.hasChanges() ) @@ -243,7 +244,7 @@ protected final PreparedRotation prepareRotation( final long version ) @Override public final void shutdown() throws IOException { - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { stopped = true; state = state.stop(); @@ -290,7 +291,7 @@ public long rotate() throws IOException @Override public void run() { - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { rotate( true ); } @@ -309,7 +310,7 @@ private long rotate( boolean force ) throws IOException final long version = rotation.rotationVersion(); ProgressiveState next = rotation.rotate( force, rotationStrategy, rotationTimerFactory, value -> updateHeaders( value, version ) ); - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { state = next; } @@ -319,7 +320,7 @@ private long rotate( boolean force ) throws IOException { // Rotation failed. Here we assume that rotation state remembers this so that closing it // won't close the state as it was before rotation began, which we're reverting to right here. - try ( LockWrapper ignored = writeLock( updateLock ) ) + try ( LockWrapper ignored = writeLock( updateLock, logger ) ) { // Only mark as failed if we're still running. // If shutdown has been called while being in rotation state then shutdown will fail diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/LockWrapper.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/LockWrapper.java new file mode 100644 index 0000000000000..426e970e09ab1 --- /dev/null +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/LockWrapper.java @@ -0,0 +1,91 @@ +/* + * Copyright (c) 2002-2019 "Neo4j," + * Neo4j Sweden AB [http://neo4j.com] + * + * This file is part of Neo4j. + * + * Neo4j is free software: you can redistribute it and/or modify + * it under the terms of the GNU General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program. If not, see . + */ +package org.neo4j.kernel.impl.store.kvstore; + +import java.util.concurrent.TimeUnit; +import java.util.concurrent.locks.Lock; + +import org.neo4j.logging.Logger; +import org.neo4j.util.FeatureToggles; + +public class LockWrapper implements AutoCloseable +{ + private static final boolean debugLocking = FeatureToggles.flag( AbstractKeyValueStore.class, "debugLocking", false ); + + public static LockWrapper readLock( UpdateLock lock, Logger logger ) + { + return new LockWrapper( lock.readLock(), lock, logger ); + } + + public static LockWrapper writeLock( UpdateLock lock, Logger logger ) + { + return new LockWrapper( lock.writeLock(), lock, logger ); + } + + private Lock lock; + + private LockWrapper( Lock lock, UpdateLock managingLock, Logger logger ) + { + this.lock = lock; + if ( debugLocking ) + { + if ( !lock.tryLock() ) + { + logger.log( Thread.currentThread() + " may block on " + lock + " of " + managingLock ); + while ( !tryLockBlocking( lock, managingLock, logger ) ) + { + logger.log( Thread.currentThread() + " still blocked on " + lock + " of " + managingLock ); + } + } + } + else + { + lock.lock(); + } + } + + private static boolean tryLockBlocking( Lock lock, UpdateLock managingLock, Logger logger ) + { + try + { + return lock.tryLock( 1, TimeUnit.HOURS ); + } + catch ( InterruptedException e ) + { + logger.log( Thread.currentThread() + " ignoring interrupt while blocked on " + lock + " of " + managingLock ); + } + return false; + } + + @Override + public void close() + { + if ( lock != null ) + { + lock.unlock(); + lock = null; + } + } + + public Lock get() + { + return lock; + } +} diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/locking/LockWrapper.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/UpdateLock.java similarity index 51% rename from community/kernel/src/main/java/org/neo4j/kernel/impl/locking/LockWrapper.java rename to community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/UpdateLock.java index 6ffa17e477e36..5e9ee41285aa9 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/locking/LockWrapper.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/store/kvstore/UpdateLock.java @@ -17,41 +17,27 @@ * You should have received a copy of the GNU General Public License * along with this program. If not, see . */ -package org.neo4j.kernel.impl.locking; +package org.neo4j.kernel.impl.store.kvstore; -import java.util.concurrent.locks.Lock; +import java.util.concurrent.locks.ReentrantReadWriteLock; -public class LockWrapper implements AutoCloseable +class UpdateLock extends ReentrantReadWriteLock { - public static LockWrapper readLock( java.util.concurrent.locks.ReadWriteLock lock ) + UpdateLock() { - return new LockWrapper( lock.readLock() ); - } - - public static LockWrapper writeLock( java.util.concurrent.locks.ReadWriteLock lock ) - { - return new LockWrapper( lock.writeLock() ); - } - - private java.util.concurrent.locks.Lock lock; - - public LockWrapper( java.util.concurrent.locks.Lock lock ) - { - (this.lock = lock).lock(); + super( true /* always fair */ ); } @Override - public void close() - { - if ( lock != null ) - { - lock.unlock(); - lock = null; - } - } - - public Lock get() + public String toString() { - return lock; + return "AbstractKeyValyeStore-UpdateLock[owner = " + getOwner() + + ", is write locked = " + isWriteLocked() + + ", writer holds count = " + getWriteHoldCount() + + ", read holds count = " + getReadHoldCount() + + ", readers count = " + getReadLockCount() + + ", threads waiting for write lock = " + getQueuedWriterThreads() + + ", threads waiting for read lock = " + getQueuedReaderThreads() + + "] " + super.toString(); } } diff --git a/community/kernel/src/test/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStoreTest.java b/community/kernel/src/test/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStoreTest.java index 0e6ca7db5e40d..b4f57b40d7c72 100644 --- a/community/kernel/src/test/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStoreTest.java +++ b/community/kernel/src/test/java/org/neo4j/kernel/impl/store/kvstore/AbstractKeyValueStoreTest.java @@ -480,11 +480,6 @@ public void shouldLeaveStoreInGoodStateAfterRotationFailure() throws Exception } } - private static ValueUpdate longValue( long value ) - { - return target -> target.putLong( 0, value ); - } - private Store createTestStore() { return createTestStore( TimeUnit.SECONDS.toMillis( 100 ) ); @@ -607,7 +602,7 @@ private Store( HeaderField... headerFields ) private Store( long rotationTimeout, HeaderField... headerFields ) { - super( resourceManager.fileSystem(), resourceManager.pageCache(), resourceManager.testPath(), null, + super( resourceManager.fileSystem(), resourceManager.pageCache(), resourceManager.testPath(), null, null, new RotationTimerFactory( Clocks.nanoClock(), rotationTimeout ), EmptyVersionContextSupplier.EMPTY, 16, 16, headerFields ); this.headerFields = headerFields; diff --git a/community/kernel/src/test/java/org/neo4j/kernel/impl/transaction/log/checkpoint/CheckPointerConstraintCreationDeadlockIT.java b/community/kernel/src/test/java/org/neo4j/kernel/impl/transaction/log/checkpoint/CheckPointerConstraintCreationDeadlockIT.java index 4614f55ae94b8..4ebe299113d6a 100644 --- a/community/kernel/src/test/java/org/neo4j/kernel/impl/transaction/log/checkpoint/CheckPointerConstraintCreationDeadlockIT.java +++ b/community/kernel/src/test/java/org/neo4j/kernel/impl/transaction/log/checkpoint/CheckPointerConstraintCreationDeadlockIT.java @@ -34,7 +34,7 @@ import org.neo4j.kernel.impl.api.TransactionCommitProcess; import org.neo4j.kernel.impl.api.TransactionToApply; import org.neo4j.kernel.impl.api.index.IndexingService; -import org.neo4j.kernel.impl.locking.LockWrapper; +import org.neo4j.kernel.impl.store.kvstore.LockWrapper; import org.neo4j.kernel.impl.transaction.TransactionRepresentation; import org.neo4j.kernel.impl.transaction.log.LogicalTransactionStore; import org.neo4j.kernel.impl.transaction.log.TransactionCursor;