Further improve logging around CleanupJob

- CleanupJob catch Throwable and not only Exception - Log failure in CleanupJob - toString method for CleanupJob - Label index use log with "Label index" instead of "Scan store"
neo4j · Jun 18, 2018 · f825f9d · f825f9d
1 parent ee789a3
commit f825f9d
Show file tree

Hide file tree

Showing 12 changed files with 154 additions and 76 deletions.
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
@@ -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
@@ -73,8 +73,8 @@ class CrashGenerationCleaner
     public void clean() throws IOException
     {
         monitor.cleanupStarted();
-        assert unstableGeneration > stableGeneration;
-        assert unstableGeneration - stableGeneration > 1;
+        assert unstableGeneration > stableGeneration : unexpectedGenerations();
+        assert unstableGeneration - stableGeneration > 1 : unexpectedGenerations();
 
         long startTime = currentTimeMillis();
         int threads = availableProcessors;
@@ -242,4 +242,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
@@ -177,6 +177,11 @@ public void cleanupClosed()
             {   // no-op
             }
 
+            @Override
+            public void cleanupFailed( Throwable throwable )
+            {   // no-op
+            }
+
             @Override
             public void startupState( boolean clean )
             {   // no-op
@@ -218,6 +223,12 @@ public void startupState( boolean clean )
          */
         void cleanupClosed();
 
+        /**
+         * Called when cleanup job catches a throwable
+         * @param throwable cause of failure
+         */
+        void cleanupFailed( Throwable throwable );
+
         /**
          * Report tree state on startup.
          *
@@ -1096,7 +1107,7 @@ private CleanupJob createCleanupJob( boolean needsCleaning )
             CrashGenerationCleaner crashGenerationCleaner =
                     new CrashGenerationCleaner( pagedFile, bTreeNode, IdSpace.MIN_TREE_NODE_ID, highTreeNodeId,
                             stableGeneration, unstableGeneration, monitor );
-            return new GBPTreeCleanupJob( crashGenerationCleaner, lock, monitor );
+            return new GBPTreeCleanupJob( crashGenerationCleaner, lock, monitor, indexFile );
         }
     }
 

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
@@ -19,24 +19,29 @@
  */
 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
+     * @param indexFile Target file
      */
-    GBPTreeCleanupJob( CrashGenerationCleaner crashGenerationCleaner, GBPTreeLock gbpTreeLock, GBPTree.Monitor monitor )
+    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;
 
     }
@@ -54,7 +59,7 @@ public boolean hasFailed()
     }
 
     @Override
-    public Exception getCause()
+    public Throwable getCause()
     {
         return failure;
     }
@@ -74,9 +79,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/.../test/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollectorTest.java b/.../test/java/org/neo4j/index/internal/gbptree/GroupingRecoveryCleanupWorkCollectorTest.java
@@ -179,7 +179,7 @@ public boolean hasFailed()
         }
 
         @Override
-        public Exception getCause()
+        public Throwable getCause()
         {
             return null;
         }

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
@@ -19,6 +19,8 @@
  */
 package org.neo4j.kernel.api.index;
 
+import org.apache.commons.lang3.exception.ExceptionUtils;
+
 import java.util.StringJoiner;
 
 import org.neo4j.kernel.api.schema.index.IndexDescriptor;
@@ -71,6 +73,13 @@ public void recoveryCleanupClosed( long indexId, IndexDescriptor descriptor )
         log.info( "Schema index cleanup job closed: " + indexDescription( indexId, descriptor ) );
     }
 
+    @Override
+    public void recoveryCleanupFailed( long indexId, IndexDescriptor descriptor, Throwable throwable )
+    {
+        log.info( "Schema index cleanup job failed: " + indexDescription( indexId, descriptor ) + ".\n" +
+                "Caused by: " + ExceptionUtils.getStackTrace( throwable ) );
+    }
+
     private String indexDescription( long indexId, IndexDescriptor indexDescriptor )
     {
         return "indexId: " + indexId + " descriptor: " + indexDescriptor.toString();

diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/index/SchemaIndexProvider.java b/community/kernel/src/main/java/org/neo4j/kernel/api/index/SchemaIndexProvider.java
@@ -123,6 +123,11 @@ public void recoveryCleanupFinished( long indexId, IndexDescriptor indexDescript
             public void recoveryCleanupClosed( long indexId, IndexDescriptor descriptor )
             {   // no-op
             }
+
+            @Override
+            public void recoveryCleanupFailed( long indexId, IndexDescriptor descriptor, Throwable throwable )
+            {   // no-op
+            }
         }
 
         void failedToOpenIndex( long indexId, IndexDescriptor indexDescriptor, String action, Exception cause );
@@ -135,6 +140,8 @@ void recoveryCleanupFinished( long indexId, IndexDescriptor indexDescriptor,
                 long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis );
 
         void recoveryCleanupClosed( long indexId, IndexDescriptor descriptor );
+
+        void recoveryCleanupFailed( long indexId, IndexDescriptor descriptor, Throwable throwable );
     }
 
     public static final SchemaIndexProvider NO_INDEX_PROVIDER =

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
@@ -84,6 +84,11 @@ public void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCle
             public void recoveryCleanupClosed()
             {   // empty
             }
+
+            @Override
+            public void recoveryCleanupFailed( Throwable throwable )
+            {   // empty
+            }
         }
 
         void init();
@@ -103,6 +108,8 @@ public void recoveryCleanupClosed()
         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
@@ -19,6 +19,8 @@
  */
 package org.neo4j.kernel.api.labelscan;
 
+import org.apache.commons.lang3.exception.ExceptionUtils;
+
 import java.util.StringJoiner;
 
 import org.neo4j.kernel.api.labelscan.LabelScanStore.Monitor;
@@ -41,43 +43,43 @@ 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 notValidIndex()
     {
-        log.warn( "Scan store could not be read. Preparing to rebuild." );
+        log.warn( "Label index could not be read. Preparing to rebuild." );
     }
 
     @Override
     public void rebuilding()
     {
-        log.info( "Rebuilding scan store, this may take a while" );
+        log.info( "Rebuilding label index, this may take a while" );
     }
 
     @Override
     public void rebuilt( long roughNodeCount )
     {
-        log.info( "Scan store rebuilt (roughly " + roughNodeCount + " nodes)" );
+        log.info( "Label index rebuilt (roughly " + roughNodeCount + " nodes)" );
     }
 
     @Override
     public void recoveryCleanupRegistered()
     {
-        log.info( "Scan store cleanup job registered" );
+        log.info( "Label index cleanup job registered" );
     }
 
     @Override
     public void recoveryCleanupStarted()
     {
-        log.info( "Scan store cleanup job started" );
+        log.info( "Label index cleanup job started" );
     }
 
     @Override
     public void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCleanedCrashPointers, long durationMillis )
     {
-        StringJoiner joiner = new StringJoiner( ", ", "Scan store cleanup job finished: ", "" );
+        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 ) );
@@ -87,6 +89,12 @@ public void recoveryCleanupFinished( long numberOfPagesVisited, long numberOfCle
     @Override
     public void recoveryCleanupClosed()
     {
-        log.info( "Scan store cleanup job closed" );
+        log.info( "Label index cleanup job closed" );
+    }
+
+    @Override
+    public void recoveryCleanupFailed( Throwable throwable )
+    {
+        log.info( "Label index cleanup job failed.\nCaused by: " + ExceptionUtils.getStackTrace( throwable ) );
     }
 }
diff --git a/...nity/kernel/src/main/java/org/neo4j/kernel/impl/index/labelscan/NativeLabelScanStore.java b/...nity/kernel/src/main/java/org/neo4j/kernel/impl/index/labelscan/NativeLabelScanStore.java
@@ -375,33 +375,7 @@ private boolean instantiateTree() throws IOException
 
     private GBPTree.Monitor treeMonitor()
     {
-        return new 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();
-            }
-        };
+        return new LabelIndexTreeMonitor();
     }
 
     @Override
@@ -500,4 +474,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 );
+        }
+    }
 }