Skip to content

Commit

Permalink
Logging about page cache warmup start and completion.
Browse files Browse the repository at this point in the history
Add info log messages about page cache warmer start and completion.
Also, include a number of loaded pages and duration into completion
message.
  • Loading branch information
MishaDemianenko committed Sep 18, 2018
1 parent d54bc35 commit fc5186f
Show file tree
Hide file tree
Showing 9 changed files with 163 additions and 17 deletions.
Expand Up @@ -28,6 +28,7 @@
import org.neo4j.kernel.NeoStoreDataSource;
import org.neo4j.kernel.availability.DatabaseAvailabilityGuard;
import org.neo4j.kernel.configuration.Config;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerMonitor;
import org.neo4j.kernel.impl.transaction.state.NeoStoreFileListing;
import org.neo4j.kernel.lifecycle.LifecycleAdapter;
import org.neo4j.logging.Log;
Expand Down
Expand Up @@ -30,6 +30,8 @@
import org.neo4j.kernel.configuration.Config;
import org.neo4j.kernel.extension.ExtensionType;
import org.neo4j.kernel.extension.KernelExtensionFactory;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerLoggingMonitor;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerMonitor;
import org.neo4j.kernel.impl.spi.KernelContext;
import org.neo4j.kernel.lifecycle.Lifecycle;
import org.neo4j.kernel.monitoring.Monitors;
Expand Down Expand Up @@ -75,7 +77,9 @@ public Lifecycle newInstance( KernelContext context, Dependencies deps )
LogService logService = deps.logService();
NeoStoreDataSource dataSourceManager = deps.getDataSource();
Log log = logService.getInternalLog( PageCacheWarmer.class );
PageCacheWarmerMonitor monitor = deps.monitors().newMonitor( PageCacheWarmerMonitor.class );
Monitors monitors = deps.monitors();
PageCacheWarmerMonitor monitor = monitors.newMonitor( PageCacheWarmerMonitor.class );
monitors.addMonitorListener( new PageCacheWarmerLoggingMonitor( log ) );
Config config = deps.config();
return new PageCacheWarmerKernelExtension(
scheduler, databaseAvailabilityGuard, pageCache, fs, dataSourceManager, log, monitor, config );
Expand Down
Expand Up @@ -27,6 +27,7 @@
import org.neo4j.graphdb.factory.GraphDatabaseSettings;
import org.neo4j.kernel.availability.AvailabilityListener;
import org.neo4j.kernel.configuration.Config;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerMonitor;
import org.neo4j.logging.Log;
import org.neo4j.scheduler.Group;
import org.neo4j.scheduler.JobHandle;
Expand Down Expand Up @@ -73,6 +74,7 @@ private void startWarmup()
}
try
{
monitor.warmupStarted();
pageCacheWarmer.reheat().ifPresent( monitor::warmupCompleted );
}
catch ( Exception e )
Expand Down
@@ -0,0 +1,57 @@
/*
* Copyright (c) 2002-2018 "Neo4j,"
* Neo4j Sweden AB [http://neo4j.com]
*
* This file is part of Neo4j Enterprise Edition. The included source
* code can be redistributed and/or modified under the terms of the
* GNU AFFERO GENERAL PUBLIC LICENSE Version 3
* (http://www.fsf.org/licensing/licenses/agpl-3.0.html) with the
* Commons Clause, as found in the associated LICENSE.txt file.
*
* 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 Affero General Public License for more details.
*
* Neo4j object code can be licensed independently from the source
* under separate terms from the AGPL. Inquiries can be directed to:
* licensing@neo4j.com
*
* More information is also available at:
* https://neo4j.com/licensing/
*/
package org.neo4j.kernel.impl.pagecache.monitor;

import org.neo4j.logging.Log;

import static java.lang.System.currentTimeMillis;
import static org.neo4j.helpers.Format.duration;

public class PageCacheWarmerLoggingMonitor extends PageCacheWarmerMonitorAdapter
{
private final Log log;
private long warmupStartMillis;

public PageCacheWarmerLoggingMonitor( Log log )
{
this.log = log;
}

@Override
public void warmupStarted()
{
warmupStartMillis = currentTimeMillis();
log.info( "Page cache warmup started." );
}

@Override
public void warmupCompleted( long pagesLoaded )
{
log.info( "Page cache warmup completed. %d pages loaded. Duration: %s.", pagesLoaded, getDuration( warmupStartMillis ) );
}

private static String getDuration( long startTimeMillis )
{
return duration( currentTimeMillis() - startTimeMillis );
}
}
Expand Up @@ -20,10 +20,13 @@
* More information is also available at:
* https://neo4j.com/licensing/
*/
package org.neo4j.kernel.impl.pagecache;
package org.neo4j.kernel.impl.pagecache.monitor;

public interface PageCacheWarmerMonitor
{
void warmupStarted();

void warmupCompleted( long pagesLoaded );

void profileCompleted( long pagesInMemory );
}
@@ -0,0 +1,44 @@
/*
* Copyright (c) 2002-2018 "Neo4j,"
* Neo4j Sweden AB [http://neo4j.com]
*
* This file is part of Neo4j Enterprise Edition. The included source
* code can be redistributed and/or modified under the terms of the
* GNU AFFERO GENERAL PUBLIC LICENSE Version 3
* (http://www.fsf.org/licensing/licenses/agpl-3.0.html) with the
* Commons Clause, as found in the associated LICENSE.txt file.
*
* 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 Affero General Public License for more details.
*
* Neo4j object code can be licensed independently from the source
* under separate terms from the AGPL. Inquiries can be directed to:
* licensing@neo4j.com
*
* More information is also available at:
* https://neo4j.com/licensing/
*/
package org.neo4j.kernel.impl.pagecache.monitor;

public class PageCacheWarmerMonitorAdapter implements PageCacheWarmerMonitor
{
@Override
public void warmupStarted()
{
//nothing
}

@Override
public void warmupCompleted( long pagesLoaded )
{
//nothing
}

@Override
public void profileCompleted( long pagesInMemory )
{
//nothing
}
}
Expand Up @@ -37,7 +37,7 @@
import org.neo4j.ext.udc.UdcSettings;
import org.neo4j.graphdb.factory.GraphDatabaseSettings;
import org.neo4j.kernel.configuration.Settings;
import org.neo4j.kernel.impl.pagecache.PageCacheWarmerMonitor;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerMonitorAdapter;
import org.neo4j.kernel.monitoring.Monitors;
import org.neo4j.test.causalclustering.ClusterRule;
import org.neo4j.util.concurrent.BinaryLatch;
Expand Down Expand Up @@ -109,19 +109,14 @@ private static BinaryLatch injectWarmupLatch( ClusterMember member, AtomicLong p
{
BinaryLatch warmupLatch = new BinaryLatch();
Monitors monitors = member.monitors();
monitors.addMonitorListener( new PageCacheWarmerMonitor()
monitors.addMonitorListener( new PageCacheWarmerMonitorAdapter()
{
@Override
public void warmupCompleted( long pagesLoaded )
{
pagesLoadedInWarmup.set( pagesLoaded );
warmupLatch.release();
}

@Override
public void profileCompleted( long pagesInMemory )
{
}
} );
return warmupLatch;
}
Expand Down
Expand Up @@ -34,12 +34,15 @@
import org.neo4j.commandline.admin.CommandLocator;
import org.neo4j.commandline.admin.RealOutsideWorld;
import org.neo4j.ext.udc.UdcSettings;
import org.neo4j.graphdb.factory.GraphDatabaseFactory;
import org.neo4j.graphdb.factory.GraphDatabaseSettings;
import org.neo4j.io.fs.FileUtils;
import org.neo4j.kernel.configuration.Settings;
import org.neo4j.kernel.impl.enterprise.configuration.OnlineBackupSettings;
import org.neo4j.logging.AssertableLogProvider;
import org.neo4j.metrics.MetricsSettings;
import org.neo4j.ports.allocation.PortAuthority;
import org.neo4j.test.TestGraphDatabaseFactory;
import org.neo4j.test.rule.DatabaseRule;
import org.neo4j.test.rule.EnterpriseDatabaseRule;
import org.neo4j.test.rule.SuppressOutput;
Expand All @@ -58,12 +61,22 @@

public class PageCacheWarmupEnterpriseEditionIT extends PageCacheWarmupTestSupport
{
private final AssertableLogProvider logProvider = new AssertableLogProvider( true );

@Rule
public final SuppressOutput suppressOutput = SuppressOutput.suppressAll();
@Rule
public final TestDirectory testDirectory = TestDirectory.testDirectory();
@Rule
public final EnterpriseDatabaseRule db = new EnterpriseDatabaseRule( testDirectory ).startLazily();
public final EnterpriseDatabaseRule db = new EnterpriseDatabaseRule( testDirectory )
{
@Override
protected void configure( GraphDatabaseFactory databaseFactory )
{
super.configure( databaseFactory );
((TestGraphDatabaseFactory) databaseFactory).setInternalLogProvider( logProvider );
}
}.startLazily();

private static void verifyEventuallyWarmsUp( long pagesInMemory, File metricsDirectory ) throws Exception
{
Expand Down Expand Up @@ -199,4 +212,28 @@ public void exit( int status )

verifyEventuallyWarmsUp( pagesInMemory, metricsDirectory );
}

@Test
public void logPageCacheWarmupStartCompletionMessages() throws Exception
{
File metricsDirectory = testDirectory.directory( "metrics" );
db.withSetting( MetricsSettings.metricsEnabled, Settings.FALSE )
.withSetting( OnlineBackupSettings.online_backup_enabled, Settings.FALSE )
.withSetting( GraphDatabaseSettings.pagecache_warmup_profiling_interval, "100ms" );
db.ensureStarted();

createTestData( db );
long pagesInMemory = waitForCacheProfile( db.getMonitors() );

db.restartDatabase(
MetricsSettings.neoPageCacheEnabled.name(), Settings.TRUE,
MetricsSettings.csvEnabled.name(), Settings.TRUE,
MetricsSettings.csvInterval.name(), "100ms",
MetricsSettings.csvPath.name(), metricsDirectory.getAbsolutePath() );

verifyEventuallyWarmsUp( pagesInMemory, metricsDirectory );

logProvider.assertContainsMessageContaining( "Page cache warmup started." );
logProvider.assertContainsMessageContaining( "Page cache warmup completed. %d pages loaded. Duration: %s." );
}
}
Expand Up @@ -30,7 +30,8 @@
import org.neo4j.graphdb.Relationship;
import org.neo4j.graphdb.RelationshipType;
import org.neo4j.graphdb.Transaction;
import org.neo4j.kernel.impl.pagecache.PageCacheWarmerMonitor;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerMonitor;
import org.neo4j.kernel.impl.pagecache.monitor.PageCacheWarmerMonitorAdapter;
import org.neo4j.kernel.monitoring.Monitors;
import org.neo4j.util.concurrent.BinaryLatch;

Expand Down Expand Up @@ -74,7 +75,7 @@ static BinaryLatch pauseProfile( Monitors monitors )
return new PauseProfileMonitor( monitors );
}

private static class AwaitProfileMonitor implements PageCacheWarmerMonitor
private static class AwaitProfileMonitor extends PageCacheWarmerMonitorAdapter
{
private final AtomicLong pageCount;
private final BinaryLatch profileLatch;
Expand All @@ -85,11 +86,6 @@ private static class AwaitProfileMonitor implements PageCacheWarmerMonitor
this.profileLatch = profileLatch;
}

@Override
public void warmupCompleted( long pagesLoaded )
{
}

@Override
public void profileCompleted( long pagesInMemory )
{
Expand All @@ -108,9 +104,16 @@ private static class PauseProfileMonitor extends BinaryLatch implements PageCach
monitors.addMonitorListener( this );
}

@Override
public void warmupStarted()
{
//nothing
}

@Override
public void warmupCompleted( long pagesLoaded )
{
//nothing
}

@Override
Expand Down

0 comments on commit fc5186f

Please sign in to comment.