Db.addLogFunc

[jon]

Hi,

I have the following in boot:
DB.addLogFunc((query, len) => Log.info("The query: "+query+" took
"+len+" milliseconds"))

I was expecting the query parameter to be sql, but it's actually some
sort of guid

"INFO - The query: 6839c016-0122-f09a-9c96-0000003844e8 took 5
milliseconds"

Any ideas?
I'm running with derby.

Thanks,

Jon

[marius d.]

Yeah we're aware of that. That is based on toString application which
is JDBC driver dependent. I think Derek started some work on this to
correct this behavior. Derek ?


Br's,
Marius

[Derek Chen-Becker]

Well, I started looking at it and determined that the only way for us to truly log the queries would be to essentially make our own wrappers over Statement and PreparedStatement. There are projects (log4jdbc, notably) that already do this, and in a transparent manner. I'm not sure that adding a whole bunch of SQL logging directly to Lift is better than leveraging some existing libraries to do it.

Derek

[marius d.]

Probably building our own wrappers would be more lightweight then 3-rd
party. Jus' guessing

Br's,
Marius

On Aug 6, 9:58 pm, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
> Well, I started looking at it and determined that the only way for us to
> truly log the queries would be to essentially make our own wrappers over
> Statement and PreparedStatement. There are projects (log4jdbc, notably) that
> already do this, and in a transparent manner. I'm not sure that adding a
> whole bunch of SQL logging directly to Lift is better than leveraging some
> existing libraries to do it.
>
> Derek
>

[Derek Chen-Becker]

If there's a consensus that we want our own JDBC wrappers I'll go ahead and write them.

Derek

[jon]

btw, the query param happens to include the actual sql under h2.

[Derek Chen-Becker]

Right. The current impl just does a toString on the vendor's PreparedStatement. Some Vendors print GUIDs, some print the SQL, but there really aren't any requirements one way or the other.

Derek

[marius d.]

Please do so. If you need any help for some reason (time availability
etc.) please let me know. As a note probably the wrappers should be
only only when there is at least one log function registered.

Br's,
Marius

On Aug 6, 11:48 pm, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
> If there's a consensus that we want our own JDBC wrappers I'll go ahead and
> write them.
>
> Derek
>

[Derek Chen-Becker]

Will do.

[Derek Chen-Becker]

OK, a preliminary version of log wrappers is checked in on wip-dcb-sql-log-wrappers. I'll merge it on Tuesday if no one sees any problems with it.

Derek

[Bill Venners]

Hi Derek,

I noticed you checked in a change to Lift that updated the Maven ScalaTest ref. However the ref is to version 0.9.4, whereas the current version is 0.9.5. 

Thanks.

Bill

----

Bill Venners

Artima, Inc.

http://www.artima.com

[Derek Chen-Becker]

I only fixed the groupId because maven was giving me a warning that it had changed. I can bump the versions to 0.9.5 this week and if that builds fine I'll check it in.

[marius d.]

Derek,

I was looking to your code, GOOD stuff ! One thing though.The
LoggedStatement.toString would return a List of log entries and not a
query but the user's Log function expects a query and the time spent
on that query so there is a little miss match between when user's
function expects and what we're feeding to it. Also you are creating
strings like:

"Exec query \"%s\" : rs = %s".format(sql, rs)"

...which may be perfect. But I wonder if user's won't expect just the
query/update and nothing else and they will do their own logging and
formatting.


Br's,
Marius

On Aug 16, 3:07 am, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
> I only fixed the groupId because maven was giving me a warning that it had
> changed. I can bump the versions to 0.9.5 this week and if that builds fine
> I'll check it in.
>

> On Sat, Aug 15, 2009 at 3:22 PM, Bill Venners <b...@artima.com> wrote:
> > Hi Derek,
>
> > I noticed you checked in a change to Lift that updated the Maven ScalaTest
> > ref. However the ref is to version 0.9.4, whereas the current version is
> > 0.9.5.
>
> > Thanks.
>
> > Bill----
> > Bill Venners
> > Artima, Inc.
> >http://www.artima.com
>

> > On Aug 15, 2009, at 7:02 AM, Derek Chen-Becker <dchenbec...@gmail.com>

> > wrote:
>
> > OK, a preliminary version of log wrappers is checked in on
> > wip-dcb-sql-log-wrappers. I'll merge it on Tuesday if no one sees any
> > problems with it.
>
> > Derek
>

> > On Tue, Aug 11, 2009 at 11:08 AM, Derek Chen-Becker <<dchenbec...@gmail.com>
> > dchenbec...@gmail.com> wrote:
>
> >> Will do.
>

[Derek Chen-Becker]

Yeah, I was actually thinking about that same angle last night. Perhaps I could provide some control var on DB to enable detailed or basic logging? I think that it would be very useful in some cases, for example, to know that underlying code is setting max rows or max fetch size, but I agree that most people will probably just want basic statements logged. Also, with a prepared statement someone *could* execute multiple queries in one go, so I can't get rid of the list of stuff. Another approach would be to give the logFuncs List to the Logging classes and then they could decide whether to log (and time) each execution individually or all at once (if someone sets batch mode, for example). What do you think?

Derek

[Derek Chen-Becker]

Also, I just pushed a bump to 0.9.5 for scalatest to 1.0_maint. It'll make it into 1.0.1.

Derek

[marius d.]

On Aug 16, 5:18 pm, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
> Yeah, I was actually thinking about that same angle last night. Perhaps I
> could provide some control var on DB to enable detailed or basic logging?

Yeah ... or maybe for the logFunc to not pass just a query string but
an object (abstracted by a trait) and let the user extract from there
whatever is needed. Just the plain query and/or other stuff. Yes this
would mean a breaking change but I think a good one.

> I
> think that it would be very useful in some cases, for example, to know that
> underlying code is setting max rows or max fetch size, but I agree that most
> people will probably just want basic statements logged. Also, with a
> prepared statement someone *could* execute multiple queries in one go, so I
> can't get rid of the list of stuff.

Totally agree, but please see my notes above.

> Another approach would be to give the
> logFuncs List to the Logging classes and then they could decide whether to
> log (and time) each execution individually or all at once (if someone sets
> batch mode, for example). What do you think?

Based on the above I'd probably opt in for a trait rather then the
List.

Perhaps :

trait LogStatement {

def getStatement: (String, Long) // returns the statement and the
tiem spent

def getDetailedInfo: List[String] // /returns your list

}


... or you may be thinking of a better abstraction.

And logFuncs would become:

logFuncs: List[(LogStatement) => Any] = Nil


Br's,
Marius

>
> Derek

[Derek Chen-Becker]

1.1-SNAPSHOT has been bumped to 0.9.5 as well.

[Derek Chen-Becker]

I really like the idea of changing the logFunc type if everyone is OK with that. To further refine it, the trait could define three defs:

def getStatements : List[(String,Long)]
def getMetaCommands : List[(String,Long)]
def getAll : List[(String,Long)]

getAll would return the union of the first two, in proper sequential order. I could further refine this by making use of case classes instead of (String,Long):

sealed abstract class DBLogEntry
case class LoggedStatement(statement : String, duration : Long) extends DBLogEntry
case class LoggedMetaCommand(statement : String, duration : Long) extends DBLogEntry

I don't know enough detail on JDBC to know whether or not meta commands require round-trips to the DB or if the spec requires that they're all local, but it seems like we should just time everything.

Thoughts?

[marius d.]

On Aug 16, 6:56 pm, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
> I really like the idea of changing the logFunc type if everyone is OK with
> that. To further refine it, the trait could define three defs:
>
> def getStatements : List[(String,Long)]
> def getMetaCommands : List[(String,Long)]
> def getAll : List[(String,Long)]
>
> getAll would return the union of the first two, in proper sequential order.
> I could further refine this by making use of case classes instead of
> (String,Long):
>
> sealed abstract class DBLogEntry
> case class LoggedStatement(statement : String, duration : Long) extends
> DBLogEntry
> case class LoggedMetaCommand(statement : String, duration : Long) extends
> DBLogEntry
>
> I don't know enough detail on JDBC to know whether or not meta commands
> require round-trips to the DB or if the spec requires that they're all
> local, but it seems like we should just time everything.
>
> Thoughts?

I like it ... and I'd go for concrete cases classes(LoggedStatement,
LoggedMetaCommand ...) above as opposed to tupples. So at least you
got my vote :)

[Derek Chen-Becker]

Hi all,
    I've made a change to the Mapper logging functionality in wip-dcb-sql-log-wrappers. The DB.addLogFunc method has changed to:

addLogFunc( f: (DBLog,Long) => Any)

where DBLog is a new trait (below) and the Long corresponds to the *total* duration of a given DB execution method. DBLog is defined as:

trait DBLog {
  ... private stuff up here ...
  /** Return a list of all of the DBStatementEntry instances in the log buffer */
  def statementEntries : List[DBStatementEntry] = ...

  /** Return a list of all of the DBMetaEntry instances in the log buffer */
  def metaEntries : List[DBMetaEntry] = ...

  /** Return all log buffer entries */
  def allEntries : List[DBLogEntry] = ...
}

and we have some new event class/traits:

trait DBLogEntry {
  def statement : String
  def duration : Long
}
object DBLogEntry {
  def unapply(obj : Any) = obj match {
    case entry : DBLogEntry => Some(entry.statement,entry.duration)
    case _ => None
  }
}
case class DBStatementEntry(statement : String, duration : Long) extends DBLogEntry
case class DBMetaEntry(statement : String, duration : Long) extends DBLogEntry

Statements are SQL statements, prepared or immediate, and meta entries correspond to things like getMaxRows, getGeneratedKeys, etc. As you can see, each individual statement records its own duration as well, so you can get fine-grained detail on all activity. An example log function in Boot could look like:

    DB.addLogFunc {
      case (query, time) => {
        Log.info("All queries took " + time + "ms: ")
        query.allEntries.foreach({ case DBLogEntry(stmt, duration) => Log.info(stmt + " took " + duration + "ms")})
        Log.info("End queries")
      }
    }

And we get output like:

INFO - All queries took 17ms:
INFO - Exec update "INSERT INTO users (lastname,locale,password_pw,password_slt,validated,uniqueid,timezone,firstname,email,superuser,textarea) VALUES ("C","en_US","GzwLqDpmJ6TrECg06bGKvOAQxyc=","1JTAWGSSYLJHXASO",1,"DU0G0RT3IFOA0NHSY5QQQTX42BOIHDGI","US/Mountain","D","d...@c.com",0,"")" : updated 1 rows took 9ms
INFO - Get generated keys : rs = oracle.jdbc.driver.OracleReturnResultSet@23f9e6e5 took 2ms
INFO - Closed Statement took 0ms
INFO - End queries

Note that this code does introduce a breaking change if you're already using log functions, since the addLogFunc signature has changed. If I can get a review on the code before I merge to master I would appreciate it.

Derek

[marius d.]

EXCELLENT WORK DEREK !

> On Sat, Aug 15, 2009 at 8:02 AM, Derek Chen-Becker <dchenbec...@gmail.com>wrote:
>
> > OK, a preliminary version of log wrappers is checked in on
> > wip-dcb-sql-log-wrappers. I'll merge it on Tuesday if no one sees any
> > problems with it.
>
> > Derek
>

> > On Tue, Aug 11, 2009 at 11:08 AM, Derek Chen-Becker <dchenbec...@gmail.com
> > > wrote:
>
> >> Will do.

[David]

Hello, I'm trying to use the new logging information as described
here. In my Boot I have:

import net.liftweb.mapper.{DB, DBLogEntry}
snip...

DB.addLogFunc {
case (query, time) => {
Log.info("All queries took " + time + "ms: ")
query.allEntries.foreach({ case DBLogEntry(stmt, duration) =>
Log.info(stmt + " took " + duration + "ms")})
Log.info("End queries")
}
}

I'm using slf4j and logback, my root level is set to trace. I see
trace output from lift, like:
16:32:02.208 [5991680@qtp-10429832-0] TRACE lift.trace:76 - Released
connection ConnectionIdentifier(lift) on thread Thread
[5991680@qtp-10429832-0,5,main]

But I don't see any output from the DB log functions. Is there
anything else I need to do in order to enable logging? I'm using
scala 2.7.5 and lift 1.1-SNAPSHOT.

Thanks, Dave

On Aug 28, 1:20 pm, "marius d." <marius.dan...@gmail.com> wrote:
> EXCELLENT WORK DEREK !
>
> On Aug 28, 7:28 pm, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
>
> > Hi all,
> >     I've made a change to the Mapper logging functionality in

> > wip-dcb-sql-log-wrappers. The DB.addLogFuncmethod has changed to:

> > log functions, since theaddLogFuncsignature has changed. If I can get a

[Derek Chen-Becker]

I tested it locally on my own code and it works. Just for giggles, does anything print on the console if you change those lines to println?

Derek

[David]

Nope, changed to println():

DB.addLogFunc {
case (query, time) => {

println("All queries took " + time + "ms: ")

query.allEntries.foreach({ case DBLogEntry(stmt, duration) =>

println(stmt + " took " + duration + "ms")})
println("End queries")
}
}

Nothing on console.

Thanks, David

On Sep 28, 1:36 pm, Derek Chen-Becker <dchenbec...@gmail.com> wrote:
> I tested it locally on my own code and it works. Just for giggles, does
> anything print on the console if you change those lines to println?
>
> Derek
>

[David Pollak]

Could this be a JDK 1.5 vs. 1.6 issue?

--
Lift, the simply functional web framework http://liftweb.net
Beginning Scala http://www.apress.com/book/view/1430219890
Follow me: http://twitter.com/dpp
Surf the harmonics

[Derek Chen-Becker]

I can't rule it out, but because the new logging implements methods on java.sql.Statement that don't exist in Java 5, I would expect some classloading issues or exceptions.

[David]

Whoops, I take it back, not sure what happened earlier, but I am now
seeing the timing and queries when I use println. Maybe I did a mvn
clean. Sorry about that.

-Dave

On Sep 28, 1:47 pm, David Pollak <feeder.of.the.be...@gmail.com>
wrote:

> Beginning Scalahttp://www.apress.com/book/view/1430219890

[Derek Chen-Becker]

The refactored logging (supporting both Java 5 and 6) has been checked into master. I built it on my machine with both JDK1.5 and JDK1.6 JVMs and everything built.

Derek