From 4e8a2a15f7e62c3a905f79bfaf158f4f5667be97 Mon Sep 17 00:00:00 2001 From: lutovich Date: Fri, 15 Apr 2016 17:47:34 +0200 Subject: [PATCH] Show parameters in query logging When logging slow queries we now also display the parameters that was used for the specific case. This commit **backports** 24f867e2a8da3677c9b1f947ec428798d7e93473. Additional setting `dbms.querylog.parameter_logging_enabled` is added to enable/disable logging of query parameters. --- .../compiler/v2_2/PipeExecutionResult.scala | 11 +- .../v2_2/helpers/JavaCompatibility.scala | 35 ++++++ .../org/neo4j/cypher/ExecutionEngine.scala | 5 +- .../compatibility/CompatibilityFor2_2.scala | 13 ++- .../cypher/QueryExecutionMonitorTest.scala | 40 +++---- .../cypher/QueryStatisticsTestSupport.scala | 4 +- .../factory/GraphDatabaseSettings.java | 3 + .../impl/query/QueryExecutionMonitor.java | 4 +- .../query/QueryLoggerKernelExtension.java | 102 ++++++++++++++++-- .../kernel/impl/query/QueryLoggerIT.java | 66 +++++++++++- .../kernel/impl/query/QueryLoggerTest.java | 81 ++++++++++++-- 11 files changed, 310 insertions(+), 54 deletions(-) create mode 100644 community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/helpers/JavaCompatibility.scala diff --git a/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/PipeExecutionResult.scala b/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/PipeExecutionResult.scala index 59a85edf81aed..ed9ff117195ab 100644 --- a/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/PipeExecutionResult.scala +++ b/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/PipeExecutionResult.scala @@ -24,6 +24,7 @@ import java.util import java.util.Collections import org.neo4j.cypher.internal.compiler.v2_2.executionplan.InternalExecutionResult +import org.neo4j.cypher.internal.compiler.v2_2.helpers.JavaCompatibility.asJavaCompatible import org.neo4j.cypher.internal.compiler.v2_2.helpers.{Eagerly, CollectionSupport} import org.neo4j.cypher.internal.compiler.v2_2.pipes.QueryState import org.neo4j.cypher.internal.compiler.v2_2.planDescription.InternalPlanDescription @@ -55,7 +56,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] = @@ -64,7 +65,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 @@ -85,12 +86,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 state.query.withAnyOpenQueryContext( qtx => f(ExecutionResultDumper(result, columns, queryStatistics()))(qtx) ) diff --git a/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/helpers/JavaCompatibility.scala b/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/helpers/JavaCompatibility.scala new file mode 100644 index 0000000000000..d59536d4b13ee --- /dev/null +++ b/community/cypher/cypher-compiler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/helpers/JavaCompatibility.scala @@ -0,0 +1,35 @@ +/* + * Copyright (c) 2002-2016 "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.compiler.v2_2.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/cypher/cypher/src/main/scala/org/neo4j/cypher/ExecutionEngine.scala b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/ExecutionEngine.scala index f475287d93b5e..fdbe36a91f579 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,6 +22,7 @@ package org.neo4j.cypher import java.util.{Map => JavaMap} import org.neo4j.cypher.internal.compiler.v2_2._ +import org.neo4j.cypher.internal.compiler.v2_2.helpers.JavaCompatibility.asJavaMap import org.neo4j.cypher.internal.compiler.v2_2.helpers.LRUCache import org.neo4j.cypher.internal.compiler.v2_2.parser.ParserMonitor import org.neo4j.cypher.internal.compiler.v2_2.prettifier.Prettifier @@ -82,7 +83,7 @@ class ExecutionEngine(graph: GraphDatabaseService, logger: StringLogger = String @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) @@ -108,7 +109,7 @@ class ExecutionEngine(graph: GraphDatabaseService, logger: StringLogger = String @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) } diff --git a/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor2_2.scala b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor2_2.scala index 375f6aaee49a4..9c52dff41f842 100644 --- a/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor2_2.scala +++ b/community/cypher/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor2_2.scala @@ -257,11 +257,20 @@ case class ExecutionResultWrapperFor2_2(inner: InternalExecutionResult, planner: ) } - def close() = exceptionHandlerFor2_2.runSafely{ inner.close() } + def close() = exceptionHandlerFor2_2.runSafely { + endQueryExecution() + inner.close() + } def next() = exceptionHandlerFor2_2.runSafely{ inner.next() } - def hasNext = exceptionHandlerFor2_2.runSafely{ inner.hasNext } + def hasNext = exceptionHandlerFor2_2.runSafely { + val next = inner.hasNext + if (!next) { + endQueryExecution() + } + next + } def convert(i: InternalPlanDescription): ExtendedPlanDescription = exceptionHandlerFor2_2.runSafely { CompatibilityPlanDescription(i, CypherVersion.v2_2, planner) 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 7189ce887970d..295fb24810b0b 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.neo4j.cypher.internal.commons.CypherFunSuite import org.neo4j.graphdb.GraphDatabaseService import org.neo4j.kernel.GraphDatabaseAPI @@ -41,7 +43,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) } @@ -61,7 +63,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) } @@ -77,7 +79,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) } @@ -93,7 +95,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() @@ -123,7 +125,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) } @@ -148,7 +150,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) } @@ -164,7 +166,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() @@ -184,7 +186,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.profile("CYPHER 2.1 RETURN [1, 2, 3, 4, 5]", Map.empty[String, Any], session).javaIterator //then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 RETURN [1, 2, 3, 4, 5]") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 RETURN [1, 2, 3, 4, 5]", Collections.emptyMap()) while (result.hasNext) { verify(monitor, never).endSuccess(session) result.next() @@ -204,7 +206,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 2.1 RETURN 42", Map.empty[String, Any], session).javaIterator.close() // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -229,7 +231,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { } // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endFailure(session, throwable) } @@ -245,7 +247,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 2.1 CREATE()", Map.empty[String, Any], session).javaIterator // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 CREATE()") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.1 CREATE()", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -261,7 +263,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.profile("CYPHER 2.0 RETURN [1, 2, 3, 4, 5]", Map.empty[String, Any], session).javaIterator //then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 RETURN [1, 2, 3, 4, 5]") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 RETURN [1, 2, 3, 4, 5]", Collections.emptyMap()) while (result.hasNext) { verify(monitor, never).endSuccess(session) result.next() @@ -281,7 +283,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 2.0 RETURN 42", Map.empty[String, Any], session).javaIterator.close() // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -306,7 +308,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { } // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endFailure(session, throwable) } @@ -322,7 +324,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 2.0 CREATE()", Map.empty[String, Any], session).javaIterator // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 CREATE()") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 2.0 CREATE()", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -338,7 +340,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.profile("CYPHER 1.9 CREATE() RETURN [1, 2, 3, 4, 5]", Map.empty[String, Any], session).javaIterator //then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE() RETURN [1, 2, 3, 4, 5]") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE() RETURN [1, 2, 3, 4, 5]", Collections.emptyMap()) while (result.hasNext) { verify(monitor, never).endSuccess(session) result.next() @@ -358,7 +360,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 1.9 CREATE() RETURN 42", Map.empty[String, Any], session).javaIterator.close() // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE() RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE() RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endSuccess(session) } @@ -383,7 +385,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { } // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE() RETURN 42") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE() RETURN 42", Collections.emptyMap()) verify(monitor, times(1)).endFailure(session, throwable) } @@ -399,7 +401,7 @@ class QueryExecutionMonitorTest extends CypherFunSuite { val result = engine.execute("CYPHER 1.9 CREATE()", Map.empty[String, Any], session).javaIterator // then - verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 CREATE()") + verify(monitor, times(1)).startQueryExecution(session, "CYPHER 1.9 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 d459895aef186..d9bf58e476f3d 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.ExecutionResultWrapperFor2_2 import org.neo4j.cypher.internal.compiler.v2_2.PlannerName import org.neo4j.cypher.internal.compiler.v2_2.executionplan.InternalExecutionResult @@ -35,7 +37,7 @@ 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/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java b/community/kernel/src/main/java/org/neo4j/graphdb/factory/GraphDatabaseSettings.java index 6a3cc9c9df044..8fa1ddeb1e872 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 @@ -399,6 +399,9 @@ private static String defaultPageCacheMemory() @Description( "Log executed queries that takes longer than the configured threshold." ) public static final Setting log_queries = setting("dbms.querylog.enabled", BOOLEAN, FALSE ); + @Description( "Log parameters for executed queries that took longer than the configured threshold." ) + public static final Setting log_queries_parameter_logging_enabled = setting( "dbms.querylog.parameter_logging_enabled", BOOLEAN, TRUE ); + @Description( "The file where queries will be recorded." ) public static final Setting log_queries_filename = setting("dbms.querylog.filename", PATH, NO_DEFAULT ); 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 8dff0d5b08d2f..165fb22159580 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 ced42e36aab55..60542dfe2d879 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 @@ -20,11 +20,13 @@ package org.neo4j.kernel.impl.query; import java.io.File; +import java.util.Map; import org.neo4j.function.Factory; 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; @@ -74,9 +76,10 @@ public Lifecycle newKernelExtension( Dependencies dependencies ) throws Throwabl Long rotationThreshold = config.get( GraphDatabaseSettings.log_queries_rotation_threshold ); long thresholdMillis = config.get( GraphDatabaseSettings.log_queries_threshold ); + boolean logQueryParameters = config.get( GraphDatabaseSettings.log_queries_parameter_logging_enabled ); LoggerFactory loggerFactory = new LoggerFactory( dependencies.filesystem(), queryLogFile, rotationThreshold ); - QueryLogger logger = new QueryLogger( Clock.SYSTEM_CLOCK, loggerFactory, thresholdMillis ); + QueryLogger logger = new QueryLogger( Clock.SYSTEM_CLOCK, loggerFactory, thresholdMillis, logQueryParameters ); dependencies.monitoring().addMonitorListener( logger ); return logger; } @@ -90,16 +93,21 @@ public static class QueryLogger extends LifecycleAdapter implements QueryExecuti { private static final MetadataKey START_TIME = new MetadataKey<>( Long.class, "start time" ); private static final MetadataKey QUERY_STRING = new MetadataKey<>( String.class, "query string" ); + private static final MetadataKey> PARAMS = new MetadataKey<>( paramsClass(), "parameters" ); + private final Clock clock; private final Factory loggerFactory; private final long thresholdMillis; + private final boolean logQueryParameters; private StringLogger logger; - public QueryLogger( Clock clock, Factory loggerFactory, long thresholdMillis ) + public QueryLogger( Clock clock, Factory loggerFactory, long thresholdMillis, + boolean logQueryParameters ) { this.clock = clock; this.loggerFactory = loggerFactory; this.thresholdMillis = thresholdMillis; + this.logQueryParameters = logQueryParameters; } @Override @@ -116,11 +124,15 @@ public void shutdown() } @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 ); + if ( logQueryParameters ) + { + session.put( PARAMS, parameters ); + } if ( oldTime != null || oldQuery != null ) { logger.warn( String.format( "Concurrent queries for session %s: \"%s\" @ %s and \"%s\" @ %s", @@ -131,31 +143,103 @@ public void startQueryExecution( QuerySession session, String query ) @Override public void endFailure( QuerySession session, Throwable failure ) { - String query = session.remove( QUERY_STRING ); + String query = extractQueryString( session ); Long startTime = session.remove( START_TIME ); if ( startTime != null ) { long time = clock.currentTimeMillis() - startTime; - logger.error( String.format( "FAILURE %d ms: %s - %s", time, session, - query == null ? "" : query ), failure ); + logFailure( time, session, query, failure ); } } @Override public void endSuccess( QuerySession session ) { - String query = session.remove( QUERY_STRING ); + String query = extractQueryString( session ); Long startTime = session.remove( START_TIME ); if ( startTime != null ) { long time = clock.currentTimeMillis() - startTime; if ( time >= thresholdMillis ) { - logger.info( String.format( "SUCCESS %d ms: %s - %s", time, session, - query == null ? "" : query ) ); + logSuccess( time, session, query ); } } } + + private void logFailure( long time, QuerySession session, String query, Throwable failure ) + { + if ( logQueryParameters ) + { + String params = extractParamsString( session ); + logger.error( String.format( "FAILURE %d ms: %s - %s - %s", time, session, query, params ), failure ); + } + else + { + logger.error( String.format( "FAILURE %d ms: %s - %s", time, session, query ), failure ); + } + } + + private void logSuccess( long time, QuerySession session, String query ) + { + if ( logQueryParameters ) + { + String params = extractParamsString( session ); + logger.info( String.format( "SUCCESS %d ms: %s - %s - %s", time, session, query, params ) ); + } + else + { + logger.info( String.format( "SUCCESS %d ms: %s - %s", time, session, query ) ); + } + } + + private static String extractQueryString( QuerySession session ) + { + String query = session.remove( QUERY_STRING ); + return query == null ? "" : query; + } + + private static String extractParamsString( QuerySession session ) + { + Map params = session.remove( PARAMS ); + return mapAsString( params ); + } + + @SuppressWarnings( "unchecked" ) + private static String mapAsString( Map params ) + { + if ( params == null ) + { + return "{}"; + } + + StringBuilder builder = new StringBuilder( "{" ); + String sep = ""; + for ( Map.Entry entry : params.entrySet() ) + { + builder.append( sep ).append( entry.getKey() ).append( ": " ); + + Object value = entry.getValue(); + if ( value instanceof Map ) + { + builder.append( mapAsString( (Map) value ) ); + } + else + { + builder.append( Strings.prettyPrint( value ) ); + } + sep = ", "; + } + builder.append( "}" ); + + return builder.toString(); + } + + @SuppressWarnings( "unchecked" ) + private static Class> paramsClass() + { + return (Class>) (Object) Map.class; + } } private static class LoggerFactory implements Factory 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 401fb16716dd9..65d287c8b6d34 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 @@ -19,17 +19,22 @@ */ package org.neo4j.kernel.impl.query; -import org.hamcrest.Matchers; import org.junit.Before; import org.junit.Rule; import org.junit.Test; + import java.io.BufferedReader; import java.io.File; import java.io.IOException; import java.util.ArrayList; import java.util.Arrays; +import java.util.HashMap; +import java.util.LinkedHashMap; import java.util.List; +import java.util.Map; + 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; @@ -37,6 +42,7 @@ import org.neo4j.test.TargetDirectory; import org.neo4j.test.TestGraphDatabaseFactory; +import static org.hamcrest.Matchers.endsWith; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertThat; import static org.junit.Assert.assertTrue; @@ -64,16 +70,65 @@ 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() ) + .setConfig( GraphDatabaseSettings.log_queries_parameter_logging_enabled, Settings.FALSE ) .newGraphDatabase(); executeQueryAndShutdown( database ); List logLines = readAllLines( logFilename ); assertEquals( 1, logLines.size() ); - assertThat( logLines.get( 0 ), Matchers.endsWith( String.format( " ms: %s - %s", + assertThat( logLines.get( 0 ), endsWith( String.format( " ms: %s - %s", QueryEngineProvider.embeddedSession(), QUERY ) ) ); } + @Test + public void shouldLogParametersWhenNestedMap() throws Exception + { + File logFilename = new File( testDirectory.graphDbDir(), "queries.log" ); + GraphDatabaseService database = databaseBuilder.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE ) + .setConfig( GraphDatabaseSettings.log_queries_filename, logFilename.getPath() ) + .setConfig( GraphDatabaseSettings.log_queries_parameter_logging_enabled, Settings.TRUE ) + .newGraphDatabase(); + + Map props = new LinkedHashMap<>(); // to be sure about ordering in the last assertion + 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 ), endsWith( String.format( + " ms: %s - %s - {props: {name: Roland, position: Gunslinger, followers: [Jake, Eddie, Susannah]}}", + QueryEngineProvider.embeddedSession(), query ) ) ); + } + + @Test + public void shouldLogParametersWhenList() throws Exception + { + File logFilename = new File( testDirectory.graphDbDir(), "queries.log" ); + GraphDatabaseService database = databaseBuilder.setConfig( GraphDatabaseSettings.log_queries, Settings.TRUE ) + .setConfig( GraphDatabaseSettings.log_queries_filename, logFilename.getPath() ) + .setConfig( GraphDatabaseSettings.log_queries_parameter_logging_enabled, Settings.TRUE ) + .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 ), endsWith( String.format( + " ms: %s - %s - {ids: [0, 1, 2]}", + QueryEngineProvider.embeddedSession(), query ) ) ); + } + @Test public void shouldSuppressQueryLoggingIfTheGivenPathIsNull() throws Exception { @@ -156,6 +211,13 @@ private void executeQueryAndShutdown( GraphDatabaseService database ) database.shutdown(); } + private void executeQueryAndShutdown( GraphDatabaseService database, String query, Map params ) + { + Result execute = database.execute( query, params ); + execute.close(); + database.shutdown(); + } + private List readAllLines( File logFilename ) throws IOException { List logLines = new ArrayList<>(); 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 9d9fe22108b86..7d711a334c109 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 @@ -22,9 +22,14 @@ import org.junit.Test; import org.mockito.InOrder; +import java.util.Arrays; +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; import java.util.concurrent.TimeUnit; import org.neo4j.function.Factory; +import org.neo4j.helpers.Clock; import org.neo4j.helpers.FakeClock; import org.neo4j.kernel.impl.query.QueryLoggerKernelExtension.QueryLogger; import org.neo4j.kernel.impl.util.StringLogger; @@ -44,11 +49,11 @@ public void shouldLogQuerySlowerThanThreshold() throws Exception StringLogger logger = mock( StringLogger.class ); QuerySession session = session( "{the session}" ); FakeClock clock = new FakeClock(); - QueryLogger queryLogger = new QueryLogger( clock, new LoggerFactory( logger ), 10/*ms*/ ); + QueryLogger queryLogger = queryLoggerWithoutParams( logger, clock ); queryLogger.init(); // when - queryLogger.startQueryExecution( session, "MATCH (n) RETURN n" ); + queryLogger.startQueryExecution( session, "MATCH (n) RETURN n", Collections.emptyMap() ); clock.forward( 11, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( session ); @@ -63,11 +68,11 @@ public void shouldNotLogQueryFasterThanThreshold() throws Exception StringLogger logger = mock( StringLogger.class ); QuerySession session = session( "{the session}" ); FakeClock clock = new FakeClock(); - QueryLogger queryLogger = new QueryLogger( clock, new LoggerFactory( logger ), 10/*ms*/ ); + QueryLogger queryLogger = queryLoggerWithoutParams( logger, clock ); queryLogger.init(); // when - queryLogger.startQueryExecution( session, "MATCH (n) RETURN n" ); + queryLogger.startQueryExecution( session, "MATCH (n) RETURN n", Collections.emptyMap() ); clock.forward( 9, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( session ); @@ -84,15 +89,15 @@ public void shouldKeepTrackOfDifferentSessions() throws Exception QuerySession session2 = session( "{session two}" ); QuerySession session3 = session( "{session three}" ); FakeClock clock = new FakeClock(); - QueryLogger queryLogger = new QueryLogger( clock, new LoggerFactory( logger ), 10/*ms*/ ); + QueryLogger queryLogger = queryLoggerWithoutParams( logger, clock ); queryLogger.init(); // when - queryLogger.startQueryExecution( session1, "MATCH (a) RETURN a" ); + queryLogger.startQueryExecution( session1, "MATCH (a) RETURN a", Collections.emptyMap() ); clock.forward( 1, TimeUnit.MILLISECONDS ); - queryLogger.startQueryExecution( session2, "MATCH (b) RETURN b" ); + queryLogger.startQueryExecution( session2, "MATCH (b) RETURN b", Collections.emptyMap() ); clock.forward( 1, TimeUnit.MILLISECONDS ); - queryLogger.startQueryExecution( session3, "MATCH (c) RETURN c" ); + queryLogger.startQueryExecution( session3, "MATCH (c) RETURN c", Collections.emptyMap() ); clock.forward( 7, TimeUnit.MILLISECONDS ); queryLogger.endSuccess( session3 ); clock.forward( 7, TimeUnit.MILLISECONDS ); @@ -114,12 +119,12 @@ public void shouldLogQueryOnFailureEvenIfFasterThanThreshold() throws Exception StringLogger logger = mock( StringLogger.class ); QuerySession session = session( "{the session}" ); FakeClock clock = new FakeClock(); - QueryLogger queryLogger = new QueryLogger( clock, new LoggerFactory( logger ), 10/*ms*/ ); + QueryLogger queryLogger = queryLoggerWithoutParams( logger, clock ); queryLogger.init(); RuntimeException failure = new RuntimeException(); // when - queryLogger.startQueryExecution( session, "MATCH (n) RETURN n" ); + queryLogger.startQueryExecution( session, "MATCH (n) RETURN n", Collections.emptyMap() ); clock.forward( 1, TimeUnit.MILLISECONDS ); queryLogger.endFailure( session, failure ); @@ -127,6 +132,62 @@ public void shouldLogQueryOnFailureEvenIfFasterThanThreshold() throws Exception verify( logger ).error( "FAILURE 1 ms: {the session} - MATCH (n) RETURN n", failure ); } + @Test + public void shouldLogQueryParameters() throws Exception + { + // given + StringLogger logger = mock( StringLogger.class ); + QuerySession session = session( "{the session}" ); + FakeClock clock = new FakeClock(); + QueryLogger queryLogger = queryLoggerWithParams( logger, clock ); + queryLogger.init(); + + // when + Map params = new HashMap<>(); + params.put( "ages", Arrays.asList( 41, 42, 43 ) ); + queryLogger.startQueryExecution( session, "MATCH (n) WHERE n.age IN {ages} RETURN n", params ); + clock.forward( 11, TimeUnit.MILLISECONDS ); + queryLogger.endSuccess( session ); + + // then + verify( logger ).info( + "SUCCESS 11 ms: {the session} - MATCH (n) WHERE n.age IN {ages} RETURN n - {ages: [41, 42, 43]}" ); + } + + @Test + public void shouldLogQueryParametersOnFailure() throws Exception + { + // given + StringLogger logger = mock( StringLogger.class ); + QuerySession session = session( "{the session}" ); + FakeClock clock = new FakeClock(); + QueryLogger queryLogger = queryLoggerWithParams( logger, clock ); + queryLogger.init(); + RuntimeException failure = new RuntimeException(); + + // when + Map params = new HashMap<>(); + params.put( "ages", Arrays.asList( 41, 42, 43 ) ); + queryLogger.startQueryExecution( session, "MATCH (n) WHERE n.age IN {ages} RETURN n", params ); + clock.forward( 1, TimeUnit.MILLISECONDS ); + queryLogger.endFailure( session, failure ); + + // then + verify( logger ).error( + "FAILURE 1 ms: {the session} - MATCH (n) WHERE n.age IN {ages} RETURN n - {ages: [41, 42, 43]}", + failure ); + } + + private static QueryLogger queryLoggerWithoutParams( StringLogger logger, Clock clock ) + { + return new QueryLogger( clock, new LoggerFactory( logger ), 10/*ms*/, false ); + } + + private static QueryLogger queryLoggerWithParams( StringLogger logger, Clock clock ) + { + return new QueryLogger( clock, new LoggerFactory( logger ), 10/*ms*/, true ); + } + private static QuerySession session( final String data ) { return new QuerySession()