diff --git a/community/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java b/community/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java index 386241440217..3eab43f04bcb 100644 --- a/community/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java +++ b/community/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java @@ -488,6 +488,12 @@ public class GraphDatabaseSettings implements LoadableConfig @Description( "Log parameters for executed queries that took longer than the configured threshold." ) public static final Setting log_queries_parameter_logging_enabled = setting( "dbms.logs.query.parameter_logging_enabled", BOOLEAN, TRUE ); + @Description( "Log detailed time information for executed queries that took longer than the configured threshold." ) + public static final Setting log_queries_detailed_time_logging_enabled = setting( "dbms.logs.query.time_logging_enabled", BOOLEAN, FALSE ); + + @Description( "Log allocated bytes for executed queries that took longer than the configured threshold." ) + public static final Setting log_queries_allocation_logging_enabled = setting( "dbms.logs.query.allocation_logging_enabled", BOOLEAN, FALSE ); + @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.") public static final Setting log_queries_threshold = setting("dbms.logs.query.threshold", DURATION, "0s"); diff --git a/community/kernel/src/main/java/org/neo4j/kernel/api/query/ExecutingQuery.java b/community/kernel/src/main/java/org/neo4j/kernel/api/query/ExecutingQuery.java index f40f5578ee6e..a371aedc600f 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/api/query/ExecutingQuery.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/api/query/ExecutingQuery.java @@ -243,11 +243,6 @@ ClientConnectionInfo clientConnection() return clientConnection; } - public String connectionDetailsForLogging() - { - return clientConnection.asConnectionDetails(); - } - private LockWaitEvent waitForLock( boolean exclusive, ResourceType resourceType, long[] resourceIds ) { WaitingOnLockEvent event = new WaitingOnLockEvent( diff --git a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java index 40abc7e5fab9..ed7e1f266076 100644 --- a/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java +++ b/enterprise/query-logging/src/main/java/org/neo4j/kernel/impl/query/QueryLoggerKernelExtension.java @@ -22,20 +22,22 @@ import java.io.Closeable; import java.io.File; import java.io.OutputStream; -import java.time.Clock; import java.util.Collection; import java.util.Collections; +import java.util.EnumSet; import java.util.HashSet; import java.util.Map; import java.util.Set; import java.util.regex.Matcher; import java.util.regex.Pattern; +import org.neo4j.graphdb.config.Setting; import org.neo4j.graphdb.factory.GraphDatabaseSettings; import org.neo4j.helpers.Service; import org.neo4j.helpers.Strings; import org.neo4j.io.fs.FileSystemAbstraction; import org.neo4j.kernel.api.query.ExecutingQuery; +import org.neo4j.kernel.api.query.QuerySnapshot; import org.neo4j.kernel.configuration.Config; import org.neo4j.kernel.extension.KernelExtensionFactory; import org.neo4j.kernel.impl.logging.LogService; @@ -47,7 +49,6 @@ import org.neo4j.logging.FormattedLog; import org.neo4j.logging.Log; import org.neo4j.logging.RotatingFileOutputStreamSupplier; -import org.neo4j.time.Clocks; import static java.lang.String.format; import static org.neo4j.io.file.Files.createOrOpenAsOuputStream; @@ -68,6 +69,24 @@ public interface Dependencies JobScheduler jobScheduler(); } + enum Flag + { + LOG_PARAMETERS( GraphDatabaseSettings.log_queries_parameter_logging_enabled ), + LOG_DETAILED_TIME( GraphDatabaseSettings.log_queries_detailed_time_logging_enabled ), + LOG_ALLOCATED_BYTES( GraphDatabaseSettings.log_queries_allocation_logging_enabled ); + private final Setting setting; + + Flag( Setting setting ) + { + this.setting = setting; + } + + boolean enabledIn( Config config ) + { + return config.get( setting ); + } + } + public QueryLoggerKernelExtension() { super( "query-logging" ); @@ -99,7 +118,14 @@ public void init() throws Throwable Long thresholdMillis = config.get( GraphDatabaseSettings.log_queries_threshold ); Long rotationThreshold = config.get( GraphDatabaseSettings.log_queries_rotation_threshold ); int maxArchives = config.get( GraphDatabaseSettings.log_queries_max_archives ); - boolean logQueryParameters = config.get( GraphDatabaseSettings.log_queries_parameter_logging_enabled ); + EnumSet flags = EnumSet.noneOf( Flag.class ); + for ( Flag flag : Flag.values() ) + { + if (flag.enabledIn(config)) + { + flags.add( flag ); + } + } FormattedLog.Builder logBuilder = FormattedLog.withUTCTimeZone(); Log log; @@ -119,7 +145,7 @@ public void init() throws Throwable closable = rotatingSupplier; } - QueryLogger logger = new QueryLogger( Clocks.systemClock(), log, thresholdMillis, logQueryParameters ); + QueryLogger logger = new QueryLogger( log, thresholdMillis, flags ); monitoring.addMonitorListener( logger ); } @@ -138,10 +164,9 @@ private Lifecycle createEmptyAdapter() static class QueryLogger implements QueryExecutionMonitor { - private final Clock clock; private final Log log; private final long thresholdMillis; - private final boolean logQueryParameters; + private final boolean logQueryParameters, logDetailedTime, logAllocatedBytes; private static final Pattern PASSWORD_PATTERN = Pattern.compile( // call signature @@ -151,12 +176,13 @@ static class QueryLogger implements QueryExecutionMonitor // password parameter, in single, double quotes, or parametrized "\\s*('(?:(?<=\\\\)'|[^'])*'|\"(?:(?<=\\\\)\"|[^\"])*\"|\\$\\w*|\\{\\w*\\})\\s*\\)" ); - QueryLogger( Clock clock, Log log, long thresholdMillis, boolean logQueryParameters ) + QueryLogger( Log log, long thresholdMillis, EnumSet flags ) { - this.clock = clock; this.log = log; this.thresholdMillis = thresholdMillis; - this.logQueryParameters = logQueryParameters; + this.logQueryParameters = flags.contains( Flag.LOG_PARAMETERS ); + this.logDetailedTime = flags.contains( Flag.LOG_DETAILED_TIME ); + this.logAllocatedBytes = flags.contains( Flag.LOG_ALLOCATED_BYTES ); } @Override @@ -167,23 +193,22 @@ public void startQueryExecution( ExecutingQuery query ) @Override public void endFailure( ExecutingQuery query, Throwable failure ) { - long time = clock.millis() - query.startTimestampMillis(); - log.error( logEntry( time, query ), failure ); + log.error( logEntry( query.snapshot() ), failure ); } @Override public void endSuccess( ExecutingQuery query ) { - long time = clock.millis() - query.startTimestampMillis(); - if ( time >= thresholdMillis ) + QuerySnapshot snapshot = query.snapshot(); + if ( snapshot.elapsedTimeMillis() >= thresholdMillis ) { - log.info( logEntry( time, query ) ); + log.info( logEntry( snapshot ) ); } } - private String logEntry( long time, ExecutingQuery query ) + private String logEntry( QuerySnapshot query ) { - String sourceString = query.connectionDetailsForLogging(); + String sourceString = query.clientConnection().asConnectionDetails(); String queryText = query.queryText(); String metaData = mapAsString( query.transactionAnnotationData() ); @@ -208,15 +233,34 @@ else if ( password.charAt( 0 ) == '{' ) } } - if ( logQueryParameters ) + StringBuilder result = new StringBuilder(); + result.append( query.elapsedTimeMillis() ).append( " ms: " ); + if ( logDetailedTime ) { - String params = mapAsString( query.queryParameters(), passwordParams ); - return format( "%d ms: %s - %s - %s - %s", time, sourceString, queryText, params, metaData ); + result.append( "(planning: " ).append( query.planningTimeMillis() ); + Long cpuTime = query.cpuTimeMillis(); + if ( cpuTime != null ) + { + result.append( ", cpu: " ).append( cpuTime ); + } + result.append( ", waiting: " ).append( query.waitTimeMillis() ); + result.append( ") - " ); } - else + if ( logAllocatedBytes ) + { + Long bytes = query.allocatedBytes(); + if ( bytes != null ) + { + result.append( bytes ).append( " B - " ); + } + } + result.append( sourceString ).append( " - " ).append( queryText ); + if ( logQueryParameters ) { - return format( "%d ms: %s - %s - %s", time, sourceString, queryText, metaData ); + result.append( " - " ).append( mapAsString( query.queryParameters(), passwordParams ) ); } + result.append( " - " ).append( metaData ); + return result.toString(); } private static String mapAsString( Map params ) diff --git a/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java b/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java index bd612cbb502c..2add10b492dd 100644 --- a/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java +++ b/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerTest.java @@ -19,32 +19,36 @@ */ package org.neo4j.kernel.impl.query; -import org.junit.Test; - -import java.time.Clock; import java.util.Arrays; import java.util.Collections; +import java.util.EnumSet; import java.util.HashMap; import java.util.Map; import java.util.concurrent.TimeUnit; +import org.junit.Test; + import org.neo4j.kernel.api.query.ExecutingQuery; import org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.QueryLogger; import org.neo4j.kernel.impl.query.clientconnection.ClientConnectionInfo; import org.neo4j.kernel.impl.query.clientconnection.ShellConnectionInfo; import org.neo4j.logging.AssertableLogProvider; import org.neo4j.logging.LogProvider; -import org.neo4j.resources.HeapAllocation; +import org.neo4j.test.FakeCpuClock; +import org.neo4j.test.FakeHeapAllocation; import org.neo4j.time.Clocks; -import org.neo4j.resources.CpuClock; import org.neo4j.time.FakeClock; import static java.lang.String.format; import static java.util.Collections.emptyMap; +import static org.hamcrest.Matchers.containsString; import static org.hamcrest.Matchers.equalTo; import static org.hamcrest.Matchers.sameInstance; import static org.hamcrest.core.Is.is; import static org.neo4j.helpers.collection.MapUtil.map; +import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_ALLOCATED_BYTES; +import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_DETAILED_TIME; +import static org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.Flag.LOG_PARAMETERS; import static org.neo4j.logging.AssertableLogProvider.inLog; public class QueryLoggerTest @@ -56,15 +60,17 @@ public class QueryLoggerTest private static final String QUERY_2 = "MATCH (a)--(b) RETURN b.name"; private static final String QUERY_3 = "MATCH (c)-[:FOO]->(d) RETURN d.size"; private static final String QUERY_4 = "MATCH (n) WHERE n.age IN {ages} RETURN n"; + private final FakeClock clock = Clocks.fakeClock(); + private final FakeCpuClock cpuClock = new FakeCpuClock(); + private final FakeHeapAllocation heapAllocation = new FakeHeapAllocation(); @Test public void shouldLogQuerySlowerThanThreshold() throws Exception { // given final AssertableLogProvider logProvider = new AssertableLogProvider(); - ExecutingQuery query = query( 0, SESSION_1, "TestUser", QUERY_1 ); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithoutParams( logProvider, clock ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_1 ); + QueryLogger queryLogger = queryLogger( logProvider ); // when queryLogger.startQueryExecution( query ); @@ -83,9 +89,8 @@ public void shouldNotLogQueryFasterThanThreshold() throws Exception { // given final AssertableLogProvider logProvider = new AssertableLogProvider(); - ExecutingQuery query = query( 0, SESSION_1, "TestUser", QUERY_1 ); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithoutParams( logProvider, clock ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_1 ); + QueryLogger queryLogger = queryLogger( logProvider ); // when queryLogger.startQueryExecution( query ); @@ -101,12 +106,13 @@ public void shouldKeepTrackOfDifferentSessions() throws Exception { // given final AssertableLogProvider logProvider = new AssertableLogProvider(); - ExecutingQuery query1 = query( 0, SESSION_1, "TestUser1", QUERY_1 ); - ExecutingQuery query2 = query( 1, SESSION_2, "TestUser2", QUERY_2 ); - ExecutingQuery query3 = query( 2, SESSION_3, "TestUser3", QUERY_3 ); + ExecutingQuery query1 = query( SESSION_1, "TestUser1", QUERY_1 ); + clock.forward( 1, TimeUnit.MILLISECONDS ); + ExecutingQuery query2 = query( SESSION_2, "TestUser2", QUERY_2 ); + clock.forward( 1, TimeUnit.MILLISECONDS ); + ExecutingQuery query3 = query( SESSION_3, "TestUser3", QUERY_3 ); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithoutParams( logProvider, clock ); + QueryLogger queryLogger = queryLogger( logProvider ); // when queryLogger.startQueryExecution( query1 ); @@ -125,8 +131,8 @@ public void shouldKeepTrackOfDifferentSessions() throws Exception String expectedSession1String = sessionConnectionDetails( SESSION_1, "TestUser1" ); String expectedSession2String = sessionConnectionDetails( SESSION_2, "TestUser2" ); logProvider.assertExactly( - inLog( getClass() ).info( format( "%d ms: %s - %s - {}", 15L, expectedSession2String, QUERY_2 ) ), - inLog( getClass() ).info( format( "%d ms: %s - %s - {}", 23L, expectedSession1String, QUERY_1 ) ) + inLog( getClass() ).info( format( "%d ms: %s - %s - {}", 17L, expectedSession2String, QUERY_2 ) ), + inLog( getClass() ).info( format( "%d ms: %s - %s - {}", 25L, expectedSession1String, QUERY_1 ) ) ); } @@ -135,10 +141,9 @@ public void shouldLogQueryOnFailureEvenIfFasterThanThreshold() throws Exception { // given final AssertableLogProvider logProvider = new AssertableLogProvider(); - ExecutingQuery query = query( 0, SESSION_1, "TestUser", QUERY_1 ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_1 ); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithoutParams( logProvider, clock ); + QueryLogger queryLogger = queryLogger( logProvider ); RuntimeException failure = new RuntimeException(); // when @@ -161,11 +166,8 @@ public void shouldLogQueryParameters() throws Exception final AssertableLogProvider logProvider = new AssertableLogProvider(); Map params = new HashMap<>(); params.put( "ages", Arrays.asList( 41, 42, 43 ) ); - ExecutingQuery query = query( 0, - SESSION_1, "TestUser", QUERY_4, params, emptyMap() - ); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithParams( logProvider, clock ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_4, params, emptyMap() ); + QueryLogger queryLogger = queryLogger( logProvider, LOG_PARAMETERS ); // when queryLogger.startQueryExecution( query ); @@ -188,11 +190,8 @@ public void shouldLogQueryParametersOnFailure() throws Exception final AssertableLogProvider logProvider = new AssertableLogProvider(); Map params = new HashMap<>(); params.put( "ages", Arrays.asList( 41, 42, 43 ) ); - ExecutingQuery query = query( 0, - SESSION_1, "TestUser", QUERY_4, params, emptyMap() - ); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithParams( logProvider, clock ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_4, params, emptyMap() ); + QueryLogger queryLogger = queryLogger( logProvider, LOG_PARAMETERS ); RuntimeException failure = new RuntimeException(); // when @@ -214,16 +213,15 @@ public void shouldLogUserName() throws Exception { // given final AssertableLogProvider logProvider = new AssertableLogProvider(); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithoutParams( logProvider, clock ); + QueryLogger queryLogger = queryLogger( logProvider ); // when - ExecutingQuery query = query( 0, SESSION_1, "TestUser", QUERY_1 ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_1 ); queryLogger.startQueryExecution( query ); clock.forward( 10, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( query ); - ExecutingQuery anotherQuery = query( 10, SESSION_1, "AnotherUser", QUERY_1 ); + ExecutingQuery anotherQuery = query( SESSION_1, "AnotherUser", QUERY_1 ); queryLogger.startQueryExecution( anotherQuery ); clock.forward( 10, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( anotherQuery ); @@ -242,20 +240,16 @@ public void shouldLogMetaData() throws Exception { // given final AssertableLogProvider logProvider = new AssertableLogProvider(); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithoutParams( logProvider, clock ); + QueryLogger queryLogger = queryLogger( logProvider ); // when - ExecutingQuery query = query( 0, - SESSION_1, - "TestUser", QUERY_1, emptyMap(), map( "User", "UltiMate" ) - ); + ExecutingQuery query = query( SESSION_1, "TestUser", QUERY_1, emptyMap(), map( "User", "UltiMate" ) ); queryLogger.startQueryExecution( query ); clock.forward( 10, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( query ); ExecutingQuery anotherQuery = - query( 10, SESSION_1, "AnotherUser", QUERY_1, emptyMap(), map( "Place", "Town" ) ); + query( SESSION_1, "AnotherUser", QUERY_1, emptyMap(), map( "Place", "Town" ) ); queryLogger.startQueryExecution( anotherQuery ); clock.forward( 10, TimeUnit.MILLISECONDS ); Throwable error = new Throwable(); @@ -395,11 +389,10 @@ public void shouldNotLogPasswordDifferentWhitespace() throws Exception private void runAndCheck( String inputQuery, String outputQuery, Map params, String paramsString ) { final AssertableLogProvider logProvider = new AssertableLogProvider(); - FakeClock clock = Clocks.fakeClock(); - QueryLogger queryLogger = queryLoggerWithParams( logProvider, clock ); + QueryLogger queryLogger = queryLogger( logProvider, LOG_PARAMETERS ); // when - ExecutingQuery query = query( 0, SESSION_1, "neo", inputQuery, params, emptyMap() ); + ExecutingQuery query = query( SESSION_1, "neo", inputQuery, params, emptyMap() ); queryLogger.startQueryExecution( query ); clock.forward( 10, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( query ); @@ -411,23 +404,57 @@ private void runAndCheck( String inputQuery, String outputQuery, Map flagSet = EnumSet.noneOf( QueryLoggerKernelExtension.Flag.class ); + Collections.addAll( flagSet, flags ); + return new QueryLogger( logProvider.getLog( getClass() ), 10/*ms*/, flagSet ); } private ExecutingQuery query( - long startTime, ClientConnectionInfo sessionInfo, String username, String queryText ) { - return query( startTime, sessionInfo, username, queryText, emptyMap(), emptyMap() ); + return query( sessionInfo, username, queryText, emptyMap(), emptyMap() ); } private String sessionConnectionDetails( ClientConnectionInfo sessionInfo, String username ) @@ -438,11 +465,12 @@ private String sessionConnectionDetails( ClientConnectionInfo sessionInfo, Strin private int queryId; private ExecutingQuery query( - long startTime, ClientConnectionInfo sessionInfo, String username, String queryText, Map params, - Map metaData - ) + ClientConnectionInfo sessionInfo, + String username, + String queryText, + Map params, + Map metaData ) { - FakeClock clock = Clocks.fakeClock( startTime, TimeUnit.MILLISECONDS ); return new ExecutingQuery( queryId++, sessionInfo.withUsername( username ), username, @@ -452,7 +480,7 @@ private ExecutingQuery query( () -> 0, Thread.currentThread(), clock, - CpuClock.CPU_CLOCK, - HeapAllocation.HEAP_ALLOCATION ); + cpuClock, + heapAllocation ); } }