diff --git a/community/community-it/index-it/src/test/java/schema/IndexPopulationIT.java b/community/community-it/index-it/src/test/java/schema/IndexPopulationIT.java index 7244958070d55..65971d9ea36c1 100644 --- a/community/community-it/index-it/src/test/java/schema/IndexPopulationIT.java +++ b/community/community-it/index-it/src/test/java/schema/IndexPopulationIT.java @@ -39,7 +39,6 @@ import org.neo4j.graphdb.ResourceIterator; import org.neo4j.graphdb.Result; import org.neo4j.graphdb.Transaction; -import org.neo4j.graphdb.factory.GraphDatabaseFactory; import org.neo4j.helpers.collection.Iterables; import org.neo4j.helpers.collection.Iterators; import org.neo4j.kernel.impl.api.index.IndexPopulationJob; @@ -48,6 +47,8 @@ import org.neo4j.test.rule.TestDirectory; import org.neo4j.values.storable.RandomValues; +import static org.hamcrest.Matchers.allOf; +import static org.hamcrest.Matchers.containsString; import static org.junit.Assert.assertEquals; public class IndexPopulationIT @@ -58,11 +59,15 @@ public class IndexPopulationIT private static final int TEST_TIMEOUT = 120_000; private static GraphDatabaseService database; private static ExecutorService executorService; + private static AssertableLogProvider logProvider; @BeforeClass public static void setUp() { - database = new GraphDatabaseFactory().newEmbeddedDatabase( directory.storeDir() ); + TestGraphDatabaseFactory factory = new TestGraphDatabaseFactory(); + logProvider = new AssertableLogProvider( true ); + factory.setInternalLogProvider( logProvider ); + database = factory.newEmbeddedDatabase( directory.storeDir() ); executorService = Executors.newCachedThreadPool(); } @@ -157,6 +162,44 @@ public void shutdownDatabaseDuringIndexPopulations() assertableLogProvider.assertNone( AssertableLogProvider.inLog( IndexPopulationJob.class ).anyError() ); } + @Test + public void mustLogPhaseTracker() + { + Label nodeLabel = Label.label( "testLabel5" ); + try ( Transaction transaction = database.beginTx() ) + { + database.createNode( nodeLabel ).setProperty( "key", "hej" ); + transaction.success(); + } + + // when + try ( Transaction tx = database.beginTx() ) + { + database.schema().indexFor( nodeLabel ).on( "key" ).create(); + tx.success(); + } + try ( Transaction tx = database.beginTx() ) + { + database.schema().awaitIndexesOnline( 1, TimeUnit.MINUTES ); + tx.success(); + } + + // then + //noinspection unchecked + logProvider.assertContainsMessageMatching( allOf( + containsString( "TIME/PHASE" ), + containsString( "Final: " ), + containsString( "SCAN" ), + containsString( "WRITE" ), + containsString( "FLIP" ), + containsString( "totalTime=" ), + containsString( "avgTime=" ), + containsString( "minTime=" ), + containsString( "maxTime=" ), + containsString( "nbrOfReports=" ) + ) ); + } + private void prePopulateDatabase( GraphDatabaseService database, Label testLabel, String propertyName ) { final RandomValues randomValues = RandomValues.create(); diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/BatchingMultipleIndexPopulator.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/BatchingMultipleIndexPopulator.java index efcb987f212de..8c40c8b3103a5 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/BatchingMultipleIndexPopulator.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/BatchingMultipleIndexPopulator.java @@ -154,11 +154,12 @@ private void awaitCompletion() /** * Insert the given batch of updates into the index defined by the given {@link IndexPopulation}. + * Called from {@link MultipleIndexPopulator#flush(IndexPopulation)}. * * @param population the index population. */ @Override - protected void flush( IndexPopulation population ) + void doFlush( IndexPopulation population ) { activeTasks.incrementAndGet(); Collection> batch = population.takeCurrentBatch(); 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 new file mode 100644 index 0000000000000..475bdc7e49bff --- /dev/null +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTracker.java @@ -0,0 +1,231 @@ +/* + * 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.api.index; + +import java.util.EnumMap; +import java.util.StringJoiner; +import java.util.concurrent.TimeUnit; + +import org.neo4j.helpers.TimeUtil; +import org.neo4j.logging.Log; +import org.neo4j.util.FeatureToggles; + +public class LoggingPhaseTracker implements PhaseTracker +{ + + private static final int PERIOD_INTERVAL = FeatureToggles.getInteger( LoggingPhaseTracker.class, "period_interval", 600 ); + private static final String MESSAGE_PREFIX = "TIME/PHASE "; + + private final long periodIntervalInSeconds; + private final Log log; + + private EnumMap times = new EnumMap<>( Phase.class ); + private Phase currentPhase; + private long timeEnterPhase; + private boolean stopped; + private long lastPeriodReport = -1; + + LoggingPhaseTracker( Log log ) + { + this( PERIOD_INTERVAL, log ); + } + + LoggingPhaseTracker( long periodIntervalInSeconds, Log log ) + { + this.periodIntervalInSeconds = periodIntervalInSeconds; + this.log = log; + for ( Phase phase : Phase.values() ) + { + times.put( phase, new Logger( phase ) ); + } + } + + @Override + public void enterPhase( Phase phase ) + { + if ( stopped ) + { + throw new IllegalStateException( "Trying to report a new phase after phase tracker has been stopped." ); + } + if ( phase != currentPhase ) + { + long now = logCurrentTime(); + currentPhase = phase; + timeEnterPhase = now; + + if ( lastPeriodReport == -1 ) + { + lastPeriodReport = now; + } + + long secondsSinceLastPeriodReport = TimeUnit.NANOSECONDS.toSeconds( now - lastPeriodReport ); + if ( secondsSinceLastPeriodReport >= periodIntervalInSeconds ) + { + // Report period + periodReport( secondsSinceLastPeriodReport ); + lastPeriodReport = now; + } + } + } + + @Override + public void stop() + { + stopped = true; + logCurrentTime(); + currentPhase = null; + finalReport(); + } + + EnumMap times() + { + return times; + } + + private void finalReport() + { + log.debug( MESSAGE_PREFIX + mainReportString( "Final" ) ); + } + + private void periodReport( long secondsSinceLastPeriodReport ) + { + String periodReportString = periodReportString( secondsSinceLastPeriodReport ); + String mainReportString = mainReportString( "Total" ); + log.debug( MESSAGE_PREFIX + mainReportString + ", " + periodReportString ); + } + + private String mainReportString( String title ) + { + StringJoiner joiner = new StringJoiner( ", ", title + ": ", "" ); + times.values().forEach( p -> joiner.add( p.toString() ) ); + return joiner.toString(); + } + + private String periodReportString( long secondsSinceLastPeriodReport ) + { + StringJoiner joiner = new StringJoiner( ", ", "Last " + secondsSinceLastPeriodReport + " sec: ", "" ); + times.values().forEach( logger -> + { + joiner.add( logger.period().toString() ); + logger.period().reset(); + } ); + return joiner.toString(); + } + + private long logCurrentTime() + { + long now = System.nanoTime(); + if ( currentPhase != null ) + { + Logger logger = times.get( currentPhase ); + long nanoTime = now - timeEnterPhase; + logger.log( nanoTime ); + } + return now; + } + + public class Logger extends Counter + { + final Counter periodCounter; + + private Logger( Phase phase ) + { + super( phase ); + periodCounter = new Counter( phase ); + periodCounter.reset(); + } + + void log( long nanoTime ) + { + super.log( nanoTime ); + periodCounter.log( nanoTime ); + } + + Counter period() + { + return periodCounter; + } + } + + public class Counter + { + private final Phase phase; + long totalTime; + long nbrOfReports; + long maxTime; + long minTime; + + Counter( Phase phase ) + { + this.phase = phase; + } + + void log( long nanoTime ) + { + totalTime += nanoTime; + nbrOfReports++; + maxTime = Math.max( maxTime, nanoTime ); + minTime = Math.min( minTime, nanoTime ); + } + + void reset() + { + totalTime = 0; + nbrOfReports = 0; + maxTime = Long.MIN_VALUE; + minTime = Long.MAX_VALUE; + } + + @Override + public String toString() + { + StringJoiner joiner = new StringJoiner( ", ", phase.toString() + "[", "]" ); + if ( nbrOfReports == 0 ) + { + addToString( "nbrOfReports", nbrOfReports, joiner, false ); + } + else + { + long avgTime = totalTime / nbrOfReports; + addToString( "totalTime", totalTime, joiner, true ); + addToString( "avgTime", avgTime, joiner, true ); + addToString( "minTime", minTime, joiner, true ); + addToString( "maxTime", maxTime, joiner, true ); + addToString( "nbrOfReports", nbrOfReports, joiner, false ); + } + return joiner.toString(); + } + + void addToString( String name, long measurement, StringJoiner joiner, boolean isTime ) + { + String measurementString; + if ( isTime ) + { + long timeRoundedToMillis = TimeUnit.MILLISECONDS.toNanos( TimeUnit.NANOSECONDS.toMillis( measurement ) ); + measurementString = TimeUtil.nanosToString( timeRoundedToMillis ); + } + else + { + measurementString = Long.toString( measurement ); + } + joiner.add( String.format( "%s=%s", name, measurementString ) ); + } + } +} diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulator.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulator.java index 883b9ad1eda64..94ee46de62df3 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulator.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulator.java @@ -106,6 +106,7 @@ public class MultipleIndexPopulator implements IndexPopulator protected final Log log; private final EntityType type; private final SchemaState schemaState; + private final PhaseTracker phaseTracker; private StoreScan storeScan; public MultipleIndexPopulator( IndexStoreView storeView, LogProvider logProvider, EntityType type, SchemaState schemaState ) @@ -115,6 +116,7 @@ public MultipleIndexPopulator( IndexStoreView storeView, LogProvider logProvider this.log = logProvider.getLog( IndexPopulationJob.class ); this.type = type; this.schemaState = schemaState; + this.phaseTracker = new LoggingPhaseTracker( logProvider.getLog( IndexPopulationJob.class ) ); } IndexPopulation addPopulator( IndexPopulator populator, CapableIndexDescriptor capableIndexDescriptor, FlippableIndexProxy flipper, @@ -172,6 +174,7 @@ StoreScan indexAllEntities() { storeScan = storeView.visitNodes( entityTokenIds, propertyKeyIdFilter, new EntityPopulationVisitor(), null, false ); } + storeScan.setPhaseTracker( phaseTracker ); return new DelegatingStoreScan( storeScan ) { @Override @@ -268,6 +271,7 @@ public MultipleIndexUpdater newPopulatingUpdater( NodePropertyAccessor accessor @Override public void close( boolean populationCompletedSuccessfully ) { + phaseTracker.stop(); // closing the populators happens in flip, fail or individually when they are completed } @@ -355,6 +359,12 @@ void flushAll() } protected void flush( IndexPopulation population ) + { + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.WRITE ); + doFlush( population ); + } + + void doFlush( IndexPopulation population ) { try { @@ -553,6 +563,7 @@ private void onUpdate( IndexEntryUpdate update ) void flip( boolean verifyBeforeFlipping ) throws FlipFailedKernelException { + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.FLIP ); flipper.flip( () -> { populatorLock.lock(); @@ -678,5 +689,11 @@ public PopulationProgress getProgress() { return delegate.getProgress(); } + + @Override + public void setPhaseTracker( PhaseTracker phaseTracker ) + { + delegate.setPhaseTracker( phaseTracker ); + } } } 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 index 43aa99e6591c6..9d54898693ba6 100644 --- 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 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2002-2018 "Neo4j," + * Copyright (c) 2002-2019 "Neo4j," * Neo4j Sweden AB [http://neo4j.com] * * This file is part of Neo4j. @@ -19,216 +19,31 @@ */ package org.neo4j.kernel.impl.api.index; -import java.util.EnumMap; -import java.util.StringJoiner; -import java.util.concurrent.TimeUnit; - -import org.neo4j.helpers.TimeUtil; -import org.neo4j.logging.Log; -import org.neo4j.util.FeatureToggles; - -public class PhaseTracker +public interface PhaseTracker { - public enum Phase - { - SCAN, - WRITE, - FLIP; - } - - private static final int PERIOD_INTERVAL = FeatureToggles.getInteger( PhaseTracker.class, "period_interval", 600 ); - private static final String MESSAGE_PREFIX = "TIME/PHASE "; - - private final long periodIntervalInSeconds; - private final Log log; - - private EnumMap times = new EnumMap<>( Phase.class ); - private Phase currentPhase; - private long timeEnterPhase; - private boolean stopped; - private long lastPeriodReport = -1; - - PhaseTracker( Log log ) - { - this( PERIOD_INTERVAL, log ); - } - - PhaseTracker( long periodIntervalInSeconds, Log log ) - { - this.periodIntervalInSeconds = periodIntervalInSeconds; - this.log = log; - for ( Phase phase : Phase.values() ) - { - times.put( phase, new Logger( phase ) ); - } - } - - public void enterPhase( Phase phase ) - { - if ( stopped ) - { - throw new IllegalStateException( "Trying to report a new phase after phase tracker has been stopped." ); - } - if ( phase != currentPhase ) - { - long now = logCurrentTime(); - currentPhase = phase; - timeEnterPhase = now; - - if ( lastPeriodReport == -1 ) - { - lastPeriodReport = now; - } - - long secondsSinceLastPeriodReport = TimeUnit.NANOSECONDS.toSeconds( now - lastPeriodReport ); - if ( secondsSinceLastPeriodReport >= periodIntervalInSeconds ) - { - // Report period - reportPeriod( secondsSinceLastPeriodReport ); - lastPeriodReport = now; - } - } - } - - void stop() - { - stopped = true; - logCurrentTime(); - currentPhase = null; - } - - void reportMain( String title ) - { - log.debug( MESSAGE_PREFIX + mainReportString( title ) ); - } - - private void reportPeriod( long secondsSinceLastPeriodReport ) - { - String periodReportString = periodReportString( secondsSinceLastPeriodReport ); - String mainReportString = mainReportString( "Total" ); - log.debug( MESSAGE_PREFIX + mainReportString + ", " + periodReportString ); - } + void enterPhase( Phase phase ); - private String mainReportString( String title ) - { - StringJoiner joiner = new StringJoiner( ", ", title + ": ", "" ); - times.values().forEach( p -> joiner.add( p.toString() ) ); - return joiner.toString(); - } - - private String periodReportString( long secondsSinceLastPeriodReport ) - { - StringJoiner joiner = new StringJoiner( ", ", "Last " + secondsSinceLastPeriodReport + " sec: ", "" ); - times.values().forEach( logger -> - { - joiner.add( logger.period().toString() ); - logger.period().reset(); - } ); - return joiner.toString(); - } - - public EnumMap times() - { - return times; - } + void stop(); - private long logCurrentTime() - { - long now = System.nanoTime(); - if ( currentPhase != null ) - { - Logger logger = times.get( currentPhase ); - long nanoTime = now - timeEnterPhase; - logger.log( nanoTime ); - } - return now; - } + PhaseTracker nullInstance = new NullPhaseTracker(); - public class Logger extends Counter + enum Phase { - final Counter periodCounter; - - private Logger( Phase phase ) - { - super( phase ); - periodCounter = new Counter( phase ); - periodCounter.reset(); - } - - void log( long nanoTime ) - { - super.log( nanoTime ); - periodCounter.log( nanoTime ); - } - - Counter period() - { - return periodCounter; - } + SCAN, + WRITE, + FLIP } - public class Counter + class NullPhaseTracker implements PhaseTracker { - private final Phase phase; - long totalTime; - long nbrOfReports; - long maxTime; - long minTime; - - Counter( Phase phase ) - { - this.phase = phase; - } - - void log( long nanoTime ) - { - totalTime += nanoTime; - nbrOfReports++; - maxTime = Math.max( maxTime, nanoTime ); - minTime = Math.min( minTime, nanoTime ); - } - - void reset() - { - totalTime = 0; - nbrOfReports = 0; - maxTime = Long.MIN_VALUE; - minTime = Long.MAX_VALUE; - } - @Override - public String toString() + public void enterPhase( Phase phase ) { - StringJoiner joiner = new StringJoiner( ", ", phase.toString() + "[", "]" ); - if ( nbrOfReports == 0 ) - { - addToString( "nbrOfReports", nbrOfReports, joiner, false ); - } - else - { - long avgTime = totalTime / nbrOfReports; - addToString( "totalTime", totalTime, joiner, true ); - addToString( "avgTime", avgTime, joiner, true ); - addToString( "minTime", minTime, joiner, true ); - addToString( "maxTime", maxTime, joiner, true ); - addToString( "nbrOfReports", nbrOfReports, joiner, false ); - } - return joiner.toString(); } - void addToString( String name, long measurement, StringJoiner joiner, boolean isTime ) + @Override + public void stop() { - String measurementString; - if ( isTime ) - { - long timeRoundedToMillis = TimeUnit.MILLISECONDS.toNanos( TimeUnit.NANOSECONDS.toMillis( measurement ) ); - measurementString = TimeUtil.nanosToString( timeRoundedToMillis ); - } - else - { - measurementString = Long.toString( measurement ); - } - joiner.add( String.format( "%s=%s", name, measurementString ) ); } } } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/StoreScan.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/StoreScan.java index 3aafc6c72dfa4..d1379e27797ef 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/StoreScan.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/api/index/StoreScan.java @@ -32,4 +32,13 @@ void acceptUpdate( MultipleIndexPopulator.MultipleIndexUpdater updater, IndexEnt long currentlyIndexedNodeId ); PopulationProgress getProgress(); + + /** + * Give this {@link StoreScan} a {@link PhaseTracker} to report to. + * Must not be called once scan has already started. + * @param phaseTracker {@link PhaseTracker} this store scan shall report to. + */ + default void setPhaseTracker( PhaseTracker phaseTracker ) + { // no-op + } } diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/transaction/state/storeview/PropertyAwareEntityStoreScan.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/transaction/state/storeview/PropertyAwareEntityStoreScan.java index 1ad1c0037908a..37437e68b375f 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/transaction/state/storeview/PropertyAwareEntityStoreScan.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/transaction/state/storeview/PropertyAwareEntityStoreScan.java @@ -27,7 +27,9 @@ import org.neo4j.io.IOUtils; import org.neo4j.kernel.api.index.IndexEntryUpdate; import org.neo4j.kernel.impl.api.index.EntityUpdates; +import org.neo4j.kernel.impl.api.index.LoggingPhaseTracker; import org.neo4j.kernel.impl.api.index.MultipleIndexPopulator; +import org.neo4j.kernel.impl.api.index.PhaseTracker; import org.neo4j.kernel.impl.api.index.StoreScan; import org.neo4j.kernel.impl.locking.Lock; import org.neo4j.storageengine.api.StorageEntityScanCursor; @@ -46,6 +48,7 @@ public abstract class PropertyAwareEntityStoreScan lockFunction; + private PhaseTracker phaseTracker; protected PropertyAwareEntityStoreScan( StorageReader storageReader, long totalEntityCount, IntPredicate propertyKeyIdFilter, LongFunction lockFunction ) @@ -56,6 +59,7 @@ protected PropertyAwareEntityStoreScan( StorageReader storageReader, long totalE this.propertyKeyIdFilter = propertyKeyIdFilter; this.lockFunction = lockFunction; this.totalCount = totalEntityCount; + this.phaseTracker = PhaseTracker.nullInstance; } protected abstract CURSOR allocateCursor( StorageReader storageReader ); @@ -106,6 +110,7 @@ public void run() throws FAILURE continueScanning = true; while ( continueScanning && entityIdIterator.hasNext() ) { + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); long id = entityIdIterator.next(); try ( Lock ignored = lockFunction.apply( id ) ) { @@ -161,6 +166,12 @@ public PopulationProgress getProgress() return PopulationProgress.DONE; } + @Override + public void setPhaseTracker( PhaseTracker phaseTracker ) + { + this.phaseTracker = phaseTracker; + } + protected EntityIdIterator getEntityIdIterator() { return new EntityIdIterator() diff --git a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/PhaseTrackerTest.java b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTrackerTest.java similarity index 70% rename from community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/PhaseTrackerTest.java rename to community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTrackerTest.java index f3b21acd8122b..5116628949a7f 100644 --- a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/PhaseTrackerTest.java +++ b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/LoggingPhaseTrackerTest.java @@ -1,5 +1,5 @@ /* - * Copyright (c) 2002-2018 "Neo4j," + * Copyright (c) 2002-2019 "Neo4j," * Neo4j Sweden AB [http://neo4j.com] * * This file is part of Neo4j. @@ -36,22 +36,22 @@ import static org.junit.Assert.assertTrue; import static org.junit.Assert.fail; -public class PhaseTrackerTest +public class LoggingPhaseTrackerTest { @Test public void shouldLogSingleTime() throws InterruptedException { - PhaseTracker phaseTracker = getPhaseTracker(); + LoggingPhaseTracker phaseTracker = getPhaseTracker(); - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); sleep( 100 ); phaseTracker.stop(); - EnumMap times = phaseTracker.times(); - for ( PhaseTracker.Phase phase : times.keySet() ) + EnumMap times = phaseTracker.times(); + for ( LoggingPhaseTracker.Phase phase : times.keySet() ) { - PhaseTracker.Logger logger = times.get( phase ); - if ( phase == PhaseTracker.Phase.SCAN ) + LoggingPhaseTracker.Logger logger = times.get( phase ); + if ( phase == LoggingPhaseTracker.Phase.SCAN ) { assertTrue( logger.totalTime >= TimeUnit.MILLISECONDS.toNanos( 100 ) ); assertTrue( logger.totalTime < TimeUnit.MILLISECONDS.toNanos( 500 ) ); @@ -66,20 +66,20 @@ public void shouldLogSingleTime() throws InterruptedException @Test public void shouldLogMultipleTimes() throws InterruptedException { - PhaseTracker phaseTracker = getPhaseTracker(); + LoggingPhaseTracker phaseTracker = getPhaseTracker(); - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); sleep( 100 ); - phaseTracker.enterPhase( PhaseTracker.Phase.WRITE ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.WRITE ); sleep( 100 ); phaseTracker.stop(); - EnumMap times = phaseTracker.times(); - for ( PhaseTracker.Phase phase : times.keySet() ) + EnumMap times = phaseTracker.times(); + for ( LoggingPhaseTracker.Phase phase : times.keySet() ) { - PhaseTracker.Logger logger = times.get( phase ); - if ( phase == PhaseTracker.Phase.SCAN || - phase == PhaseTracker.Phase.WRITE ) + LoggingPhaseTracker.Logger logger = times.get( phase ); + if ( phase == LoggingPhaseTracker.Phase.SCAN || + phase == LoggingPhaseTracker.Phase.WRITE ) { assertTrue( logger.totalTime >= TimeUnit.MILLISECONDS.toNanos( 100 ) ); assertTrue( logger.totalTime < TimeUnit.MILLISECONDS.toNanos( 500 ) ); @@ -94,14 +94,14 @@ public void shouldLogMultipleTimes() throws InterruptedException @Test public void shouldAccumulateTimes() throws InterruptedException { - PhaseTracker phaseTracker = getPhaseTracker(); + LoggingPhaseTracker phaseTracker = getPhaseTracker(); - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); sleep( 100 ); - phaseTracker.enterPhase( PhaseTracker.Phase.WRITE ); - PhaseTracker.Logger scanLogger = phaseTracker.times().get( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.WRITE ); + LoggingPhaseTracker.Logger scanLogger = phaseTracker.times().get( LoggingPhaseTracker.Phase.SCAN ); long firstCount = scanLogger.totalTime; - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); sleep( 100 ); phaseTracker.stop(); @@ -115,7 +115,7 @@ public void throwIfEnterAfterStop() phaseTracker.stop(); try { - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); fail( "Should have failed" ); } catch ( IllegalStateException e ) @@ -131,16 +131,15 @@ public void mustReportMain() throws InterruptedException AssertableLogProvider logProvider = new AssertableLogProvider( true ); Log log = logProvider.getLog( IndexPopulationJob.class ); PhaseTracker phaseTracker = getPhaseTracker( log ); - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); sleep( 100 ); - phaseTracker.enterPhase( PhaseTracker.Phase.WRITE ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.WRITE ); sleep( 100 ); - phaseTracker.enterPhase( PhaseTracker.Phase.FLIP ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.FLIP ); sleep( 100 ); // when phaseTracker.stop(); - phaseTracker.reportMain( "Final" ); // then //noinspection unchecked @@ -165,11 +164,11 @@ public void mustReportPeriod() throws InterruptedException AssertableLogProvider logProvider = new AssertableLogProvider( true ); Log log = logProvider.getLog( IndexPopulationJob.class ); PhaseTracker phaseTracker = getPhaseTracker( 1, log ); - phaseTracker.enterPhase( PhaseTracker.Phase.SCAN ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.SCAN ); // when sleep( 1000 ); - phaseTracker.enterPhase( PhaseTracker.Phase.WRITE ); + phaseTracker.enterPhase( LoggingPhaseTracker.Phase.WRITE ); // then //noinspection unchecked @@ -187,18 +186,18 @@ public void mustReportPeriod() throws InterruptedException ) ); } - private PhaseTracker getPhaseTracker() + private LoggingPhaseTracker getPhaseTracker() { return getPhaseTracker( NullLog.getInstance() ); } - private PhaseTracker getPhaseTracker( Log log ) + private LoggingPhaseTracker getPhaseTracker( Log log ) { - return new PhaseTracker( log ); + return new LoggingPhaseTracker( log ); } private PhaseTracker getPhaseTracker( int periodIntervalInSeconds, Log log ) { - return new PhaseTracker( periodIntervalInSeconds, log ); + return new LoggingPhaseTracker( periodIntervalInSeconds, log ); } } diff --git a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulatorTest.java b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulatorTest.java index ab1e0164ae39f..a2270a2ad1a2f 100644 --- a/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulatorTest.java +++ b/community/kernel/src/test/java/org/neo4j/kernel/impl/api/index/MultipleIndexPopulatorTest.java @@ -71,10 +71,8 @@ public class MultipleIndexPopulatorTest { private final LabelSchemaDescriptor index1 = SchemaDescriptorFactory.forLabel( 1, 1 ); - @Mock + @Mock( answer = Answers.RETURNS_MOCKS ) private IndexStoreView indexStoreView; - @Mock - private StoreScan storeScan; @Mock( answer = Answers.RETURNS_MOCKS ) private LogProvider logProvider; @Mock