Skip to content

Commit

Permalink
Query log rotation
Browse files Browse the repository at this point in the history 
Add possibility to rotate query. Rotation threshold is specified by 'dbms.querylog.rotation.threshold' property
and maximum number of history files to keep by 'dbms.querylog.max_archives'.
By default rotation will happen each 20m and we will keep 7 files.
  • Loading branch information
@MishaDemianenko
MishaDemianenko committed Sep 16, 2015
1 parent 56a0b13 commit e0a8ba6
Show file tree
Hide file tree
Showing 4 changed files with 166 additions and 111 deletions.
11 changes: 10 additions & 1 deletion community/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java
View file
Expand Up @@ -465,9 +465,18 @@ private static String defaultPageCacheMemory()
public static final Setting<File> log_queries_filename = setting("dbms.querylog.filename", PATH, NO_DEFAULT ); public static final Setting<File> log_queries_filename = setting("dbms.querylog.filename", PATH, NO_DEFAULT );


@Description("If the execution of query takes more time than this threshold, the query is logged - " + @Description("If the execution of query takes more time than this threshold, the query is logged - " +
"provided query logging is enabled. Defaults to 0 seconds, that is all queries are logged.") "provided query logging is enabled. Defaults to 0 seconds, that is all queries are logged.")
public static final Setting<Long> log_queries_threshold = setting("dbms.querylog.threshold", DURATION, "0s"); public static final Setting<Long> log_queries_threshold = setting("dbms.querylog.threshold", DURATION, "0s");


@Description( "Specifies at which file size the query log will auto-rotate. " +
"`0` means that no rotation will automatically occur based on file size." )
public static final Setting<Long> log_queries_rotation_threshold = setting("dbms.querylog.rotation.threshold",
BYTES, "20m", min( 0L ), max( Long.MAX_VALUE ) );

@Description( "Maximum number of history files for the query log." )
public static final Setting<Integer> log_queries_max_archives = setting( "dbms.querylog.max_archives", INTEGER,
"7", min( 1 ) );

@Description( "Specifies number of operations that batch inserter will try to group into one batch before " + @Description( "Specifies number of operations that batch inserter will try to group into one batch before " +
"flushing data into underlying storage.") "flushing data into underlying storage.")
@Internal @Internal
Expand Down
5 changes: 5 additions & 0 deletions community/kernel/src/main/java/org/neo4j/kernel/impl/util/JobScheduler.java
View file
Expand Up @@ -131,6 +131,11 @@ class Groups
*/ */
public static final Group internalLogRotation = new Group( "InternalLogRotation", POOLED ); public static final Group internalLogRotation = new Group( "InternalLogRotation", POOLED );


/**
* Rotates query logs
*/
public static final Group queryLogRotation = new Group( "queryLogRotation", POOLED );

/** /**
* Checkpoint and store flush * Checkpoint and store flush
*/ */
Expand Down
82 changes: 57 additions & 25 deletions ...e/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java
View file
Expand Up @@ -19,6 +19,7 @@
*/ */
package org.neo4j.kernel.impl.query; package org.neo4j.kernel.impl.query;


import java.io.Closeable;
import java.io.File; import java.io.File;
import java.io.OutputStream; import java.io.OutputStream;


Expand All @@ -30,11 +31,14 @@
import org.neo4j.kernel.extension.KernelExtensionFactory; import org.neo4j.kernel.extension.KernelExtensionFactory;
import org.neo4j.kernel.impl.logging.LogService; import org.neo4j.kernel.impl.logging.LogService;
import org.neo4j.kernel.impl.query.QuerySession.MetadataKey; import org.neo4j.kernel.impl.query.QuerySession.MetadataKey;
import org.neo4j.kernel.impl.spi.KernelContext;
import org.neo4j.kernel.impl.util.JobScheduler;
import org.neo4j.kernel.lifecycle.Lifecycle; import org.neo4j.kernel.lifecycle.Lifecycle;
import org.neo4j.kernel.lifecycle.LifecycleAdapter; import org.neo4j.kernel.lifecycle.LifecycleAdapter;
import org.neo4j.kernel.monitoring.Monitors; import org.neo4j.kernel.monitoring.Monitors;
import org.neo4j.logging.FormattedLog; import org.neo4j.logging.FormattedLog;
import org.neo4j.logging.Log; import org.neo4j.logging.Log;
import org.neo4j.logging.RotatingFileOutputStreamSupplier;


import static org.neo4j.io.file.Files.createOrOpenAsOuputStream; import static org.neo4j.io.file.Files.createOrOpenAsOuputStream;


Expand All @@ -43,13 +47,15 @@ public class QueryLoggerKernelExtension extends KernelExtensionFactory<QueryLogg
{ {
public interface Dependencies public interface Dependencies
{ {
FileSystemAbstraction filesystem(); FileSystemAbstraction fileSystem();


Config config(); Config config();


Monitors monitoring(); Monitors monitoring();


LogService logger(); LogService logger();

JobScheduler jobScheduler();
} }


public QueryLoggerKernelExtension() public QueryLoggerKernelExtension()
Expand All @@ -58,50 +64,76 @@ public QueryLoggerKernelExtension()
} }


@Override @Override
public Lifecycle newKernelExtension( final Dependencies deps ) throws Throwable public Lifecycle newInstance( @SuppressWarnings( "unused" ) KernelContext context,
final Dependencies dependencies ) throws Throwable
{ {
boolean queryLogEnabled = deps.config().get( GraphDatabaseSettings.log_queries ); final Config config = dependencies.config();
final File queryLogFile = deps.config().get( GraphDatabaseSettings.log_queries_filename ); boolean queryLogEnabled = config.get( GraphDatabaseSettings.log_queries );
final File queryLogFile = config.get( GraphDatabaseSettings.log_queries_filename );


if ( !queryLogEnabled || queryLogFile == null ) if (!queryLogEnabled)
{ {
if ( queryLogFile == null ) return createEmptyAdapter();
{ }
deps.logger().getInternalLog( getClass() ).warn( GraphDatabaseSettings.log_queries.name() + if ( queryLogFile == null )
" is enabled but no " + {
GraphDatabaseSettings.log_queries_filename.name() + dependencies.logger().getInternalLog( getClass() )
" has not been provided in configuration, hence query logging is suppressed" ); .warn( GraphDatabaseSettings.log_queries.name() + " is enabled but no " +
} GraphDatabaseSettings.log_queries_filename.name() +
return new LifecycleAdapter(); " has not been provided in configuration, hence query logging is suppressed" );

return createEmptyAdapter();
} }


return new LifecycleAdapter() return new LifecycleAdapter()
{ {
OutputStream logOutputStream; Closeable closable;


@Override @Override
public void init() throws Throwable public void init() throws Throwable
{ {
final FileSystemAbstraction filesystem = deps.filesystem(); final FileSystemAbstraction fileSystem = dependencies.fileSystem();
logOutputStream = createOrOpenAsOuputStream( filesystem, queryLogFile, true );
Long thresholdMillis = deps.config().get( GraphDatabaseSettings.log_queries_threshold ); Long thresholdMillis = config.get( GraphDatabaseSettings.log_queries_threshold );

Long rotationThreshold = config.get( GraphDatabaseSettings.log_queries_rotation_threshold );
QueryLogger logger = new QueryLogger( int maxArchives = config.get( GraphDatabaseSettings.log_queries_max_archives );
Clock.SYSTEM_CLOCK,
FormattedLog.withUTCTimeZone().toOutputStream( logOutputStream ), FormattedLog.Builder logBuilder = FormattedLog.withUTCTimeZone();
thresholdMillis Log log;
); if (rotationThreshold == 0)
deps.monitoring().addMonitorListener( logger ); {
OutputStream logOutputStream = createOrOpenAsOuputStream( fileSystem, queryLogFile, true );
log = logBuilder.toOutputStream( logOutputStream );
closable = logOutputStream;
}
else
{
JobScheduler jobScheduler = dependencies.jobScheduler();
RotatingFileOutputStreamSupplier
rotatingSupplier = new RotatingFileOutputStreamSupplier( fileSystem, queryLogFile,
rotationThreshold, 0, maxArchives,
jobScheduler.executor( JobScheduler.Groups.queryLogRotation ) );
log = logBuilder.toOutputStream( rotatingSupplier );
closable = rotatingSupplier;
}

QueryLogger logger = new QueryLogger( Clock.SYSTEM_CLOCK, log, thresholdMillis );
dependencies.monitoring().addMonitorListener( logger );
} }


@Override @Override
public void shutdown() throws Throwable public void shutdown() throws Throwable
{ {
logOutputStream.close(); closable.close();
} }
}; };
} }


private Lifecycle createEmptyAdapter()
{
return new LifecycleAdapter();
}

public static class QueryLogger implements QueryExecutionMonitor public static class QueryLogger implements QueryExecutionMonitor
{ {
private static final MetadataKey<Long> START_TIME = new MetadataKey<>( Long.class, "start time" ); private static final MetadataKey<Long> START_TIME = new MetadataKey<>( Long.class, "start time" );
Expand Down
179 changes: 94 additions & 85 deletions enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerIT.java
View file
Expand Up @@ -20,126 +20,135 @@
package org.neo4j.kernel.impl.query; package org.neo4j.kernel.impl.query;


import org.hamcrest.Matchers; import org.hamcrest.Matchers;
import org.junit.Before;
import org.junit.Rule; import org.junit.Rule;
import org.junit.Test; import org.junit.Test;
import org.junit.experimental.runners.Enclosed;
import org.junit.rules.RuleChain;
import org.junit.rules.TestRule;
import org.junit.runner.RunWith;


import java.io.BufferedReader; import java.io.BufferedReader;
import java.io.File; import java.io.File;
import java.io.IOException;
import java.util.ArrayList; import java.util.ArrayList;
import java.util.List; import java.util.List;
import java.util.concurrent.TimeUnit;


import org.neo4j.graphdb.GraphDatabaseService;
import org.neo4j.graphdb.factory.GraphDatabaseBuilder; import org.neo4j.graphdb.factory.GraphDatabaseBuilder;
import org.neo4j.graphdb.factory.GraphDatabaseFactory;
import org.neo4j.graphdb.factory.GraphDatabaseSettings; import org.neo4j.graphdb.factory.GraphDatabaseSettings;
import org.neo4j.helpers.Settings; import org.neo4j.helpers.Settings;
import org.neo4j.logging.AssertableLogProvider; import org.neo4j.logging.AssertableLogProvider;
import org.neo4j.test.DatabaseRule;
import org.neo4j.test.EphemeralFileSystemRule; import org.neo4j.test.EphemeralFileSystemRule;
import org.neo4j.test.ImpermanentDatabaseRule; import org.neo4j.test.TargetDirectory;
import org.neo4j.test.TestGraphDatabaseFactory; import org.neo4j.test.TestGraphDatabaseFactory;


import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertEquals;
import static org.junit.Assert.assertThat; import static org.junit.Assert.assertThat;
import static org.junit.Assert.assertTrue;


@RunWith( Enclosed.class )
public class QueryLoggerIT public class QueryLoggerIT
{ {
public static class ConfiguredCorrectly
{
@Rule
public TestRule ruleOrder()
{
return RuleChain.outerRule( fs ).around( db );
}


private final EphemeralFileSystemRule fs = new EphemeralFileSystemRule(); @Rule
private final DatabaseRule db = new ImpermanentDatabaseRule() public final EphemeralFileSystemRule fileSystem = new EphemeralFileSystemRule();
{ @Rule
@Override public final TargetDirectory.TestDirectory testDirectory = TargetDirectory.testDirForTest( getClass() );
protected GraphDatabaseFactory newFactory() private AssertableLogProvider inMemoryLog;
{ private GraphDatabaseBuilder databaseBuilder;
return ((TestGraphDatabaseFactory) super.newFactory()).setFileSystem( fs.get() ); public static final String QUERY = "CREATE (n:Foo{bar:\"baz\"})";
}


@Override @Before
protected GraphDatabaseBuilder newBuilder( GraphDatabaseFactory factory ) public void setUp()
{ {
return super.newBuilder( factory ) inMemoryLog = new AssertableLogProvider();
.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE ) databaseBuilder = new TestGraphDatabaseFactory().setFileSystem( fileSystem.get() )
.setConfig( GraphDatabaseSettings.log_queries_filename, logFilename.getPath() ); .setInternalLogProvider( inMemoryLog )
} .newImpermanentDatabaseBuilder( testDirectory.graphDbDir() );
}; }


private final File logFilename = new File( "target/test-data/impermanent-db/queries.log" ); @Test
public void shouldLogQuerySlowerThanThreshold() throws Exception
{
final File logFilename = new File( testDirectory.graphDbDir(), "queries.log" );
GraphDatabaseService database = databaseBuilder.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE )
.setConfig( GraphDatabaseSettings.log_queries_filename, logFilename.getPath() )
.newGraphDatabase();


@Test executeQueryAndShutdown( database );
public void shouldLogQuerySlowerThanThreshold() throws Exception
{
String QUERY = "CREATE (n:Foo{bar:\"baz\"})";
db.getGraphDatabaseService().execute( QUERY );


db.shutdown(); List<String> logLines = readAllLines( logFilename );
assertEquals( 1, logLines.size() );
assertThat( logLines.get( 0 ), Matchers.endsWith( String.format( " ms: %s - %s",
QueryEngineProvider.embeddedSession(), QUERY ) ) );
}


List<String> logLines = new ArrayList<>(); @Test
try ( BufferedReader reader = new BufferedReader( fs.get().openAsReader( logFilename, "UTF-8" ) ) ) public void shouldSuppressQueryLoggingIfTheGivenPathIsNull() throws Exception
{ {
for ( String line; (line = reader.readLine()) != null; ) GraphDatabaseService database = databaseBuilder.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE )
{ .newGraphDatabase();
logLines.add( line );
}
}


assertEquals( 1, logLines.size() ); executeQueryAndShutdown( database );
assertThat( logLines.get( 0 ), Matchers.endsWith( String.format( " ms: %s - %s",
QueryEngineProvider.embeddedSession(), QUERY ) ) ); inMemoryLog.assertContainsMessageContaining( GraphDatabaseSettings.log_queries.name() +
} " is enabled but no " +
GraphDatabaseSettings.log_queries_filename.name() +
" has not been provided in configuration, hence query logging is" +
" suppressed" );
} }


public static class MissingLogQueryPathInConfiguration @Test
public void disabledQueryLogging() throws IOException
{ {
@Rule final File logFilename = new File( testDirectory.graphDbDir(), "queries.log" );
public TestRule ruleOrder() GraphDatabaseService database = databaseBuilder.setConfig( GraphDatabaseSettings.log_queries, Settings.FALSE )
{ .setConfig( GraphDatabaseSettings.log_queries_filename, logFilename.getPath() )
return RuleChain.outerRule( fs ).around( db ); .newGraphDatabase();
}


private final EphemeralFileSystemRule fs = new EphemeralFileSystemRule(); executeQueryAndShutdown( database );
private final AssertableLogProvider inMemoryLog = new AssertableLogProvider();
private final DatabaseRule db = new ImpermanentDatabaseRule()
{
@Override
protected GraphDatabaseFactory newFactory()
{
return ((TestGraphDatabaseFactory) super.newFactory())
.setFileSystem( fs.get() )
.setInternalLogProvider( inMemoryLog );
}


@Override List<String> lines = readAllLines( logFilename );
protected GraphDatabaseBuilder newBuilder( GraphDatabaseFactory factory ) assertTrue( "Should not have any queries logged since query log is disabled", lines.isEmpty() );
{ }
return super.newBuilder( factory )
.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE );
}
};

@Test
public void shouldSuppressQueryLoggingIfTheGivenPathIsNull() throws Exception
{


String QUERY = "CREATE (n:Foo{bar:\"baz\"})"; @Test
db.getGraphDatabaseService().execute( QUERY ); public void queryLogRotation() throws Exception
{
final File logFilename = new File( testDirectory.graphDbDir(), "queries.log" );
final File shiftedLogFilename = new File( testDirectory.graphDbDir(), "queries.log.1" );
GraphDatabaseService database = databaseBuilder.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE )
.setConfig( GraphDatabaseSettings.log_queries_filename, logFilename.getPath() )
.setConfig( GraphDatabaseSettings.log_queries_rotation_threshold, "1" )
.newGraphDatabase();

database.execute( QUERY );
database.execute( QUERY );
// wait for file rotation to finish
Thread.sleep( TimeUnit.SECONDS.toMillis( 1 ) );
// execute one more slow query which should go to new log file
database.execute( QUERY );
database.shutdown();

List<String> lines = readAllLines( logFilename );
assertEquals( 1, lines.size() );
List<String> shiftedLines = readAllLines( shiftedLogFilename );
assertEquals( 2, shiftedLines.size() );
}


db.shutdown(); private void executeQueryAndShutdown( GraphDatabaseService database )
{
database.execute( QUERY );
database.shutdown();
}


inMemoryLog.assertContainsMessageContaining( GraphDatabaseSettings.log_queries.name() + private List<String> readAllLines( File logFilename ) throws IOException
" is enabled but no " + {
GraphDatabaseSettings.log_queries_filename.name() + List<String> logLines = new ArrayList<>();
" has not been provided in configuration, hence query logging is suppressed" ); try ( BufferedReader reader = new BufferedReader( fileSystem.get().openAsReader( logFilename, "UTF-8" ) ) )
{
for ( String line; (line = reader.readLine()) != null; )
{
logLines.add( line );
}
} }
return logLines;
} }
} }

0 comments on commit e0a8ba6

Please sign in to comment.