Add JDBC statement parameter logging

Parameters are logged in tabular form to the new logger `slick.jdbc.JdbcBackend.parameter` similar to how results can already be logged to `slick.jdbc.StatementInvoker.result`. The table header contains the parameter index (1-based, as in JDBC) and the type. Batch operations with matching parameter types are shown in a single table. If the types change during a batch, the table gets broken up. Since the logging is integrated into the `LoggingPreparedStatement` decorator, it works for all kinds of statements and for both, Plain SQL queries and generated (Lifted Embedding) queries. Fixes #1150.
slick · Apr 22, 2016 · 2a06b58c198af0a6c4dcb35aa98aec8bf1b9d440 · 2a06b58
1 parent c3d6c54
commit 2a06b58c198af0a6c4dcb35aa98aec8bf1b9d440
Unified Split

Showing with 143 additions and 61 deletions.

+1 −0 common-test-resources/logback.xml

+5 −2 slick/src/main/scala/slick/jdbc/JdbcBackend.scala

+134 −59 slick/src/main/scala/slick/jdbc/LoggingStatement.scala

+3 −0 slick/src/sphinx/config.rst
diff --git a/common-test-resources/logback.xml b/common-test-resources/logback.xml
@@ -43,6 +43,7 @@
    <logger name="slick.compiler.VerifyTypes"               level="${log.qcomp.verifyTypes:-inherited}" />
    <logger name="slick.jdbc.DriverDataSource"              level="${log.jdbc.driver:-info}" />
    <logger name="slick.jdbc.JdbcBackend.statement"         level="${log.jdbc.statement:-info}" />
+    <logger name="slick.jdbc.JdbcBackend.parameter"         level="${log.jdbc.parameter:-info}" />
    <logger name="slick.jdbc.JdbcBackend.benchmark"         level="${log.jdbc.bench:-info}" />
    <logger name="slick.jdbc.StatementInvoker.result"       level="${log.jdbc.result:-info}" />
    <logger name="slick.jdbc.JdbcModelBuilder"              level="${log.createModel:-info}" />
diff --git a/slick/src/main/scala/slick/jdbc/JdbcBackend.scala b/slick/src/main/scala/slick/jdbc/JdbcBackend.scala
@@ -396,10 +396,12 @@ trait JdbcBackend extends RelationalBackend {
    }

    protected def loggingStatement(st: Statement): Statement =
-      if(JdbcBackend.statementLogger.isDebugEnabled || JdbcBackend.benchmarkLogger.isDebugEnabled) new LoggingStatement(st) else st
+      if(JdbcBackend.statementLogger.isDebugEnabled || JdbcBackend.benchmarkLogger.isDebugEnabled)
+        new LoggingStatement(st) else st

    protected def loggingPreparedStatement(st: PreparedStatement): PreparedStatement =
-      if(JdbcBackend.statementLogger.isDebugEnabled || JdbcBackend.benchmarkLogger.isDebugEnabled) new LoggingPreparedStatement(st) else st
+      if(JdbcBackend.statementLogger.isDebugEnabled || JdbcBackend.benchmarkLogger.isDebugEnabled || JdbcBackend.parameterLogger.isDebugEnabled)
+        new LoggingPreparedStatement(st) else st

    /** Start a `transactionally` block */
    private[slick] def startInTransaction: Unit
@@ -505,6 +507,7 @@ object JdbcBackend extends JdbcBackend {

  protected[jdbc] lazy val statementLogger = new SlickLogger(LoggerFactory.getLogger(classOf[JdbcBackend].getName+".statement"))
  protected[jdbc] lazy val benchmarkLogger = new SlickLogger(LoggerFactory.getLogger(classOf[JdbcBackend].getName+".benchmark"))
+  protected[jdbc] lazy val parameterLogger = new SlickLogger(LoggerFactory.getLogger(classOf[JdbcBackend].getName+".parameter"))

  protected[jdbc] def logStatement(msg: String, stmt: String) = if(statementLogger.isDebugEnabled) {
    val s = if(GlobalConfig.sqlIndent) msg + ":\n" + LogUtil.multilineBorder(stmt) else msg + ": " + stmt
diff --git a/slick/src/main/scala/slick/jdbc/LoggingStatement.scala b/slick/src/main/scala/slick/jdbc/LoggingStatement.scala
@@ -1,20 +1,89 @@
 package slick.jdbc

+import slick.util.TableDump
+
+import scala.collection.mutable.ArrayBuffer
 import scala.language.reflectiveCalls

-import java.sql.{PreparedStatement, Connection, SQLWarning, ResultSet, Statement}
+import java.io.{InputStream, Reader}
+import java.util.Calendar
+import java.{sql => js}
+import java.sql.{PreparedStatement, Connection, SQLWarning, ResultSet, Statement, Timestamp}

 /** A wrapper for `java.sql.Statement` that logs statements and benchmark results
  * to the appropriate [[JdbcBackend]] loggers. */
 class LoggingStatement(st: Statement) extends Statement {
  private[this] val doStatement = JdbcBackend.statementLogger.isDebugEnabled
  private[this] val doBenchmark = JdbcBackend.benchmarkLogger.isDebugEnabled
+  private[this] val doParameter = JdbcBackend.parameterLogger.isDebugEnabled
+
+  private[this] var params: ArrayBuffer[(Any, Any)] = null
+  private[this] var paramss: ArrayBuffer[ArrayBuffer[(Any, Any)]] = null
+
+  /** log a parameter */
+  protected[this] def p(idx: Int, tpe: Any, value: Any): Unit = if(doParameter) {
+    if(params eq null) params = new ArrayBuffer
+    if(params.size == idx) params += ((tpe, value))
+    else {
+      while(params.size < idx) params += null
+      params(idx-1) = (tpe, value)
+    }
+  }

-  @inline protected[this] def logged[T](sql: String, what: String = "statement")(f: =>T) = {
+  protected[this] def pushParams: Unit = if(doParameter) {
+    if(params ne null) {
+      if(paramss eq null) paramss = new ArrayBuffer
+      paramss += params
+    }
+    params = null
+  }
+
+  protected[this] def clearParamss: Unit = if(doParameter) {
+    paramss = null
+    params = null
+  }
+
+  protected[this] def logged[T](sql: String, what: String = "statement")(f: =>T) = {
    if(doStatement && (sql ne null)) JdbcBackend.statementLogger.debug("Executing "+what+": "+sql)
+    if(doParameter && (paramss ne null) && paramss.nonEmpty) {
+      // like s.groupBy but only group adjacent elements and keep the ordering
+      def groupBy[T](s: TraversableOnce[T])(f: T => AnyRef): IndexedSeq[IndexedSeq[T]] = {
+        var current: AnyRef = null
+        val b = new ArrayBuffer[ArrayBuffer[T]]
+        s.foreach { v =>
+          val id = f(v)
+          if(b.isEmpty || current != id) b += ArrayBuffer(v)
+          else b.last += v
+          current = id
+        }
+        b
+      }
+      def mkTpStr(tp: Int) = JdbcTypesComponent.typeNames.getOrElse(tp, tp.toString)
+      val paramSets = paramss.map { params =>
+        (params.map {
+          case (tp: Int, _) => mkTpStr(tp)
+          case ((tp: Int, scale: Int), _) => mkTpStr(tp)+"("+scale+")"
+          case ((tp: Int, tpStr: String), _) => mkTpStr(tp)+": "+tpStr
+          case (tpe, _) => tpe.toString
+        }, params.map {
+          case (_, null) => "NULL"
+          case (_, ()) => ""
+          case (_, v) =>
+            val s = v.toString
+            if(s eq null) "NULL" else s
+        })
+      }
+      val dump = new TableDump(25)
+      groupBy(paramSets)(_._1).foreach { matchingSets =>
+        val tpes = matchingSets.head._1
+        val idxs = 1.to(tpes.length).map(_.toString)
+        dump(Vector(idxs, tpes), matchingSets.map(_._2)).foreach(s => JdbcBackend.parameterLogger.debug(s))
+      }
+    }
    val t0 = if(doBenchmark) System.nanoTime() else 0L
    val res = f
    if(doBenchmark) JdbcBackend.benchmarkLogger.debug("Execution of "+what+" took "+formatNS(System.nanoTime()-t0))
+    clearParamss
    res
  }

@@ -77,64 +146,70 @@ class LoggingStatement(st: Statement) extends Statement {
    st.asInstanceOf[{ def isCloseOnCompletion(): Boolean }].isCloseOnCompletion()
 }

-/** A wrapper for `java.sql.PreparedStatement` that logs statements and benchmark results
+/** A wrapper for `java.sql.PreparedStatement` that logs statements, parameters and benchmark results
  * to the appropriate [[JdbcBackend]] loggers. */
 class LoggingPreparedStatement(st: PreparedStatement) extends LoggingStatement(st) with PreparedStatement {
-  def execute(): Boolean = logged(null, "prepared statement") { st.execute() }
-  def executeQuery(): java.sql.ResultSet = logged(null, "prepared query") { st.executeQuery() }
-  def executeUpdate(): Int = logged(null, "prepared update") { st.executeUpdate() }
-
-  def addBatch(): Unit = st.addBatch()
-  def clearParameters(): Unit = st.clearParameters()
-  def getMetaData(): java.sql.ResultSetMetaData = st.getMetaData
-  def getParameterMetaData(): java.sql.ParameterMetaData = st.getParameterMetaData()
-  def setArray(idx: Int, value: java.sql.Array): Unit = st.setArray(idx, value)
-  def setAsciiStream(idx: Int, value: java.io.InputStream): Unit = st.setAsciiStream(idx, value)
-  def setAsciiStream(idx: Int, value: java.io.InputStream, len: Long): Unit = st.setAsciiStream(idx, value, len)
-  def setAsciiStream(idx: Int, value: java.io.InputStream, len: Int): Unit = st.setAsciiStream(idx, value, len)
-  def setBigDecimal(idx: Int, value: java.math.BigDecimal): Unit = st.setBigDecimal(idx, value)
-  def setBinaryStream(idx: Int, value: java.io.InputStream): Unit = st.setBinaryStream(idx, value)
-  def setBinaryStream(idx: Int, value: java.io.InputStream, len: Long): Unit = st.setBinaryStream(idx, value, len)
-  def setBinaryStream(idx: Int, value: java.io.InputStream, len: Int): Unit = st.setBinaryStream(idx, value, len)
-  def setBlob(idx: Int, value: java.io.InputStream): Unit = st.setBlob(idx, value)
-  def setBlob(idx: Int, value: java.io.InputStream, len: Long): Unit = st.setBlob(idx, value, len)
-  def setBlob(idx: Int, value: java.sql.Blob): Unit = st.setBlob(idx, value)
-  def setBoolean(idx: Int, value: Boolean): Unit = st.setBoolean(idx, value)
-  def setByte(idx: Int, value: Byte): Unit = st.setByte(idx, value)
-  def setBytes(idx: Int, value: Array[Byte]): Unit = st.setBytes(idx, value)
-  def setCharacterStream(idx: Int, value: java.io.Reader): Unit = st.setCharacterStream(idx, value)
-  def setCharacterStream(idx: Int, value: java.io.Reader, len: Long): Unit = st.setCharacterStream(idx, value, len)
-  def setCharacterStream(idx: Int, value: java.io.Reader, len: Int): Unit = st.setCharacterStream(idx, value, len)
-  def setClob(idx: Int, value: java.io.Reader): Unit = st.setClob(idx, value)
-  def setClob(idx: Int, value: java.io.Reader, len: Long): Unit = st.setClob(idx, value, len)
-  def setClob(idx: Int, value: java.sql.Clob): Unit = st.setClob(idx, value)
-  def setDate(idx: Int, value: java.sql.Date, cal: java.util.Calendar): Unit = st.setDate(idx, value, cal)
-  def setDate(idx: Int, value: java.sql.Date): Unit = st.setDate(idx, value)
-  def setDouble(idx: Int, value: Double): Unit = st.setDouble(idx, value)
-  def setFloat(idx: Int, value: Float): Unit = st.setFloat(idx, value)
-  def setInt(idx: Int, value: Int): Unit = st.setInt(idx, value)
-  def setLong(idx: Int, value: Long): Unit = st.setLong(idx, value)
-  def setNCharacterStream(idx: Int, value: java.io.Reader): Unit = st.setNCharacterStream(idx, value)
-  def setNCharacterStream(idx: Int, value: java.io.Reader, len: Long): Unit = st.setNCharacterStream(idx, value, len)
-  def setNClob(idx: Int, value: java.io.Reader): Unit = st.setNClob(idx, value)
-  def setNClob(idx: Int, value: java.io.Reader, len: Long): Unit = st.setNClob(idx, value, len)
-  def setNClob(idx: Int, value: java.sql.NClob): Unit = st.setNClob(idx, value)
-  def setNString(idx: Int, value: String): Unit = st.setNString(idx, value)
-  def setNull(idx: Int, tpe: Int, tpeString: String): Unit = st.setNull(idx, tpe, tpeString)
-  def setNull(idx: Int, tpe: Int): Unit = st.setNull(idx, tpe)
-  def setObject(idx: Int, value: Any, tpe: Int, scale: Int): Unit = st.setObject(idx, value, tpe, scale)
-  def setObject(idx: Int, value: Any): Unit = st.setObject(idx, value)
-  def setObject(idx: Int, value: Any, tpe: Int): Unit = st.setObject(idx, value, tpe)
-  def setRef(idx: Int, value: java.sql.Ref): Unit = st.setRef(idx, value)
-  def setRowId(idx: Int, value: java.sql.RowId): Unit = st.setRowId(idx, value)
-  def setSQLXML(idx: Int, value: java.sql.SQLXML): Unit = st.setSQLXML(idx, value)
-  def setShort(idx: Int, value: Short): Unit = st.setShort(idx, value)
-  def setString(idx: Int, value: String): Unit = st.setString(idx, value)
-  def setTime(idx: Int, value: java.sql.Time, cal: java.util.Calendar): Unit = st.setTime(idx, value, cal)
-  def setTime(idx: Int, value: java.sql.Time): Unit = st.setTime(idx, value)
-  def setTimestamp(idx: Int, value: java.sql.Timestamp, cal: java.util.Calendar): Unit = st.setTimestamp(idx, value, cal)
-  def setTimestamp(idx: Int, value: java.sql.Timestamp): Unit = st.setTimestamp(idx, value)
-  def setURL(idx: Int, value: java.net.URL): Unit = st.setURL(idx, value)
+
+  def execute(): Boolean = { pushParams; logged(null, "prepared statement") { st.execute() } }
+  def executeQuery(): js.ResultSet = { pushParams; logged(null, "prepared query") { st.executeQuery() } }
+  def executeUpdate(): Int = { pushParams; logged(null, "prepared update") { st.executeUpdate() } }
+
+  def addBatch(): Unit = { pushParams; st.addBatch() }
+  def clearParameters(): Unit = { clearParamss; st.clearParameters() }
+
+  def getMetaData(): js.ResultSetMetaData = st.getMetaData
+  def getParameterMetaData(): js.ParameterMetaData = st.getParameterMetaData()
+
+  // printable parameters
+  def setArray           (i: Int, v: js.Array              ): Unit = { p(i, "Array",             v); st.setArray(i, v) }
+  def setBigDecimal      (i: Int, v: java.math.BigDecimal  ): Unit = { p(i, "BigDecimal",        v); st.setBigDecimal(i, v) }
+  def setBoolean         (i: Int, v: Boolean               ): Unit = { p(i, "Boolean",           v); st.setBoolean(i, v) }
+  def setByte            (i: Int, v: Byte                  ): Unit = { p(i, "Byte",              v); st.setByte(i, v) }
+  def setBytes           (i: Int, v: Array[Byte]           ): Unit = { p(i, "Bytes",             v); st.setBytes(i, v) }
+  def setDate            (i: Int, v: js.Date, c: Calendar  ): Unit = { p(i, "Date",         (v, c)); st.setDate(i, v, c) }
+  def setDate            (i: Int, v: js.Date               ): Unit = { p(i, "Date",              v); st.setDate(i, v) }
+  def setDouble          (i: Int, v: Double                ): Unit = { p(i, "Double",            v); st.setDouble(i, v) }
+  def setFloat           (i: Int, v: Float                 ): Unit = { p(i, "Float",             v); st.setFloat(i, v) }
+  def setInt             (i: Int, v: Int                   ): Unit = { p(i, "Int",               v); st.setInt(i, v) }
+  def setLong            (i: Int, v: Long                  ): Unit = { p(i, "Long",              v); st.setLong(i, v) }
+  def setNString         (i: Int, v: String                ): Unit = { p(i, "NString",           v); st.setNString(i, v) }
+  def setNull            (i: Int, tp: Int, tpStr: String   ): Unit = { p(i, (tp, tpStr),      null); st.setNull(i, tp, tpStr) }
+  def setNull            (i: Int, tp: Int                  ): Unit = { p(i, tp,               null); st.setNull(i, tp) }
+  def setObject          (i: Int, v: Any, tp: Int, scl: Int): Unit = { p(i, (tp, scl),           v); st.setObject(i, v, tp, scl) }
+  def setObject          (i: Int, v: Any, tp: Int          ): Unit = { p(i, tp,                  v); st.setObject(i, v, tp) }
+  def setObject          (i: Int, v: Any                   ): Unit = { p(i, "Object",            v); st.setObject(i, v) }
+  def setRef             (i: Int, v: js.Ref                ): Unit = { p(i, "Ref",               v); st.setRef(i, v) }
+  def setRowId           (i: Int, v: js.RowId              ): Unit = { p(i, "RowId",             v); st.setRowId(i, v) }
+  def setSQLXML          (i: Int, v: js.SQLXML             ): Unit = { p(i, "SQLXML",            v); st.setSQLXML(i, v) }
+  def setShort           (i: Int, v: Short                 ): Unit = { p(i, "Short",             v); st.setShort(i, v) }
+  def setString          (i: Int, v: String                ): Unit = { p(i, "String",            v); st.setString(i, v) }
+  def setTime            (i: Int, v: js.Time, c: Calendar  ): Unit = { p(i, "Time",         (v, c)); st.setTime(i, v, c) }
+  def setTime            (i: Int, v: js.Time               ): Unit = { p(i, "Time",              v); st.setTime(i, v) }
+  def setTimestamp       (i: Int, v: Timestamp, c: Calendar): Unit = { p(i, "Timestamp",    (v, c)); st.setTimestamp(i, v, c) }
+  def setTimestamp       (i: Int, v: Timestamp             ): Unit = { p(i, "Timestamp",         v); st.setTimestamp(i, v) }
+  def setURL             (i: Int, v: java.net.URL          ): Unit = { p(i, "URL",               v); st.setURL(i, v) }
+
+  // hidden parameters
+  def setAsciiStream     (i: Int, v: InputStream           ): Unit = { p(i, "AsciiStream",      ()); st.setAsciiStream(i, v) }
+  def setAsciiStream     (i: Int, v: InputStream, len: Long): Unit = { p(i, "AsciiStream",      ()); st.setAsciiStream(i, v, len) }
+  def setAsciiStream     (i: Int, v: InputStream, len: Int ): Unit = { p(i, "AsciiStream",      ()); st.setAsciiStream(i, v, len) }
+  def setBinaryStream    (i: Int, v: InputStream           ): Unit = { p(i, "BinaryStream",     ()); st.setBinaryStream(i, v) }
+  def setBinaryStream    (i: Int, v: InputStream, len: Long): Unit = { p(i, "BinaryStream",     ()); st.setBinaryStream(i, v, len) }
+  def setBinaryStream    (i: Int, v: InputStream, len: Int ): Unit = { p(i, "BinaryStream",     ()); st.setBinaryStream(i, v, len) }
+  def setBlob            (i: Int, v: InputStream           ): Unit = { p(i, "Blob",             ()); st.setBlob(i, v) }
+  def setBlob            (i: Int, v: InputStream, len: Long): Unit = { p(i, "Blob",             ()); st.setBlob(i, v, len) }
+  def setBlob            (i: Int, v: js.Blob               ): Unit = { p(i, "Blob",             ()); st.setBlob(i, v) }
+  def setCharacterStream (i: Int, v: Reader                ): Unit = { p(i, "CharacterStream",  ()); st.setCharacterStream(i, v) }
+  def setCharacterStream (i: Int, v: Reader, len: Long     ): Unit = { p(i, "CharacterStream",  ()); st.setCharacterStream(i, v, len) }
+  def setCharacterStream (i: Int, v: Reader, len: Int      ): Unit = { p(i, "CharacterStream",  ()); st.setCharacterStream(i, v, len) }
+  def setClob            (i: Int, v: Reader                ): Unit = { p(i, "Clob",             ()); st.setClob(i, v) }
+  def setClob            (i: Int, v: Reader, len: Long     ): Unit = { p(i, "Clob",             ()); st.setClob(i, v, len) }
+  def setClob            (i: Int, v: js.Clob               ): Unit = { p(i, "Clob",             ()); st.setClob(i, v) }
+  def setNCharacterStream(i: Int, v: Reader                ): Unit = { p(i, "NCharacterStream", ()); st.setNCharacterStream(i, v) }
+  def setNCharacterStream(i: Int, v: Reader, len: Long     ): Unit = { p(i, "NCharacterStream", ()); st.setNCharacterStream(i, v, len) }
+  def setNClob           (i: Int, v: Reader                ): Unit = { p(i, "NClob",            ()); st.setNClob(i, v) }
+  def setNClob           (i: Int, v: Reader, len: Long     ): Unit = { p(i, "NClob",            ()); st.setNClob(i, v, len) }
+  def setNClob           (i: Int, v: js.NClob              ): Unit = { p(i, "NClob",            ()); st.setNClob(i, v) }
  @deprecated("setUnicodeStream is deprecated", "")
-  def setUnicodeStream(idx: Int, value: java.io.InputStream, len: Int): Unit = st.setUnicodeStream(idx, value, len)
+  def setUnicodeStream   (i: Int, v: InputStream, len: Int ): Unit = { p(i, "UnicodeStream",    ()); st.setUnicodeStream(i, v, len) }
 }
diff --git a/slick/src/sphinx/config.rst b/slick/src/sphinx/config.rst
@@ -48,6 +48,9 @@ The following loggers are particularly interesting:
 ``slick.jdbc.JdbcBackend.statement``
   Shows all SQL statements which are executed.

+``slick.jdbc.JdbcBackend.parameter``
+   Shows bind variable contents (for supported types) of all SQL statements which are executed.
+
 ``slick.jdbc.JdbcBackend.benchmark``
   Shows execution times for SQL statements.