Show parameters in query logging

When logging slow queries we now also display the parameters
that was used for the specific case

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

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 {

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)

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)
   }
 

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){}
 

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 <http://www.gnu.org/licenses/>.
+ */
+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]]
+}

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 );
 

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<Long> START_TIME = new MetadataKey<>( Long.class, "start time" );
         private static final MetadataKey<String> QUERY_STRING = new MetadataKey<>( String.class, "query string" );
+        @SuppressWarnings( "unchecked" )
+        private static final MetadataKey<Map<String, Object>> PARAMS = new MetadataKey<>( (Class<Map<String, Object>>) (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<String,Object> 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<String,Object> 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 ? "<unknown query>" : query ), failure );
+                log.error( String.format( "%d ms: %s - %s - %s", time, session.toString(),
+                        query == null ? "<unknown query>" : query , mapToString( params )), failure );
             }
         }
 
@@ -184,12 +191,43 @@ public void endSuccess( QuerySession session )
             if ( startTime != null )
             {
                 long time = clock.currentTimeMillis() - startTime;
+                Map<String,Object> params = session.remove( PARAMS );
                 if ( time >= thresholdMillis )
                 {
-                    log.info( "%d ms: %s - %s", time, session.toString(),
-                            query == null ? "<unknown query>" : query );
+                    log.info( "%d ms: %s - %s - %s", time, session.toString(),
+                            query == null ? "<unknown query>" : query, mapToString( params ) );
                 }
             }
         }
+
+        @SuppressWarnings( "unchecked" )
+        private String mapToString( Map<String,Object> params )
+        {
+            if ( params == null )
+            {
+                return "{}";
+            }
+
+            StringBuilder builder = new StringBuilder( "{" );
+            String sep = "";
+            for ( Entry<String,Object> entry : params.entrySet() )
+            {
+                builder.append( sep ).append( entry.getKey() ).append( ": " );
+
+                Object value = entry.getValue();
+                if ( value instanceof Map<?,?> )
+                {
+                    builder.append( mapToString( (Map<String,Object>) value ) );
+                }
+                else
+                {
+                    builder.append( Strings.prettyPrint( value ) );
+                }
+                sep = ", ";
+            }
+            builder.append( "}" );
+
+            return builder.toString();
+        }
     }
 }