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** 24f867e. Additional setting `dbms.querylog.parameter_logging_enabled` is added to enable/disable logging of query parameters.
neo4j · Apr 15, 2016 · 4e8a2a1 · 4e8a2a1
1 parent 2f5f2fc
commit 4e8a2a1
Show file tree

Hide file tree

Showing 11 changed files with 310 additions and 54 deletions.
diff --git a/...iler-2.2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/PipeExecutionResult.scala b/...iler-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/....2/src/main/scala/org/neo4j/cypher/internal/compiler/v2_2/helpers/JavaCompatibility.scala b/....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 <http://www.gnu.org/licenses/>.
+ */
+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
@@ -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/...r/cypher/src/main/scala/org/neo4j/cypher/internal/compatibility/CompatibilityFor2_2.scala b/...r/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
@@ -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
@@ -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
@@ -399,6 +399,9 @@ private static String defaultPageCacheMemory()
     @Description( "Log executed queries that takes longer than the configured threshold." )
     public static final Setting<Boolean> 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<Boolean> 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<File> 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
@@ -19,14 +19,16 @@
  */
 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
  * of them with the same session parameter should do nothing.
  */
 public interface QueryExecutionMonitor
 {
-    void startQueryExecution( QuerySession session, String query );
+    void startQueryExecution( QuerySession session, String query, Map<String,Object> parameters );
 
     void endFailure( QuerySession session, Throwable failure );