From 24f867e2a8da3677c9b1f947ec428798d7e93473 Mon Sep 17 00:00:00 2001 From: Pontus Melke Date: Tue, 27 Oct 2015 13:16:55 +0100 Subject: [PATCH] Show parameters in query logging When logging slow queries we now also display the parameters that was used for the specific case --- .../compiler/v3_0/PipeExecutionResult.scala | 11 +-- .../org/neo4j/cypher/ExecutionEngine.scala | 10 +-- .../compatibility/CompatibilityFor3_0.scala | 13 +++- .../cypher/QueryExecutionMonitorTest.scala | 24 ++++--- .../cypher/QueryStatisticsTestSupport.scala | 5 +- .../v3_0/helpers/JavaCompatibility.scala | 35 ++++++++++ .../impl/query/QueryExecutionMonitor.java | 4 +- .../query/QueryLoggerKernelExtension.java | 48 +++++++++++-- .../kernel/impl/query/QueryLoggerIT.java | 63 ++++++++++++++++- .../kernel/impl/query/QueryLoggerTest.java | 70 ++++++++++++++++--- 10 files changed, 239 insertions(+), 44 deletions(-) create mode 100644 community/cypher/frontend-3.0/src/main/scala/org/neo4j/cypher/internal/frontend/v3_0/helpers/JavaCompatibility.scala diff --git a/community/cypher/cypher-compiler-3.0/src/main/scala/org/neo4j/cypher/internal/compiler/v3_0/PipeExecutionResult.scala b/community/cypher/cypher-compiler-3.0/src/main/scala/org/neo4j/cypher/internal/compiler/v3_0/PipeExecutionResult.scala index 1034af7d6b77..638bb7a3b1c2 100644 --- a/community/cypher/cypher-compiler-3.0/src/main/scala/org/neo4j/cypher/internal/compiler/v3_0/PipeExecutionResult.scala +++ b/community/cypher/cypher-compiler-3.0/src/main/scala/org/neo4j/cypher/internal/compiler/v3_0/PipeExecutionResult.scala @@ -21,8 +21,8 @@ package org.neo4j.cypher.internal.compiler.v3_0 import java.io.PrintWriter import java.util -import java.util.Collections +import org.neo4j.cypher.internal.frontend.v3_0.helpers.JavaCompatibility._ import org.neo4j.cypher.internal.compiler.v3_0.executionplan.InternalExecutionResult import org.neo4j.cypher.internal.compiler.v3_0.helpers.{CollectionSupport, iteratorToVisitable} import org.neo4j.cypher.internal.compiler.v3_0.pipes.QueryState @@ -58,7 +58,7 @@ class PipeExecutionResult(val result: ResultIterator, def javaColumnAs[T](column: String): ResourceIterator[T] = new WrappingResourceIterator[T] { def hasNext = self.hasNext - def next() = makeValueJavaCompatible(getAnyColumn(column, self.next())).asInstanceOf[T] + def next() = asJavaCompatible(getAnyColumn(column, self.next())).asInstanceOf[T] } def columnAs[T](column: String): Iterator[T] = @@ -67,7 +67,7 @@ class PipeExecutionResult(val result: ResultIterator, def javaIterator: ResourceIterator[java.util.Map[String, Any]] = new WrappingResourceIterator[util.Map[String, Any]] { def hasNext = self.hasNext - def next() = Eagerly.immutableMapValues(self.next(), makeValueJavaCompatible).asJava + def next() = Eagerly.immutableMapValues(self.next(), asJavaCompatible).asJava } override def toList: List[Predef.Map[String, Any]] = result.toList @@ -88,11 +88,6 @@ class PipeExecutionResult(val result: ResultIterator, private def getAnyColumn[T](column: String, m: Map[String, Any]): Any = m.getOrElse(column, columnNotFoundException(column, m.keys)) - private def makeValueJavaCompatible(value: Any): Any = value match { - case iter: Seq[_] => iter.map(makeValueJavaCompatible).asJava - case iter: Map[_, _] => Eagerly.immutableMapValues(iter, makeValueJavaCompatible).asJava - case x => x - } private def withDumper[T](f: (ExecutionResultDumper) => (QueryContext => T)): T = { val result = toList diff --git a/community/cypher/cypher/src/main/scala/org/neo4j/cypher/ExecutionEngine.scala b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/ExecutionEngine.scala index 2d5352b9ce3a..cfdb1ae5b5e9 100644 --- a/community/cypher/cypher/src/main/scala/org/neo4j/cypher/ExecutionEngine.scala +++ b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/ExecutionEngine.scala @@ -22,10 +22,10 @@ package org.neo4j.cypher import java.lang.Boolean.FALSE import java.util.{Map => JavaMap} -import org.neo4j.cypher.internal.compiler.v3_0.helpers.using import org.neo4j.cypher.internal.compiler.v3_0.prettifier.Prettifier import org.neo4j.cypher.internal.compiler.v3_0.{LRUCache => LRUCachev3_0, _} -import org.neo4j.cypher.internal.tracing.CompilationTracer.QueryCompilationEvent +import org.neo4j.cypher.internal.frontend.v3_0.helpers.JavaCompatibility +import JavaCompatibility._ import org.neo4j.cypher.internal.tracing.{TimingCompilationTracer, CompilationTracer} import org.neo4j.cypher.internal.{CypherCompiler, _} import org.neo4j.graphdb.GraphDatabaseService @@ -87,7 +87,7 @@ class ExecutionEngine(graph: GraphDatabaseService, logProvider: LogProvider = Nu @throws(classOf[SyntaxException]) def profile(query: String, params: Map[String, Any],session: QuerySession): ExtendedExecutionResult = { - executionMonitor.startQueryExecution(session, query) + executionMonitor.startQueryExecution(session, query, asJavaMap(params)) val (preparedPlanExecution, txInfo) = planQuery(query) preparedPlanExecution.profile(graphAPI, txInfo, params, session) @@ -113,7 +113,8 @@ class ExecutionEngine(graph: GraphDatabaseService, logProvider: LogProvider = Nu @throws(classOf[SyntaxException]) def execute(query: String, params: Map[String, Any], session: QuerySession): ExtendedExecutionResult = { - executionMonitor.startQueryExecution(session, query) + executionMonitor.startQueryExecution(session, query, + asJavaMap(params)) val (preparedPlanExecution, txInfo) = planQuery(query) preparedPlanExecution.execute(graphAPI, txInfo, params, session) } @@ -252,6 +253,7 @@ class ExecutionEngine(graph: GraphDatabaseService, logProvider: LogProvider = Nu .andThen(_.getOrElse(defaultValue)) .applyOrElse(graph, (_: GraphDatabaseService) => defaultValue) } + } object ExecutionEngine { diff --git a/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor3_0.scala b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor3_0.scala index 5c5f413701a6..cefde62971e8 100644 --- a/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor3_0.scala +++ b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor3_0.scala @@ -276,11 +276,20 @@ case class ExecutionResultWrapperFor3_0(inner: InternalExecutionResult, planner: ) } - def close() = exceptionHandlerFor3_0.runSafely{ inner.close() } + def close() = exceptionHandlerFor3_0.runSafely{ + endQueryExecution() + inner.close() + } def next() = exceptionHandlerFor3_0.runSafely{ inner.next() } - def hasNext = exceptionHandlerFor3_0.runSafely{ inner.hasNext } + def hasNext = exceptionHandlerFor3_0.runSafely { + val next = inner.hasNext + if (!next) { + endQueryExecution() + } + next + } def convert(i: InternalPlanDescription): ExtendedPlanDescription = exceptionHandlerFor3_0.runSafely { CompatibilityPlanDescriptionFor3_0(i, CypherVersion.v3_0, planner, runtime) diff --git a/community/cypher/cypher/src/test/java/org/neo4j/cypher/QueryExecutionMonitorTest.scala b/community/cypher/cypher/src/test/java/org/neo4j/cypher/QueryExecutionMonitorTest.scala index 18467b77fecf..2126c0af3945 100644 --- a/community/cypher/cypher/src/test/java/org/neo4j/cypher/QueryExecutionMonitorTest.scala +++ b/community/cypher/cypher/src/test/java/org/neo4j/cypher/QueryExecutionMonitorTest.scala @@ -19,6 +19,8 @@ */ package org.neo4j.cypher +import java.util.Collections + import org.mockito.Mockito._ import org.neo4j.cypher.internal.frontend.v3_0.test_helpers.CypherFunSuite import org.neo4j.graphdb.GraphDatabaseService @@ -37,7 +39,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { engine.execute("RETURN 42", Map.empty[String, Any], session) // then - verify(monitor, times(1)).startQueryExecution(session, "RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "RETURN 42", Collections.emptyMap()) verify(monitor, never()).endSuccess(session) } @@ -53,7 +55,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { } // then - verify(monitor, times(1)).startQueryExecution(session, "RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -65,7 +67,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CREATE()", Map.empty[String, Any], session).javaIterator // then - verify(monitor, times(1)).startQueryExecution(session, "CREATE()") + verify(monitor, times(1)).startQueryExecution(session, "CREATE()", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -77,7 +79,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("RETURN [1, 2, 3, 4, 5]", Map.empty[String, Any], session).javaIterator //then - verify(monitor, times(1)).startQueryExecution(session, "RETURN [1, 2, 3, 4, 5]") + verify(monitor, times(1)).startQueryExecution(session, "RETURN [1, 2, 3, 4, 5]", Collections.emptyMap()) while (result.hasNext) { verify(monitor, never).endSuccess(session) result.next() @@ -102,7 +104,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("RETURN 42", Map.empty[String, Any], session).javaIterator.close() // then - verify(monitor, times(1)).startQueryExecution(session, "RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -123,7 +125,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { } // then - verify(monitor, times(1)).startQueryExecution(session, "RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endFailure(session, throwable) } @@ -135,7 +137,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.profile("RETURN [1, 2, 3, 4, 5]", Map.empty[String, Any], session).javaIterator //then - verify(monitor, times(1)).startQueryExecution(session, "RETURN [1, 2, 3, 4, 5]") + verify(monitor, times(1)).startQueryExecution(session, "RETURN [1, 2, 3, 4, 5]", Collections.emptyMap()) while (result.hasNext) { verify(monitor, never).endSuccess(session) result.next() @@ -151,7 +153,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.profile("CYPHER 2.3 RETURN [1, 2, 3, 4, 5]", Map.empty[String, Any], session).javaIterator //then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 RETURN [1, 2, 3, 4, 5]") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 RETURN [1, 2, 3, 4, 5]", Collections.emptyMap()) while (result.hasNext) { verify(monitor, never).endSuccess(session) result.next() @@ -167,7 +169,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 2.3 RETURN 42", Map.empty[String, Any], session).javaIterator.close() // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -188,7 +190,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { } // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endFailure(session, throwable) } @@ -200,7 +202,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 2.3 CREATE()", Map.empty[String, Any], session).javaIterator // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 CREATE()") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.3 CREATE()", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } diff --git a/community/cypher/cypher/src/test/scala/org/neo4j/cypher/QueryStatisticsTestSupport.scala b/community/cypher/cypher/src/test/scala/org/neo4j/cypher/QueryStatisticsTestSupport.scala index 813904fc3002..2cea7d764f4d 100644 --- a/community/cypher/cypher/src/test/scala/org/neo4j/cypher/QueryStatisticsTestSupport.scala +++ b/community/cypher/cypher/src/test/scala/org/neo4j/cypher/QueryStatisticsTestSupport.scala @@ -19,6 +19,8 @@ */ package org.neo4j.cypher +import java.util + import org.neo4j.cypher.internal.compatibility.ExecutionResultWrapperFor3_0 import org.neo4j.cypher.internal.compiler.v3_0.executionplan.InternalExecutionResult import org.neo4j.cypher.internal.compiler.v3_0.{CompiledRuntimeName, CostBasedPlannerName} @@ -35,7 +37,8 @@ trait QueryStatisticsTestSupport { def apply(actual: InternalExecutionResult) { implicit val monitor = new QueryExecutionMonitor { - override def startQueryExecution(session: QuerySession, query: String){} + override def startQueryExecution(session: QuerySession, query: String, + parameters: util.Map[String, AnyRef]){} override def endSuccess(session: QuerySession){} diff --git a/community/cypher/frontend-3.0/src/main/scala/org/neo4j/cypher/internal/frontend/v3_0/helpers/JavaCompatibility.scala b/community/cypher/frontend-3.0/src/main/scala/org/neo4j/cypher/internal/frontend/v3_0/helpers/JavaCompatibility.scala new file mode 100644 index 000000000000..174c118a07cb --- /dev/null +++ b/community/cypher/frontend-3.0/src/main/scala/org/neo4j/cypher/internal/frontend/v3_0/helpers/JavaCompatibility.scala @@ -0,0 +1,35 @@ +/* + * Copyright (c) 2002-2015 "Neo Technology," + * Network Engine for Objects in Lund AB [http://neotechnology.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.cypher.internal.frontend.v3_0.helpers + +import java.util + +import scala.collection.JavaConverters._ + +object JavaCompatibility { + + def asJavaCompatible(value: Any): Any = value match { + case seq: Seq[_] => seq.map(asJavaCompatible).asJava + case map: Map[_, _] => Eagerly.immutableMapValues(map, asJavaCompatible).asJava + case x => x + } + + def asJavaMap[S,T](map: Map[S,T]): util.Map[S, AnyRef] = Eagerly.immutableMapValues(map, asJavaCompatible).asJava.asInstanceOf[util.Map[S, AnyRef]] +} diff --git a/community/kernel/src/main/java/org/neo4j/kernel/impl/query/QueryExecutionMonitor.java b/community/kernel/src/main/java/org/neo4j/kernel/impl/query/QueryExecutionMonitor.java index a951c5bdd7f2..b74b24b1dc62 100644 --- a/community/kernel/src/main/java/org/neo4j/kernel/impl/query/QueryExecutionMonitor.java +++ b/community/kernel/src/main/java/org/neo4j/kernel/impl/query/QueryExecutionMonitor.java @@ -19,6 +19,8 @@ */ package org.neo4j.kernel.impl.query; +import java.util.Map; + /** * The current (December 2014) usage of this interface expects the {@code end*} methods to be idempotent. * That is, once either of them have been invoked with a particular session as parameter, invoking either @@ -26,7 +28,7 @@ */ public interface QueryExecutionMonitor { - void startQueryExecution( QuerySession session, String query ); + void startQueryExecution( QuerySession session, String query, Map parameters); void endFailure( QuerySession session, Throwable failure ); 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 901bae81a2c0..3729c79d2935 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,10 +22,13 @@ import java.io.Closeable; import java.io.File; import java.io.OutputStream; +import java.util.Map; +import java.util.Map.Entry; import org.neo4j.graphdb.factory.GraphDatabaseSettings; import org.neo4j.helpers.Clock; import org.neo4j.helpers.Service; +import org.neo4j.helpers.Strings; import org.neo4j.io.fs.FileSystemAbstraction; import org.neo4j.kernel.configuration.Config; import org.neo4j.kernel.extension.KernelExtensionFactory; @@ -138,6 +141,8 @@ public static class QueryLogger implements QueryExecutionMonitor { private static final MetadataKey START_TIME = new MetadataKey<>( Long.class, "start time" ); private static final MetadataKey QUERY_STRING = new MetadataKey<>( String.class, "query string" ); + @SuppressWarnings( "unchecked" ) + private static final MetadataKey> PARAMS = new MetadataKey<>( (Class>) (Class) Map.class , "parameters" ); private final Clock clock; private final Log log; @@ -151,11 +156,12 @@ public QueryLogger( Clock clock, Log log, long thresholdMillis ) } @Override - public void startQueryExecution( QuerySession session, String query ) + public void startQueryExecution( QuerySession session, String query, Map parameters) { long startTime = clock.currentTimeMillis(); Object oldTime = session.put( START_TIME, startTime ); Object oldQuery = session.put( QUERY_STRING, query ); + session.put(PARAMS, parameters); if ( oldTime != null || oldQuery != null ) { log.error( "Concurrent queries for session %s: \"%s\" @ %s and \"%s\" @ %s", @@ -168,11 +174,12 @@ public void endFailure( QuerySession session, Throwable failure ) { String query = session.remove( QUERY_STRING ); Long startTime = session.remove( START_TIME ); + Map params = session.remove( PARAMS ); if ( startTime != null ) { long time = clock.currentTimeMillis() - startTime; - log.error( String.format( "%d ms: %s - %s", time, session.toString(), - query == null ? "" : query ), failure ); + log.error( String.format( "%d ms: %s - %s - %s", time, session.toString(), + query == null ? "" : query , mapToString( params )), failure ); } } @@ -184,12 +191,43 @@ public void endSuccess( QuerySession session ) if ( startTime != null ) { long time = clock.currentTimeMillis() - startTime; + Map params = session.remove( PARAMS ); if ( time >= thresholdMillis ) { - log.info( "%d ms: %s - %s", time, session.toString(), - query == null ? "" : query ); + log.info( "%d ms: %s - %s - %s", time, session.toString(), + query == null ? "" : query, mapToString( params ) ); } } } + + @SuppressWarnings( "unchecked" ) + private String mapToString( Map params ) + { + if ( params == null ) + { + return "{}"; + } + + StringBuilder builder = new StringBuilder( "{" ); + String sep = ""; + for ( Entry entry : params.entrySet() ) + { + builder.append( sep ).append( entry.getKey() ).append( ": " ); + + Object value = entry.getValue(); + if ( value instanceof Map ) + { + builder.append( mapToString( (Map) value ) ); + } + else + { + builder.append( Strings.prettyPrint( value ) ); + } + sep = ", "; + } + builder.append( "}" ); + + return builder.toString(); + } } } diff --git a/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerIT.java b/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerIT.java index 1f1ea108047c..dd1ad4792f25 100644 --- a/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerIT.java +++ b/enterprise/query-logging/src/test/java/org/neo4j/kernel/impl/query/QueryLoggerIT.java @@ -29,10 +29,15 @@ import java.io.IOException; import java.nio.charset.StandardCharsets; import java.util.ArrayList; +import java.util.Arrays; +import java.util.Collections; +import java.util.HashMap; import java.util.List; +import java.util.Map; import java.util.concurrent.TimeUnit; import org.neo4j.graphdb.GraphDatabaseService; +import org.neo4j.graphdb.Result; import org.neo4j.graphdb.factory.GraphDatabaseBuilder; import org.neo4j.graphdb.factory.GraphDatabaseSettings; import org.neo4j.helpers.Settings; @@ -77,10 +82,58 @@ public void shouldLogQuerySlowerThanThreshold() throws Exception List logLines = readAllLines( logFilename ); assertEquals( 1, logLines.size() ); - assertThat( logLines.get( 0 ), Matchers.endsWith( String.format( " ms: %s - %s", + assertThat( logLines.get( 0 ), Matchers.endsWith( String.format( " ms: %s - %s - {}", QueryEngineProvider.embeddedSession(), QUERY ) ) ); } + @Test + public void shouldLogParametersWhenNestedMap() 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(); + + Map props = new HashMap<>(); + props.put( "name", "Roland" ); + props.put( "position", "Gunslinger" ); + props.put( "followers", Arrays.asList("Jake", "Eddie", "Susannah") ); + + Map params = new HashMap<>(); + params.put( "props", props ); + + String query = "CREATE ({props})"; + executeQueryAndShutdown( database, query, params ); + + List logLines = readAllLines( logFilename ); + assertEquals( 1, logLines.size() ); + assertThat( logLines.get( 0 ), + Matchers.endsWith( String.format( + " ms: %s - %s - {props: {followers: [Jake, Eddie, Susannah], name: Roland, position: Gunslinger}}", + QueryEngineProvider.embeddedSession(), query) ) ); + } + + @Test + public void shouldLogParametersWhenList() 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(); + + Map params = new HashMap<>(); + params.put( "ids", Arrays.asList( 0, 1, 2 ) ); + String query = "MATCH (n) WHERE id(n) in {ids} RETURN n.name"; + executeQueryAndShutdown( database, query, params ); + + List logLines = readAllLines( logFilename ); + assertEquals( 1, logLines.size() ); + assertThat( logLines.get( 0 ), + Matchers.endsWith( String.format( + " ms: %s - %s - {ids: [0, 1, 2]}", + QueryEngineProvider.embeddedSession(), query) ) ); + } + @Test public void shouldSuppressQueryLoggingIfTheGivenPathIsNull() throws Exception { @@ -136,7 +189,13 @@ public void queryLogRotation() throws Exception private void executeQueryAndShutdown( GraphDatabaseService database ) { - database.execute( QUERY ); + executeQueryAndShutdown( database, QUERY, Collections.emptyMap() ); + } + + private void executeQueryAndShutdown( GraphDatabaseService database, String query, Map params ) + { + Result execute = database.execute( query, params ); + execute.close(); database.shutdown(); } 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 f7682ffaf752..2b249c463ed4 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,6 +19,10 @@ */ package org.neo4j.kernel.impl.query; +import java.util.Arrays; +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; import java.util.concurrent.TimeUnit; import org.junit.Test; @@ -39,6 +43,7 @@ public class QueryLoggerTest public static final String QUERY_1 = "MATCH (n) RETURN n"; public static final String QUERY_2 = "MATCH (a)--(b) RETURN b.name"; public static final String QUERY_3 = "MATCH (c)-[:FOO]->(d) RETURN d.size"; + public static final String QUERY_4 = "MATCH (n) WHERE n.age IN {ages} RETURN n"; @Test public void shouldLogQuerySlowerThanThreshold() throws Exception @@ -50,13 +55,13 @@ public void shouldLogQuerySlowerThanThreshold() throws Exception QueryLogger queryLogger = new QueryLogger( clock, logProvider.getLog( getClass() ), 10/*ms*/ ); // when - queryLogger.startQueryExecution( session, QUERY_1 ); + queryLogger.startQueryExecution( session, QUERY_1, Collections.emptyMap() ); clock.forward( 11, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( session ); // then logProvider.assertExactly( - inLog( getClass() ).info( "%d ms: %s - %s", 11L, SESSION_1_NAME, QUERY_1 ) + inLog( getClass() ).info( "%d ms: %s - %s - %s", 11L, SESSION_1_NAME, QUERY_1, "{}" ) ); } @@ -70,7 +75,7 @@ public void shouldNotLogQueryFasterThanThreshold() throws Exception QueryLogger queryLogger = new QueryLogger( clock, logProvider.getLog( getClass() ), 10/*ms*/ ); // when - queryLogger.startQueryExecution( session, QUERY_1 ); + queryLogger.startQueryExecution( session, QUERY_1, Collections.emptyMap() ); clock.forward( 9, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( session ); @@ -90,11 +95,11 @@ public void shouldKeepTrackOfDifferentSessions() throws Exception QueryLogger queryLogger = new QueryLogger( clock, logProvider.getLog( getClass() ), 10/*ms*/ ); // when - queryLogger.startQueryExecution( session1, QUERY_1 ); + queryLogger.startQueryExecution( session1, QUERY_1, Collections.emptyMap() ); clock.forward( 1, TimeUnit.MILLISECONDS ); - queryLogger.startQueryExecution( session2, QUERY_2 ); + queryLogger.startQueryExecution( session2, QUERY_2, Collections.emptyMap() ); clock.forward( 1, TimeUnit.MILLISECONDS ); - queryLogger.startQueryExecution( session3, QUERY_3 ); + queryLogger.startQueryExecution( session3, QUERY_3, Collections.emptyMap() ); clock.forward( 7, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( session3 ); clock.forward( 7, TimeUnit.MILLISECONDS ); @@ -104,8 +109,8 @@ public void shouldKeepTrackOfDifferentSessions() throws Exception // then logProvider.assertExactly( - inLog( getClass() ).info( "%d ms: %s - %s", 15L, SESSION_2_NAME, QUERY_2 ), - inLog( getClass() ).info( "%d ms: %s - %s", 23L, SESSION_1_NAME, QUERY_1 ) + inLog( getClass() ).info( "%d ms: %s - %s - %s", 15L, SESSION_2_NAME, QUERY_2, "{}" ), + inLog( getClass() ).info( "%d ms: %s - %s - %s", 23L, SESSION_1_NAME, QUERY_1, "{}" ) ); } @@ -120,13 +125,58 @@ public void shouldLogQueryOnFailureEvenIfFasterThanThreshold() throws Exception RuntimeException failure = new RuntimeException(); // when - queryLogger.startQueryExecution( session, QUERY_1 ); + queryLogger.startQueryExecution( session, QUERY_1, Collections.emptyMap() ); clock.forward( 1, TimeUnit.MILLISECONDS ); queryLogger.endFailure( session, failure ); // then logProvider.assertExactly( - inLog( getClass() ).error( is( "1 ms: {session one} - MATCH (n) RETURN n" ), sameInstance( failure ) ) + inLog( getClass() ).error( is( "1 ms: {session one} - MATCH (n) RETURN n - {}" ), sameInstance( failure ) ) + ); + } + + @Test + public void shouldLogQueryParameters() throws Exception + { + // given + final AssertableLogProvider logProvider = new AssertableLogProvider(); + QuerySession session = session( SESSION_1_NAME ); + FakeClock clock = new FakeClock(); + QueryLogger queryLogger = new QueryLogger( clock, logProvider.getLog( getClass() ), 10/*ms*/ ); + + // when + Map params = new HashMap<>( ); + params.put("ages", Arrays.asList(41, 42, 43)); + queryLogger.startQueryExecution( session, QUERY_4, params ); + clock.forward( 11, TimeUnit.MILLISECONDS ); + queryLogger.endSuccess( session ); + + // then + logProvider.assertExactly( + inLog( getClass() ).info( "%d ms: %s - %s - %s", 11L, SESSION_1_NAME, QUERY_4, "{ages: [41, 42, 43]}" ) + ); + } + + @Test + public void shouldLogQueryParametersOnFailure() throws Exception + { + // given + final AssertableLogProvider logProvider = new AssertableLogProvider(); + QuerySession session = session( SESSION_1_NAME ); + FakeClock clock = new FakeClock(); + QueryLogger queryLogger = new QueryLogger( clock, logProvider.getLog( getClass() ), 10/*ms*/ ); + RuntimeException failure = new RuntimeException(); + + // when + Map params = new HashMap<>( ); + params.put("ages", Arrays.asList(41, 42, 43)); + queryLogger.startQueryExecution( session, QUERY_4, params ); + clock.forward( 1, TimeUnit.MILLISECONDS ); + queryLogger.endFailure( session, failure ); + + // then + logProvider.assertExactly( + inLog( getClass() ).error( is( "1 ms: {session one} - MATCH (n) WHERE n.age IN {ages} RETURN n - {ages: [41, 42, 43]}" ), sameInstance( failure ) ) ); }