PhaseTracker include APPLY_EXTERNAL

APPLY_EXTERNAL is the phase in which BlockBasedIndexPopulator apply external updates to the tree and verify that those don't create any uniqueness conflict if index is unique index. Also: * PhaseTracker does not include measurements for Phases that has 0 calls. * PhaseTracker only print totalTime if Phase only has a single call.
neo4j · Feb 26, 2019 · 17ea0b0 · 17ea0b0
1 parent 8f29a87
commit 17ea0b0
Show file tree

Hide file tree

Showing 4 changed files with 66 additions and 30 deletions.
diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTracker.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTracker.java
@@ -118,22 +118,36 @@ private void periodReport( long millisSinceLastPerioReport )
     private String mainReportString( String title )
     {
         StringJoiner joiner = new StringJoiner( ", ", title + ": ", "" );
-        times.values().forEach( p -> joiner.add( p.toString() ) );
+        times.values().forEach( logger ->
+        {
+            reportToJoiner( joiner, logger );
+        } );
         return joiner.toString();
     }
 
     private String periodReportString( long millisSinceLastPeriodReport )
     {
         long secondsSinceLastPeriodReport = TimeUnit.MILLISECONDS.toSeconds( millisSinceLastPeriodReport );
         StringJoiner joiner = new StringJoiner( ", ", "Last " + secondsSinceLastPeriodReport + " sec: ", "" );
-        times.values().forEach( logger ->
+        times.values().stream()
-        {
+                .map( Logger::period )
-            joiner.add( logger.period().toString() );
+                .forEach( period ->
-            logger.period().reset();
+                {
-        } );
+                    reportToJoiner( joiner, period );
+                    period.reset();
+
+                } );
         return joiner.toString();
     }
 
+    private void reportToJoiner( StringJoiner joiner, Counter counter )
+    {
+        if ( counter.nbrOfReports > 0 )
+        {
+            joiner.add( counter.toString() );
+        }
+    }
+
     private long logCurrentTime()
     {
         long now = clock.millis();
@@ -206,6 +220,10 @@ public String toString()
             {
                 addToString( "nbrOfReports", nbrOfReports, joiner, false );
             }
+            else if ( nbrOfReports == 1 )
+            {
+                addToString( "totalTime", totalTime, joiner, true );
+            }
             else
             {
                 long avgTime = totalTime / nbrOfReports;

diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/PhaseTracker.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/PhaseTracker.java
@@ -29,11 +29,14 @@ public interface PhaseTracker
 
     enum Phase
     {
+        // The order in which the phases are declared defines the order in which they will be printed in the log.
+        // Keep them arranged in the order in which they naturally are seen during index population.
         SCAN,
         WRITE,
         MERGE,
         BUILD,
-        FLIP
+        APPLY_EXTERNAL,
+        FLIP;
     }
 
     class NullPhaseTracker implements PhaseTracker

diff --git a/...ity/kernel/src/main/java/org/neo4j/kernel/impl/index/schema/BlockBasedIndexPopulator.java b/...ity/kernel/src/main/java/org/neo4j/kernel/impl/index/schema/BlockBasedIndexPopulator.java
@@ -225,6 +225,7 @@ public void scanCompleted( PhaseTracker phaseTracker ) throws IndexEntryConflict
             writeScanUpdatesToTree();
 
             // Apply the external updates
+            phaseTracker.enterPhase( PhaseTracker.Phase.APPLY_EXTERNAL );
             writeExternalUpdatesToTree();
             merged = true;
         }

diff --git a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTrackerTest.java b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTrackerTest.java
@@ -137,25 +137,28 @@ public void mustReportMain()
         sleep( 100 );
         phaseTracker.enterPhase( PhaseTracker.Phase.WRITE );
         sleep( 100 );
+        phaseTracker.enterPhase( PhaseTracker.Phase.SCAN );
+        sleep( 100 );
+        phaseTracker.enterPhase( PhaseTracker.Phase.WRITE );
+        sleep( 100 );
         phaseTracker.enterPhase( PhaseTracker.Phase.MERGE );
         sleep( 100 );
         phaseTracker.enterPhase( PhaseTracker.Phase.BUILD );
         sleep( 100 );
+        phaseTracker.enterPhase( PhaseTracker.Phase.APPLY_EXTERNAL );
+        sleep( 100 );
         phaseTracker.enterPhase( PhaseTracker.Phase.FLIP );
         sleep( 100 );
 
         // when
         phaseTracker.stop();
 
         // then
-        AssertableLogProvider.LogMatcher logMatcher = AssertableLogProvider.
+        AssertableLogProvider.LogMatcher logMatcher = AssertableLogProvider.inLog( IndexPopulationJob.class ).info(
-                inLog( IndexPopulationJob.class )
+                "TIME/PHASE Final: " +
-                .info( "TIME/PHASE Final: " +
+                        "SCAN[totalTime=200ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=2], " +
-                        "SCAN[totalTime=100ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=1], " +
+                        "WRITE[totalTime=200ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=2], " +
-                        "WRITE[totalTime=100ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=1], " +
+                        "MERGE[totalTime=100ms], BUILD[totalTime=100ms], APPLY_EXTERNAL[totalTime=100ms], FLIP[totalTime=100ms]" );
-                        "MERGE[totalTime=100ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=1], " +
-                        "BUILD[totalTime=100ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=1], " +
-                        "FLIP[totalTime=100ms, avgTime=100ms, minTime=0ns, maxTime=100ms, nbrOfReports=1]" );
         logProvider.assertAtLeastOnce( logMatcher );
     }
 
@@ -173,21 +176,32 @@ public void mustReportPeriod()
         phaseTracker.enterPhase( PhaseTracker.Phase.WRITE );
 
         // then
-        AssertableLogProvider.LogMatcher logMatcher = AssertableLogProvider.
+        AssertableLogProvider.LogMatcher firstEntry =
-                inLog( IndexPopulationJob.class )
+                AssertableLogProvider.inLog( IndexPopulationJob.class ).debug( "TIME/PHASE Total: SCAN[totalTime=1s], Last 1 sec: SCAN[totalTime=1s]" );
-                .debug( "TIME/PHASE Total: " +
+        logProvider.assertExactly( firstEntry );
-                        "SCAN[totalTime=1s, avgTime=1s, minTime=0ns, maxTime=1s, nbrOfReports=1], " +
+
-                        "WRITE[nbrOfReports=0], " +
+        // when
-                        "MERGE[nbrOfReports=0], " +
+        sleep( 1000 );
-                        "BUILD[nbrOfReports=0], " +
+        phaseTracker.enterPhase( PhaseTracker.Phase.SCAN );
-                        "FLIP[nbrOfReports=0], " +
+
-                        "Last 1 sec: " +
+        // then
-                        "SCAN[totalTime=1s, avgTime=1s, minTime=1s, maxTime=1s, nbrOfReports=1], " +
+        AssertableLogProvider.LogMatcher secondEntry =
-                        "WRITE[nbrOfReports=0], " +
+                AssertableLogProvider.inLog( IndexPopulationJob.class )
-                        "MERGE[nbrOfReports=0], " +
+                        .debug( "TIME/PHASE Total: SCAN[totalTime=1s], WRITE[totalTime=1s], Last 1 sec: WRITE[totalTime=1s]" );
-                        "BUILD[nbrOfReports=0], " +
+        logProvider.assertExactly( firstEntry, secondEntry );
-                        "FLIP[nbrOfReports=0]" );
+
-        logProvider.assertAtLeastOnce( logMatcher );
+        // when
+        sleep( 1000 );
+        phaseTracker.enterPhase( PhaseTracker.Phase.WRITE );
+
+        // then
+        AssertableLogProvider.LogMatcher thirdEntry =
+                AssertableLogProvider.inLog( IndexPopulationJob.class )
+                        .debug( "TIME/PHASE Total: " +
+                                "SCAN[totalTime=2s, avgTime=1s, minTime=0ns, maxTime=1s, nbrOfReports=2], " +
+                                "WRITE[totalTime=1s], " +
+                                "Last 1 sec: SCAN[totalTime=1s]" );
+        logProvider.assertExactly( firstEntry, secondEntry, thirdEntry );
     }
 
     private LoggingPhaseTracker getPhaseTracker()