diff --git a/community/index/src/main/java/org/neo4j/index/internal/gbptree/CleanupJob.java b/community/index/src/main/java/org/neo4j/index/internal/gbptree/CleanupJob.java index 4303c59d99051..46bcbbe233a66 100644 --- a/community/index/src/main/java/org/neo4j/index/internal/gbptree/CleanupJob.java +++ b/community/index/src/main/java/org/neo4j/index/internal/gbptree/CleanupJob.java @@ -40,7 +40,7 @@ public interface CleanupJob extends Runnable /** * @return Cause of failure if {@link #hasFailed()} or {@code null} if job has not failed. */ - Exception getCause(); + Throwable getCause(); /** * Mark this job as closed and cleanup all it's resources. @@ -70,7 +70,7 @@ public boolean hasFailed() } @Override - public Exception getCause() + public Throwable getCause() { return null; } diff --git a/community/index/src/main/java/org/neo4j/index/internal/gbptree/CrashGenerationCleaner.java b/community/index/src/main/java/org/neo4j/index/internal/gbptree/CrashGenerationCleaner.java index 62537e136e1cd..3257f7aa872ed 100644 --- a/community/index/src/main/java/org/neo4j/index/internal/gbptree/CrashGenerationCleaner.java +++ b/community/index/src/main/java/org/neo4j/index/internal/gbptree/CrashGenerationCleaner.java @@ -69,8 +69,9 @@ class CrashGenerationCleaner public void clean() throws IOException { - assert unstableGeneration > stableGeneration; - assert unstableGeneration - stableGeneration > 1; + monitor.cleanupStarted(); + assert unstableGeneration > stableGeneration : unexpectedGenerations(); + assert unstableGeneration - stableGeneration > 1 : unexpectedGenerations(); long startTime = currentTimeMillis(); int threads = availableProcessors; @@ -238,4 +239,9 @@ private void cleanCrashedGSP( PageCursor cursor, int gspOffset, AtomicInteger cl cleanedPointers.incrementAndGet(); } } + + private String unexpectedGenerations( ) + { + return "Unexpected generations, stableGeneration=" + stableGeneration + ", unstableGeneration=" + unstableGeneration; + } } diff --git a/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTree.java b/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTree.java index 351c73fb57337..d86493579b687 100644 --- a/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTree.java +++ b/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTree.java @@ -142,11 +142,31 @@ public void noStoreFile() { // no-op } + @Override + public void cleanupRegistered() + { // no-op + } + + @Override + public void cleanupStarted() + { // no-op + } + @Override public void cleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) { // no-op } + @Override + public void cleanupClosed() + { // no-op + } + + @Override + public void cleanupFailed( Throwable throwable ) + { // no-op + } + @Override public void startupState( boolean clean ) { // no-op @@ -164,6 +184,16 @@ public void startupState( boolean clean ) */ void noStoreFile(); + /** + * Called after cleanup job has been created + */ + void cleanupRegistered(); + + /** + * Called after cleanup job has been started + */ + void cleanupStarted(); + /** * Called after recovery has completed and cleaning has been done. * @@ -173,6 +203,17 @@ public void startupState( boolean clean ) */ void cleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ); + /** + * Called when cleanup job is closed and lock is released + */ + void cleanupClosed(); + + /** + * Called when cleanup job catches a throwable + * @param throwable cause of failure + */ + void cleanupFailed( Throwable throwable ); + /** * Report tree state on startup. * @@ -1006,6 +1047,7 @@ private CleanupJob createCleanupJob( RecoveryCleanupWorkCollector recoveryCleanu else { lock.cleanerLock(); + monitor.cleanupRegistered(); long generation = this.generation; long stableGeneration = stableGeneration( generation ); @@ -1015,7 +1057,7 @@ private CleanupJob createCleanupJob( RecoveryCleanupWorkCollector recoveryCleanu CrashGenerationCleaner crashGenerationCleaner = new CrashGenerationCleaner( pagedFile, bTreeNode, IdSpace.MIN_TREE_NODE_ID, highTreeNodeId, stableGeneration, unstableGeneration, monitor ); - GBPTreeCleanupJob cleanupJob = new GBPTreeCleanupJob( crashGenerationCleaner, lock ); + GBPTreeCleanupJob cleanupJob = new GBPTreeCleanupJob( crashGenerationCleaner, lock, monitor, indexFile ); recoveryCleanupWorkCollector.add( cleanupJob ); return cleanupJob; } diff --git a/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTreeCleanupJob.java b/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTreeCleanupJob.java index 8707e2e96b3fa..b7439e8770e99 100644 --- a/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTreeCleanupJob.java +++ b/community/index/src/main/java/org/neo4j/index/internal/gbptree/GBPTreeCleanupJob.java @@ -19,21 +19,30 @@ */ package org.neo4j.index.internal.gbptree; +import java.io.File; +import java.util.StringJoiner; + class GBPTreeCleanupJob implements CleanupJob { private final CrashGenerationCleaner crashGenerationCleaner; private final GBPTreeLock gbpTreeLock; + private final GBPTree.Monitor monitor; + private final File indexFile; private volatile boolean needed; - private volatile Exception failure; + private volatile Throwable failure; /** * @param crashGenerationCleaner {@link CrashGenerationCleaner} to use for cleaning. * @param gbpTreeLock {@link GBPTreeLock} to be released when job has either successfully finished or failed. + * @param monitor {@link GBPTree.Monitor} to report to + * @param indexFile Target file */ - GBPTreeCleanupJob( CrashGenerationCleaner crashGenerationCleaner, GBPTreeLock gbpTreeLock ) + GBPTreeCleanupJob( CrashGenerationCleaner crashGenerationCleaner, GBPTreeLock gbpTreeLock, GBPTree.Monitor monitor, File indexFile ) { this.crashGenerationCleaner = crashGenerationCleaner; this.gbpTreeLock = gbpTreeLock; + this.monitor = monitor; + this.indexFile = indexFile; this.needed = true; } @@ -51,7 +60,7 @@ public boolean hasFailed() } @Override - public Exception getCause() + public Throwable getCause() { return failure; } @@ -60,6 +69,7 @@ public Exception getCause() public void close() { gbpTreeLock.cleanerUnlock(); + monitor.cleanupClosed(); } @Override @@ -70,9 +80,20 @@ public void run() crashGenerationCleaner.clean(); needed = false; } - catch ( Exception e ) + catch ( Throwable e ) { + monitor.cleanupFailed( e ); failure = e; } } + + @Override + public String toString() + { + StringJoiner joiner = new StringJoiner( ", ", "CleanupJob(", ")" ); + joiner.add( "file=" + indexFile.getAbsolutePath() ); + joiner.add( "needed=" + needed ); + joiner.add( "failure=" + (failure == null ? null : failure.toString()) ); + return joiner.toString(); + } } diff --git a/community/index/src/main/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollector.java b/community/index/src/main/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollector.java index bc1758bf07ae6..20f072c14b273 100644 --- a/community/index/src/main/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollector.java +++ b/community/index/src/main/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollector.java @@ -20,7 +20,9 @@ package org.neo4j.index.internal.gbptree; import java.util.Queue; +import java.util.StringJoiner; import java.util.concurrent.LinkedBlockingQueue; +import java.util.function.Consumer; import org.neo4j.kernel.lifecycle.LifecycleAdapter; import org.neo4j.scheduler.JobScheduler; @@ -51,7 +53,13 @@ public GroupingRecoveryCleanupWorkCollector( JobScheduler jobScheduler ) public void init() { started = false; - jobs.clear(); + if ( !jobs.isEmpty() ) + { + StringJoiner joiner = new StringJoiner( "\n ", "Did not expect there to be any cleanup jobs still here. Jobs[", "]" ); + consumeAndCloseJobs( cj -> joiner.add( jobs.toString() ) ); + throw new IllegalStateException( joiner.toString() ); + } + } @Override @@ -71,6 +79,12 @@ public void start() started = true; } + @Override + public void shutdown() + { + consumeAndCloseJobs( cj -> {} ); + } + private void scheduleJobs() { jobScheduler.schedule( recoveryCleanup, allJobs() ); @@ -110,4 +124,14 @@ private Runnable allJobs() } }; } + + private void consumeAndCloseJobs( Consumer consumer ) + { + CleanupJob job; + while ( (job = jobs.poll()) != null ) + { + consumer.accept( job ); + job.close(); + } + } } diff --git a/community/index/src/test/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollectorTest.java b/community/index/src/test/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollectorTest.java index 58bdebfd781a5..35fe7d1862e57 100644 --- a/community/index/src/test/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollectorTest.java +++ b/community/index/src/test/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollectorTest.java @@ -42,8 +42,8 @@ public class GroupingRecoveryCleanupWorkCollectorTest public void mustNotScheduleAnyJobsBeforeStart() { // given - List allRuns = new ArrayList<>(); - List expectedJobs = someJobs( allRuns ); + List allRuns = new ArrayList<>(); + List expectedJobs = someJobs( allRuns ); // when collector.init(); @@ -57,8 +57,8 @@ public void mustNotScheduleAnyJobsBeforeStart() public void mustScheduleAllJobs() { // given - List allRuns = new ArrayList<>(); - List expectedJobs = someJobs( allRuns ); + List allRuns = new ArrayList<>(); + List expectedJobs = someJobs( allRuns ); // when collector.init(); @@ -70,28 +70,51 @@ public void mustScheduleAllJobs() } @Test - public void mustNotScheduleOldJobsAfterRestart() + public void mustThrowIfOldJobsDuringInit() { // given - List allRuns = new ArrayList<>(); - List someJobs = someJobs( allRuns ); + List allRuns = new ArrayList<>(); + List someJobs = someJobs( allRuns ); // when - collector.init(); addAll( someJobs ); + try + { + collector.init(); + fail( "Should have failed" ); + } + catch ( IllegalStateException e ) + { + // then + } + } + + @Test + public void mustCloseOldJobsOnShutdown() + { + // given + List allRuns = new ArrayList<>(); + List someJobs = someJobs( allRuns ); + + // when collector.init(); - collector.start(); + addAll( someJobs ); + collector.shutdown(); // then - assertTrue( allRuns.isEmpty() ); + assertTrue( "Expected no jobs to run", allRuns.isEmpty() ); + for ( DummyJob job : someJobs ) + { + assertTrue( "Expected all jobs to be closed", job.isClosed() ); + } } @Test public void mustNotScheduleOldJobsOnMultipleStart() { // given - List allRuns = new ArrayList<>(); - List expectedJobs = someJobs( allRuns ); + List allRuns = new ArrayList<>(); + List expectedJobs = someJobs( allRuns ); // when collector.init(); @@ -107,8 +130,8 @@ public void mustNotScheduleOldJobsOnMultipleStart() public void mustNotScheduleOldJobsOnStartStopStart() throws Throwable { // given - List allRuns = new ArrayList<>(); - List expectedJobs = someJobs( allRuns ); + List allRuns = new ArrayList<>(); + List expectedJobs = someJobs( allRuns ); // when collector.init(); @@ -124,13 +147,13 @@ public void mustNotScheduleOldJobsOnStartStopStart() throws Throwable @Test public void executeAllTheJobsWhenSeparateJobFails() { - List allRuns = new ArrayList<>(); + List allRuns = new ArrayList<>(); collector.init(); DummyJob firstJob = new DummyJob( "first", allRuns ); DummyJob thirdJob = new DummyJob( "third", allRuns ); DummyJob fourthJob = new DummyJob( "fourth", allRuns ); - List expectedJobs = Arrays.asList( firstJob, thirdJob, fourthJob ); + List expectedJobs = Arrays.asList( firstJob, thirdJob, fourthJob ); collector.add( firstJob ); collector.add( new EvilJob() ); @@ -167,18 +190,18 @@ public void throwOnAddingJobsAfterStart() } } - private void addAll( Collection jobs ) + private void addAll( Collection jobs ) { jobs.forEach( collector::add ); } - private void assertSame( List someJobs, List actual ) + private void assertSame( List someJobs, List actual ) { assertTrue( actual.containsAll( someJobs ) ); assertTrue( someJobs.containsAll( actual ) ); } - private List someJobs( List allRuns ) + private List someJobs( List allRuns ) { return new ArrayList<>( Arrays.asList( new DummyJob( "A", allRuns ), @@ -213,7 +236,7 @@ public boolean hasFailed() } @Override - public Exception getCause() + public Throwable getCause() { return null; } @@ -234,9 +257,10 @@ public void run() private class DummyJob implements CleanupJob { private final String name; - private final List allRuns; + private final List allRuns; + private boolean closed; - DummyJob( String name, List allRuns ) + DummyJob( String name, List allRuns ) { this.name = name; this.allRuns = allRuns; @@ -261,14 +285,15 @@ public boolean hasFailed() } @Override - public Exception getCause() + public Throwable getCause() { return null; } @Override public void close() - { // no-op + { + closed = true; } @Override @@ -276,5 +301,10 @@ public void run() { allRuns.add( this ); } + + public boolean isClosed() + { + return closed; + } } } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/index/IndexProvider.java b/community/kernel/src/main/java/org/neo4j/kernel/api/index/IndexProvider.java index 61415f2886555..5ae7db0eab677 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/api/index/IndexProvider.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/api/index/IndexProvider.java @@ -19,8 +19,8 @@ */ package org.neo4j.kernel.api.index; +import java.io.File; import java.io.IOException; -import java.util.Map; import org.neo4j.internal.kernel.api.IndexCapability; import org.neo4j.internal.kernel.api.InternalIndexState; @@ -104,14 +104,44 @@ public void failedToOpenIndex( long indexId, SchemaIndexDescriptor schemaIndexDe } @Override - public void recoveryCompleted( SchemaIndexDescriptor schemaIndexDescriptor, String indexFile, Map data ) + public void recoveryCleanupRegistered( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) + { // no-op + } + + @Override + public void recoveryCleanupStarted( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) + { // no-op + } + + @Override + public void recoveryCleanupFinished( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor, + long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) + { // no-op + } + + @Override + public void recoveryCleanupClosed( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) + { // no-op + } + + @Override + public void recoveryCleanupFailed( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor, Throwable throwable ) { // no-op } } void failedToOpenIndex( long indexId, SchemaIndexDescriptor schemaIndexDescriptor, String action, Exception cause ); - void recoveryCompleted( SchemaIndexDescriptor schemaIndexDescriptor, String indexFile, Map data ); + void recoveryCleanupRegistered( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ); + + void recoveryCleanupStarted( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ); + + void recoveryCleanupFinished( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor, + long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ); + + void recoveryCleanupClosed( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ); + + void recoveryCleanupFailed( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor, Throwable throwable ); } public static final IndexProvider EMPTY = diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/index/LoggingMonitor.java b/community/kernel/src/main/java/org/neo4j/kernel/api/index/LoggingMonitor.java index ae64327936e0c..3aef3031e534a 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/api/index/LoggingMonitor.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/api/index/LoggingMonitor.java @@ -19,13 +19,15 @@ */ package org.neo4j.kernel.api.index; -import java.util.Map; +import org.apache.commons.lang3.exception.ExceptionUtils; + +import java.io.File; import java.util.StringJoiner; import org.neo4j.kernel.api.schema.index.SchemaIndexDescriptor; import org.neo4j.logging.Log; -import static java.lang.String.format; +import static org.neo4j.helpers.Format.duration; public class LoggingMonitor implements IndexProvider.Monitor { @@ -43,12 +45,44 @@ public void failedToOpenIndex( long indexId, SchemaIndexDescriptor schemaIndexDe } @Override - public void recoveryCompleted( SchemaIndexDescriptor schemaIndexDescriptor, String indexFile, Map data ) + public void recoveryCleanupRegistered( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) + { + log.info( "Schema index cleanup job registered: " + indexDescription( indexFile, schemaIndexDescriptor ) ); + } + + @Override + public void recoveryCleanupStarted( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) { - StringJoiner joiner = new StringJoiner( ", ", "Schema index recovery completed: ", "" ); - joiner.add( "descriptor=" + schemaIndexDescriptor ); - joiner.add( "file=" + indexFile ); - data.forEach( ( key, value ) -> joiner.add( format( "%s=%s", key, value ) ) ); + log.info( "Schema index cleanup job started: " + indexDescription( indexFile, schemaIndexDescriptor ) ); + } + + @Override + public void recoveryCleanupFinished( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor, + long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) + { + StringJoiner joiner = + new StringJoiner( ", ", "Schema index cleanup job finished: " + indexDescription( indexFile, schemaIndexDescriptor ) + " ", "" ); + joiner.add( "Number of pages visited: " + numberOfPagesVisited ); + joiner.add( "Number of cleaned crashed pointers: " + numberOfCleanedCrashPointers ); + joiner.add( "Time spent: " + duration( durationMillis ) ); log.info( joiner.toString() ); } + + @Override + public void recoveryCleanupClosed( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) + { + log.info( "Schema index cleanup job closed: " + indexDescription( indexFile, schemaIndexDescriptor ) ); + } + + @Override + public void recoveryCleanupFailed( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor, Throwable throwable ) + { + log.info( "Schema index cleanup job failed: " + indexDescription( indexFile, schemaIndexDescriptor ) + ".\n" + + "Caused by: " + ExceptionUtils.getStackTrace( throwable ) ); + } + + private String indexDescription( File indexFile, SchemaIndexDescriptor schemaIndexDescriptor ) + { + return "descriptor=" + schemaIndexDescriptor.toString() + ", indexFile=" + indexFile.getAbsolutePath(); + } } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LabelScanStore.java b/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LabelScanStore.java index ec2c14d4098af..5e621ed703771 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LabelScanStore.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LabelScanStore.java @@ -21,7 +21,6 @@ import java.io.File; import java.io.IOException; -import java.util.Map; import org.neo4j.graphdb.ResourceIterator; import org.neo4j.io.pagecache.IOLimiter; @@ -52,27 +51,42 @@ public void noIndex() } @Override - public void lockedIndex( Exception e ) + public void notValidIndex() { // empty } @Override - public void notValidIndex() + public void rebuilding() { // empty } @Override - public void rebuilding() + public void rebuilt( long roughNodeCount ) { // empty } @Override - public void rebuilt( long roughNodeCount ) + public void recoveryCleanupRegistered() { // empty } @Override - public void recoveryCompleted( Map data ) + public void recoveryCleanupStarted() + { // empty + } + + @Override + public void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) + { // empty + } + + @Override + public void recoveryCleanupClosed() + { // empty + } + + @Override + public void recoveryCleanupFailed( Throwable throwable ) { // empty } } @@ -81,15 +95,21 @@ public void recoveryCompleted( Map data ) void noIndex(); - void lockedIndex( Exception e ); - void notValidIndex(); void rebuilding(); void rebuilt( long roughNodeCount ); - void recoveryCompleted( Map data ); + void recoveryCleanupRegistered(); + + void recoveryCleanupStarted(); + + void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ); + + void recoveryCleanupClosed(); + + void recoveryCleanupFailed( Throwable throwable ); } /** diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LoggingMonitor.java b/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LoggingMonitor.java index 4d7502a309218..d43dcedef2c31 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LoggingMonitor.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/api/labelscan/LoggingMonitor.java @@ -19,12 +19,14 @@ */ package org.neo4j.kernel.api.labelscan; -import java.util.Map; +import org.apache.commons.lang3.exception.ExceptionUtils; + +import java.util.StringJoiner; import org.neo4j.kernel.api.labelscan.LabelScanStore.Monitor; import org.neo4j.logging.Log; -import static java.lang.String.format; +import static org.neo4j.helpers.Format.duration; /** * Logs about important events about {@link LabelScanStore} {@link Monitor}. @@ -41,38 +43,58 @@ public LoggingMonitor( Log log ) @Override public void noIndex() { - log.info( "No scan store found, this might just be first use. Preparing to rebuild." ); + log.info( "No label index found, this might just be first use. Preparing to rebuild." ); } @Override - public void lockedIndex( Exception e ) + public void notValidIndex() { - log.error( "Scan store is locked by another process or database", e ); + log.warn( "Label index could not be read. Preparing to rebuild." ); } @Override - public void notValidIndex() + public void rebuilding() { - log.warn( "Scan store could not be read. Preparing to rebuild." ); + log.info( "Rebuilding label index, this may take a while" ); } @Override - public void rebuilding() + public void rebuilt( long roughNodeCount ) { - log.info( "Rebuilding scan store, this may take a while" ); + log.info( "Label index rebuilt (roughly " + roughNodeCount + " nodes)" ); } @Override - public void rebuilt( long roughNodeCount ) + public void recoveryCleanupRegistered() + { + log.info( "Label index cleanup job registered" ); + } + + @Override + public void recoveryCleanupStarted() + { + log.info( "Label index cleanup job started" ); + } + + @Override + public void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) + { + StringJoiner joiner = new StringJoiner( ", ", "Label index cleanup job finished: ", "" ); + joiner.add( "Number of pages visited: " + numberOfPagesVisited ); + joiner.add( "Number of cleaned crashed pointers: " + numberOfCleanedCrashPointers ); + joiner.add( "Time spent: " + duration( durationMillis ) ); + log.info( joiner.toString() ); + } + + @Override + public void recoveryCleanupClosed() { - log.info( "Scan store rebuilt (roughly " + roughNodeCount + " nodes)" ); + log.info( "Label index cleanup job closed" ); } @Override - public void recoveryCompleted( Map data ) + public void recoveryCleanupFailed( Throwable throwable ) { - StringBuilder builder = new StringBuilder( "Scan store recovery completed:" ); - data.forEach( ( key, value ) -> builder.append( format( " %s: %s", key, value ) ) ); - log.info( builder.toString() ); + log.info( "Label index cleanup job failed.\nCaused by: " + ExceptionUtils.getStackTrace( throwable ) ); } } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/index/labelscan/NativeLabelScanStore.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/index/labelscan/NativeLabelScanStore.java index 396d8707bd4c4..8731743874792 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/index/labelscan/NativeLabelScanStore.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/index/labelscan/NativeLabelScanStore.java @@ -48,10 +48,8 @@ import org.neo4j.kernel.monitoring.Monitors; import org.neo4j.storageengine.api.schema.LabelScanReader; -import static org.neo4j.helpers.Format.duration; import static org.neo4j.helpers.collection.Iterators.asResourceIterator; import static org.neo4j.helpers.collection.Iterators.iterator; -import static org.neo4j.helpers.collection.MapUtil.map; import static org.neo4j.kernel.impl.store.MetaDataStore.DEFAULT_NAME; /** @@ -376,18 +374,7 @@ private boolean instantiateTree() throws IOException private GBPTree.Monitor treeMonitor() { - return new GBPTree.Monitor.Adaptor() - { - @Override - public void cleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, - long durationMillis ) - { - monitor.recoveryCompleted( map( - "Number of pages visited", numberOfPagesVisited, - "Number of cleaned crashed pointers", numberOfCleanedCrashPointers, - "Time spent", duration( durationMillis ) ) ); - } - }; + return new LabelIndexTreeMonitor(); } @Override @@ -486,4 +473,37 @@ public boolean isDirty() { return index == null || index.wasDirtyOnStartup(); } + + private class LabelIndexTreeMonitor extends GBPTree.Monitor.Adaptor + { + @Override + public void cleanupRegistered() + { + monitor.recoveryCleanupRegistered(); + } + + @Override + public void cleanupStarted() + { + monitor.recoveryCleanupStarted(); + } + + @Override + public void cleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) + { + monitor.recoveryCleanupFinished( numberOfPagesVisited, numberOfCleanedCrashPointers, durationMillis ); + } + + @Override + public void cleanupClosed() + { + monitor.recoveryCleanupClosed(); + } + + @Override + public void cleanupFailed( Throwable throwable ) + { + monitor.recoveryCleanupFailed( throwable ); + } + } } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/index/schema/NativeSchemaIndex.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/index/schema/NativeSchemaIndex.java index 7a0f669a3df11..c6d7291928095 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/index/schema/NativeSchemaIndex.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/index/schema/NativeSchemaIndex.java @@ -34,8 +34,6 @@ import org.neo4j.kernel.api.schema.index.SchemaIndexDescriptor; import org.neo4j.kernel.impl.index.GBPTreeFileUtil; -import static org.neo4j.helpers.Format.duration; -import static org.neo4j.helpers.collection.MapUtil.map; import static org.neo4j.index.internal.gbptree.GBPTree.NO_HEADER_READER; abstract class NativeSchemaIndex, VALUE extends NativeSchemaValue> @@ -72,17 +70,7 @@ void instantiateTree( RecoveryCleanupWorkCollector recoveryCleanupWorkCollector, private GBPTree.Monitor treeMonitor( ) { - return new GBPTree.Monitor.Adaptor() - { - @Override - public void cleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) - { - monitor.recoveryCompleted( descriptor, storeFile.getAbsolutePath(), map( - "Number of pages visited", numberOfPagesVisited, - "Number of cleaned crashed pointers", numberOfCleanedCrashPointers, - "Time spent", duration( durationMillis ) ) ); - } - }; + return new NativeIndexTreeMonitor(); } private void ensureDirectoryExist() throws IOException @@ -113,4 +101,37 @@ void assertOpen() throw new IllegalStateException( "Index has been closed" ); } } + + private class NativeIndexTreeMonitor extends GBPTree.Monitor.Adaptor + { + @Override + public void cleanupRegistered() + { + monitor.recoveryCleanupRegistered( storeFile, descriptor ); + } + + @Override + public void cleanupStarted() + { + monitor.recoveryCleanupStarted( storeFile, descriptor ); + } + + @Override + public void cleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) + { + monitor.recoveryCleanupFinished( storeFile, descriptor, numberOfPagesVisited, numberOfCleanedCrashPointers, durationMillis ); + } + + @Override + public void cleanupClosed() + { + monitor.recoveryCleanupClosed( storeFile, descriptor ); + } + + @Override + public void cleanupFailed( Throwable throwable ) + { + monitor.recoveryCleanupFailed( storeFile, descriptor, throwable ); + } + } } diff --git a/community/kernel/src/test/java/org/neo4j/kernel/api/impl/labelscan/LabelScanStoreTest.java b/community/kernel/src/test/java/org/neo4j/kernel/api/impl/labelscan/LabelScanStoreTest.java index 0feeecf626794..b5d80e08cadf4 100644 --- a/community/kernel/src/test/java/org/neo4j/kernel/api/impl/labelscan/LabelScanStoreTest.java +++ b/community/kernel/src/test/java/org/neo4j/kernel/api/impl/labelscan/LabelScanStoreTest.java @@ -646,11 +646,6 @@ public void noIndex() noIndexCalled = true; } - @Override - public void lockedIndex( Exception e ) - { - } - @Override public void notValidIndex() { diff --git a/community/neo4j/src/test/java/recovery/RecoveryCleanupIT.java b/community/neo4j/src/test/java/recovery/RecoveryCleanupIT.java index 31e2e5502eb59..7942772f2632b 100644 --- a/community/neo4j/src/test/java/recovery/RecoveryCleanupIT.java +++ b/community/neo4j/src/test/java/recovery/RecoveryCleanupIT.java @@ -141,7 +141,14 @@ public void scanStoreMustLogCrashPointerCleanupDuringRecovery() throws Exception startDatabase().shutdown(); // then - logProvider.assertContainsLogCallContaining( "Scan store recovery completed" ); + logProvider.assertContainsLogCallContaining( "Label index cleanup job registered" ); + logProvider.assertContainsLogCallContaining( "Label index cleanup job started" ); + logProvider.assertContainsMessageMatching( Matchers.stringContainsInOrder( Iterables.asIterable( + "Label index cleanup job finished", + "Number of pages visited", + "Number of cleaned crashed pointers", + "Time spent" ) ) ); + logProvider.assertContainsLogCallContaining( "Label index cleanup job closed" ); } @Test @@ -158,24 +165,39 @@ public void nativeIndexMustLogCrashPointerCleanupDuringRecovery() throws Excepti // then List> matchers = new ArrayList<>(); - matchers.add( indexRecoveryLogMatcher( "string" ) ); - matchers.add( indexRecoveryLogMatcher( "native" ) ); - matchers.add( indexRecoveryLogMatcher( "spatial" ) ); - matchers.add( indexRecoveryLogMatcher( "temporal" ) ); + String[] subTypes = new String[]{"string", "native", "spatial", "temporal"}; + for ( String subType : subTypes ) + { + matchers.add( indexRecoveryLogMatcher( "Schema index cleanup job registered", subType ) ); + matchers.add( indexRecoveryLogMatcher( "Schema index cleanup job started", subType ) ); + matchers.add( indexRecoveryFinishedLogMatcher( subType ) ); + matchers.add( indexRecoveryLogMatcher( "Schema index cleanup job closed", subType ) ); + } matchers.forEach( logProvider::assertContainsExactlyOneMessageMatching ); } - private Matcher indexRecoveryLogMatcher( String subIndexProviderKey ) + private Matcher indexRecoveryLogMatcher( String logMessage, String subIndexProviderKey ) + { + + return Matchers.stringContainsInOrder( Iterables.asIterable( + logMessage, + "descriptor", + "indexFile=", + File.separator + subIndexProviderKey ) ); + } + + private Matcher indexRecoveryFinishedLogMatcher( String subIndexProviderKey ) { return Matchers.stringContainsInOrder( Iterables.asIterable( - "Schema index recovery completed", + "Schema index cleanup job finished", "descriptor", - "file=", + "indexFile=", File.separator + subIndexProviderKey, - "cleaned crashed pointers", - "pages visited", - "Time spent" ) ); + "Number of pages visited", + "Number of cleaned crashed pointers", + "Time spent" ) + ); } private void dirtyDatabase() throws IOException @@ -295,7 +317,7 @@ private class RecoveryBarrierMonitor extends LabelScanStore.Monitor.Adaptor } @Override - public void recoveryCompleted( Map data ) + public void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis ) { barrier.reached(); } diff --git a/enterprise/backup/src/test/java/org/neo4j/backup/BackupIT.java b/enterprise/backup/src/test/java/org/neo4j/backup/BackupIT.java index 6d0cb8fbf1e10..3c4b011d0dcf0 100644 --- a/enterprise/backup/src/test/java/org/neo4j/backup/BackupIT.java +++ b/enterprise/backup/src/test/java/org/neo4j/backup/BackupIT.java @@ -39,6 +39,10 @@ import java.util.ArrayList; import java.util.Arrays; import java.util.List; +import java.util.concurrent.ExecutorService; +import java.util.concurrent.Executors; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.Function; import org.neo4j.graphdb.GraphDatabaseService; @@ -76,6 +80,7 @@ import org.neo4j.test.DbRepresentation; import org.neo4j.test.TestGraphDatabaseFactory; import org.neo4j.test.rule.PageCacheRule; +import org.neo4j.test.rule.RandomRule; import org.neo4j.test.rule.SuppressOutput; import org.neo4j.test.rule.TestDirectory; import org.neo4j.test.rule.fs.DefaultFileSystemRule; @@ -98,12 +103,14 @@ public class BackupIT private final TestDirectory testDir = TestDirectory.testDirectory(); private final DefaultFileSystemRule fileSystemRule = new DefaultFileSystemRule(); private final PageCacheRule pageCacheRule = new PageCacheRule(); + private final RandomRule random = new RandomRule(); @Rule public final RuleChain ruleChain = RuleChain.outerRule( testDir ) .around( fileSystemRule ) .around( pageCacheRule ) - .around( SuppressOutput.suppressAll() ); + .around( SuppressOutput.suppressAll() ) + .around( random ); @Parameter public String recordFormatName; @@ -429,6 +436,60 @@ public void backupEmptyIndex() throws Exception } } + @Test + public void backupMultipleSchemaIndexes() throws InterruptedException + { + // given + ExecutorService executorService = Executors.newSingleThreadExecutor(); + AtomicBoolean end = new AtomicBoolean(); + int backupPort = PortAuthority.allocatePort(); + GraphDatabaseService db = getEmbeddedTestDataBaseService( backupPort ); + int numberOfIndexedLabels = 100; + List