[Lift] Re: DB logging logs statements twice?
That's +2 to removing the logging from runPreparedStatement? Any other
feelings one way or the other?
Derek
On Thu, Oct 15, 2009 at 8:13 AM, Viktor Klang wrote:
> I vote for DB.exec
>
>
> On Thu, Oct 15, 2009 at 4:09 PM, Derek Chen-Becker
> wrote:
>
>> OK, I found what's happening. Logging is getting called in the private
>> DB.runPreparedStatement, and also in the DB.exec method. Mapper uses exec
>> within the runPreparedStatement call. It seems like exec is the more
>> appropriate place to be running the logging, since you could have multiple
>> execs on a prepared statement but you generally wouldn't prepare a statement
>> without executing it. Thoughts on removing the logging from
>> runPreparedStatement?
>>
>> Derek
>>
>>
>> On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker <
>> dchenbec...@gmail.com> wrote:
>>
>>> I don't think so. In this case I'm seeing a ResultSet in both log
>>> entries, which shouldn't show up in the part where it's being prepared.
>>>
>>> Derek
>>>
>>>
>>> On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson
>>> wrote:
>>>
Is this related to a previous query dated 15 Sept, the title was
[Lift] Mapper: Why is every SQL query sent twice? (second time with
NULL parameters)
The response from @dpp was
"The SQL is not being sent twice. There are two different points (when
the Statement is created and after the Statement is executed) that the same
query is logged."
Cheers
Jono
2009/10/14 Derek Chen-Becker
OK, I'm seeing the same thing here. I'll open an issue and work on it.
>
> Derek
>
>
> On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>
>>
>> I'm also seeing this double logging behavior (using PostgreSQL. I was
>> under the impression that it was happening because the SQL statement
>> is first prepared, and then executed (each of which cause a log
>> entry). It's not critical or anything, but it would be nice if this
>> could be fixed at some point.
>>
>> -harryh
>>
>> On Oct 13, 10:28 am, Derek Chen-Becker wrote:
>> > I'm not sure how that could be getting logged twice, especially
>> since it's
>> > the exact same ResultSet being returned. When I tested this on my
>> local app
>> > (against both PG and MySQL) I didn't get this behavior, but I'll try
>> pulling
>> > from master and testing again just in case something changed.
>> >
>> > Derek
>> >
>> > On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen <
>> je...@ingolfs.dk>wrote:
>> >
>> >
>> >
>> > > Hi,
>> >
>> > > Just wanted to update to the new db logging by adding the
>> following to
>> > > boot:
>> >
>> > > DB.addLogFunc {
>> > > case (query:DBLog, time) => {
>> > >LogBoot.loggerByName("query").info(">>> All queries took "
>> + time +
>> > > "ms: ")
>> > >query.statementEntries.foreach({ case DBLogEntry(stmt,
>> duration) =>
>> > > LogBoot.loggerByName("query").info(""+stmt + " took " +
>> duration +
>> > > "ms")})
>> > >LogBoot.loggerByName("query").info("<<< End queries")
>> > > }
>> > >}
>> >
>> > > But it seems all executed statements are logged twice. I have this
>> > > snippet:
>> >
>> > > def currentUser(xhtml: Group): NodeSeq =
>> > > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName +
>> " " +
>> > > user.lastName))
>> >
>> > > This logs:
>> >
>> > > 14:46:09.068 [tp-1029120287-4] INFO query
>>-
>> > > >>> All queries took 5ms:
>> > > 14:46:09.068 [tp-1029120287-4] INFO query
>>-
>> > > Exec query "SELECT users.id, users.firstname, users.lastname,
>> > > users.email, users.locale, users.timezone, users.password_pw,
>> > > users.password_slt, users.account_id, users.superuser,
>> users.uniqueid,
>> > > users.validated FROM users WHERE id = 2 (scale -5)" :
>> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>-
>> > > <<< End queries
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>-
>> > > >>> All queries took 8ms:
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>-
>> > > Exec query "SELECT users.id, users.firstname, users.lastname,
>> > > users.email, users.locale, users.timezone, users.password_pw,
>> > > users.password_slt, users.account_id, users.superuser,
>> users.uniqueid,
>> > > users.validated FROM users WHERE id = 2 (scale -5)" :
>> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>> > > - <<< End queries
>> >
>> > > Note the same resultset. The postgres logs also shows that only a
>> single
>> > > statement is executed.
[Lift] Re: DB logging logs statements twice?
I vote for DB.exec
On Thu, Oct 15, 2009 at 4:09 PM, Derek Chen-Becker wrote:
> OK, I found what's happening. Logging is getting called in the private
> DB.runPreparedStatement, and also in the DB.exec method. Mapper uses exec
> within the runPreparedStatement call. It seems like exec is the more
> appropriate place to be running the logging, since you could have multiple
> execs on a prepared statement but you generally wouldn't prepare a statement
> without executing it. Thoughts on removing the logging from
> runPreparedStatement?
>
> Derek
>
>
> On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker > wrote:
>
>> I don't think so. In this case I'm seeing a ResultSet in both log entries,
>> which shouldn't show up in the part where it's being prepared.
>>
>> Derek
>>
>>
>> On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson wrote:
>>
>>> Is this related to a previous query dated 15 Sept, the title was
>>> [Lift] Mapper: Why is every SQL query sent twice? (second time with NULL
>>> parameters)
>>> The response from @dpp was
>>>
>>> "The SQL is not being sent twice. There are two different points (when
>>> the Statement is created and after the Statement is executed) that the same
>>> query is logged."
>>>
>>>
>>> Cheers
>>> Jono
>>>
>>>
>>> 2009/10/14 Derek Chen-Becker
>>>
>>> OK, I'm seeing the same thing here. I'll open an issue and work on it.
Derek
On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>
> I'm also seeing this double logging behavior (using PostgreSQL. I was
> under the impression that it was happening because the SQL statement
> is first prepared, and then executed (each of which cause a log
> entry). It's not critical or anything, but it would be nice if this
> could be fixed at some point.
>
> -harryh
>
> On Oct 13, 10:28 am, Derek Chen-Becker wrote:
> > I'm not sure how that could be getting logged twice, especially since
> it's
> > the exact same ResultSet being returned. When I tested this on my
> local app
> > (against both PG and MySQL) I didn't get this behavior, but I'll try
> pulling
> > from master and testing again just in case something changed.
> >
> > Derek
> >
> > On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen <
> je...@ingolfs.dk>wrote:
> >
> >
> >
> > > Hi,
> >
> > > Just wanted to update to the new db logging by adding the following
> to
> > > boot:
> >
> > > DB.addLogFunc {
> > > case (query:DBLog, time) => {
> > >LogBoot.loggerByName("query").info(">>> All queries took " +
> time +
> > > "ms: ")
> > >query.statementEntries.foreach({ case DBLogEntry(stmt,
> duration) =>
> > > LogBoot.loggerByName("query").info(""+stmt + " took " +
> duration +
> > > "ms")})
> > >LogBoot.loggerByName("query").info("<<< End queries")
> > > }
> > >}
> >
> > > But it seems all executed statements are logged twice. I have this
> > > snippet:
> >
> > > def currentUser(xhtml: Group): NodeSeq =
> > > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName +
> " " +
> > > user.lastName))
> >
> > > This logs:
> >
> > > 14:46:09.068 [tp-1029120287-4] INFO query
>-
> > > >>> All queries took 5ms:
> > > 14:46:09.068 [tp-1029120287-4] INFO query
>-
> > > Exec query "SELECT users.id, users.firstname, users.lastname,
> > > users.email, users.locale, users.timezone, users.password_pw,
> > > users.password_slt, users.account_id, users.superuser,
> users.uniqueid,
> > > users.validated FROM users WHERE id = 2 (scale -5)" :
> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > <<< End queries
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > >>> All queries took 8ms:
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > Exec query "SELECT users.id, users.firstname, users.lastname,
> > > users.email, users.locale, users.timezone, users.password_pw,
> > > users.password_slt, users.account_id, users.superuser,
> users.uniqueid,
> > > users.validated FROM users WHERE id = 2 (scale -5)" :
> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > > 14:46:09.069 [tp-1029120287-4] INFO query
> > > - <<< End queries
> >
> > > Note the same resultset. The postgres logs also shows that only a
> single
> > > statement is executed
> >
> > > So, what did I miss?
> >
> > > /Jeppe
>
>
>>>
>>>
>>>
>>
>
> >
>
--
Viktor Klang
Blog: klangism.blogspot.com
Twttr: viktorklang
Wave: viktor.kl...@googlewave.com
Code: github.com/viktorklang
AKKA Committer - akkasource.org
Lift Committer - liftweb.com
Atmosphere Committer - at
[Lift] Re: DB logging logs statements twice?
Another option that I just thought of would be to add a "logged" flag on the
PreparedStatement wrapper so that it knows not to print a dup.
Derek
On Thu, Oct 15, 2009 at 8:09 AM, Derek Chen-Becker wrote:
> OK, I found what's happening. Logging is getting called in the private
> DB.runPreparedStatement, and also in the DB.exec method. Mapper uses exec
> within the runPreparedStatement call. It seems like exec is the more
> appropriate place to be running the logging, since you could have multiple
> execs on a prepared statement but you generally wouldn't prepare a statement
> without executing it. Thoughts on removing the logging from
> runPreparedStatement?
>
> Derek
>
>
> On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker > wrote:
>
>> I don't think so. In this case I'm seeing a ResultSet in both log entries,
>> which shouldn't show up in the part where it's being prepared.
>>
>> Derek
>>
>>
>> On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson wrote:
>>
>>> Is this related to a previous query dated 15 Sept, the title was
>>> [Lift] Mapper: Why is every SQL query sent twice? (second time with NULL
>>> parameters)
>>> The response from @dpp was
>>>
>>> "The SQL is not being sent twice. There are two different points (when
>>> the Statement is created and after the Statement is executed) that the same
>>> query is logged."
>>>
>>>
>>> Cheers
>>> Jono
>>>
>>>
>>> 2009/10/14 Derek Chen-Becker
>>>
>>> OK, I'm seeing the same thing here. I'll open an issue and work on it.
Derek
On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>
> I'm also seeing this double logging behavior (using PostgreSQL. I was
> under the impression that it was happening because the SQL statement
> is first prepared, and then executed (each of which cause a log
> entry). It's not critical or anything, but it would be nice if this
> could be fixed at some point.
>
> -harryh
>
> On Oct 13, 10:28 am, Derek Chen-Becker wrote:
> > I'm not sure how that could be getting logged twice, especially since
> it's
> > the exact same ResultSet being returned. When I tested this on my
> local app
> > (against both PG and MySQL) I didn't get this behavior, but I'll try
> pulling
> > from master and testing again just in case something changed.
> >
> > Derek
> >
> > On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen <
> je...@ingolfs.dk>wrote:
> >
> >
> >
> > > Hi,
> >
> > > Just wanted to update to the new db logging by adding the following
> to
> > > boot:
> >
> > > DB.addLogFunc {
> > > case (query:DBLog, time) => {
> > >LogBoot.loggerByName("query").info(">>> All queries took " +
> time +
> > > "ms: ")
> > >query.statementEntries.foreach({ case DBLogEntry(stmt,
> duration) =>
> > > LogBoot.loggerByName("query").info(""+stmt + " took " +
> duration +
> > > "ms")})
> > >LogBoot.loggerByName("query").info("<<< End queries")
> > > }
> > >}
> >
> > > But it seems all executed statements are logged twice. I have this
> > > snippet:
> >
> > > def currentUser(xhtml: Group): NodeSeq =
> > > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName +
> " " +
> > > user.lastName))
> >
> > > This logs:
> >
> > > 14:46:09.068 [tp-1029120287-4] INFO query
>-
> > > >>> All queries took 5ms:
> > > 14:46:09.068 [tp-1029120287-4] INFO query
>-
> > > Exec query "SELECT users.id, users.firstname, users.lastname,
> > > users.email, users.locale, users.timezone, users.password_pw,
> > > users.password_slt, users.account_id, users.superuser,
> users.uniqueid,
> > > users.validated FROM users WHERE id = 2 (scale -5)" :
> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > <<< End queries
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > >>> All queries took 8ms:
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > Exec query "SELECT users.id, users.firstname, users.lastname,
> > > users.email, users.locale, users.timezone, users.password_pw,
> > > users.password_slt, users.account_id, users.superuser,
> users.uniqueid,
> > > users.validated FROM users WHERE id = 2 (scale -5)" :
> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > > 14:46:09.069 [tp-1029120287-4] INFO query
> > > - <<< End queries
> >
> > > Note the same resultset. The postgres logs also shows that only a
> single
> > > statement is executed
> >
> > > So, what did I miss?
> >
> > > /Jeppe
>
>
>>>
>>> >>>
>>>
>>
>
--~--~-~--~~~---~--~~
You received this message because yo
[Lift] Re: DB logging logs statements twice?
OK, I found what's happening. Logging is getting called in the private
DB.runPreparedStatement, and also in the DB.exec method. Mapper uses exec
within the runPreparedStatement call. It seems like exec is the more
appropriate place to be running the logging, since you could have multiple
execs on a prepared statement but you generally wouldn't prepare a statement
without executing it. Thoughts on removing the logging from
runPreparedStatement?
Derek
On Wed, Oct 14, 2009 at 11:42 PM, Derek Chen-Becker
wrote:
> I don't think so. In this case I'm seeing a ResultSet in both log entries,
> which shouldn't show up in the part where it's being prepared.
>
> Derek
>
>
> On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson wrote:
>
>> Is this related to a previous query dated 15 Sept, the title was
>> [Lift] Mapper: Why is every SQL query sent twice? (second time with NULL
>> parameters)
>> The response from @dpp was
>>
>> "The SQL is not being sent twice. There are two different points (when
>> the Statement is created and after the Statement is executed) that the same
>> query is logged."
>>
>>
>> Cheers
>> Jono
>>
>>
>> 2009/10/14 Derek Chen-Becker
>>
>> OK, I'm seeing the same thing here. I'll open an issue and work on it.
>>>
>>> Derek
>>>
>>>
>>> On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>>>
I'm also seeing this double logging behavior (using PostgreSQL. I was
under the impression that it was happening because the SQL statement
is first prepared, and then executed (each of which cause a log
entry). It's not critical or anything, but it would be nice if this
could be fixed at some point.
-harryh
On Oct 13, 10:28 am, Derek Chen-Becker wrote:
> I'm not sure how that could be getting logged twice, especially since
it's
> the exact same ResultSet being returned. When I tested this on my
local app
> (against both PG and MySQL) I didn't get this behavior, but I'll try
pulling
> from master and testing again just in case something changed.
>
> Derek
>
> On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen <
je...@ingolfs.dk>wrote:
>
>
>
> > Hi,
>
> > Just wanted to update to the new db logging by adding the following
to
> > boot:
>
> > DB.addLogFunc {
> > case (query:DBLog, time) => {
> >LogBoot.loggerByName("query").info(">>> All queries took " +
time +
> > "ms: ")
> >query.statementEntries.foreach({ case DBLogEntry(stmt,
duration) =>
> > LogBoot.loggerByName("query").info(""+stmt + " took " + duration
+
> > "ms")})
> >LogBoot.loggerByName("query").info("<<< End queries")
> > }
> >}
>
> > But it seems all executed statements are logged twice. I have this
> > snippet:
>
> > def currentUser(xhtml: Group): NodeSeq =
> > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + "
" +
> > user.lastName))
>
> > This logs:
>
> > 14:46:09.068 [tp-1029120287-4] INFO query
-
> > >>> All queries took 5ms:
> > 14:46:09.068 [tp-1029120287-4] INFO query
-
> > Exec query "SELECT users.id, users.firstname, users.lastname,
> > users.email, users.locale, users.timezone, users.password_pw,
> > users.password_slt, users.account_id, users.superuser,
users.uniqueid,
> > users.validated FROM users WHERE id = 2 (scale -5)" :
> > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > 14:46:09.069 [tp-1029120287-4] INFO query
-
> > <<< End queries
> > 14:46:09.069 [tp-1029120287-4] INFO query
-
> > >>> All queries took 8ms:
> > 14:46:09.069 [tp-1029120287-4] INFO query
-
> > Exec query "SELECT users.id, users.firstname, users.lastname,
> > users.email, users.locale, users.timezone, users.password_pw,
> > users.password_slt, users.account_id, users.superuser,
users.uniqueid,
> > users.validated FROM users WHERE id = 2 (scale -5)" :
> > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > 14:46:09.069 [tp-1029120287-4] INFO query
> > - <<< End queries
>
> > Note the same resultset. The postgres logs also shows that only a
single
> > statement is executed
>
> > So, what did I miss?
>
> > /Jeppe
>>>
>>>
>>>
>>
>> >>
>>
>
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
"Lift" group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---
[Lift] Re: DB logging logs statements twice?
I don't think so. In this case I'm seeing a ResultSet in both log entries,
which shouldn't show up in the part where it's being prepared.
Derek
On Tue, Oct 13, 2009 at 6:09 PM, Jonathan Ferguson wrote:
> Is this related to a previous query dated 15 Sept, the title was
> [Lift] Mapper: Why is every SQL query sent twice? (second time with NULL
> parameters)
> The response from @dpp was
>
> "The SQL is not being sent twice. There are two different points (when the
> Statement is created and after the Statement is executed) that the same
> query is logged."
>
>
> Cheers
> Jono
>
>
> 2009/10/14 Derek Chen-Becker
>
> OK, I'm seeing the same thing here. I'll open an issue and work on it.
>>
>> Derek
>>
>>
>> On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>>
>>>
>>> I'm also seeing this double logging behavior (using PostgreSQL. I was
>>> under the impression that it was happening because the SQL statement
>>> is first prepared, and then executed (each of which cause a log
>>> entry). It's not critical or anything, but it would be nice if this
>>> could be fixed at some point.
>>>
>>> -harryh
>>>
>>> On Oct 13, 10:28 am, Derek Chen-Becker wrote:
>>> > I'm not sure how that could be getting logged twice, especially since
>>> it's
>>> > the exact same ResultSet being returned. When I tested this on my local
>>> app
>>> > (against both PG and MySQL) I didn't get this behavior, but I'll try
>>> pulling
>>> > from master and testing again just in case something changed.
>>> >
>>> > Derek
>>> >
>>> > On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen >> >wrote:
>>> >
>>> >
>>> >
>>> > > Hi,
>>> >
>>> > > Just wanted to update to the new db logging by adding the following
>>> to
>>> > > boot:
>>> >
>>> > > DB.addLogFunc {
>>> > > case (query:DBLog, time) => {
>>> > >LogBoot.loggerByName("query").info(">>> All queries took " +
>>> time +
>>> > > "ms: ")
>>> > >query.statementEntries.foreach({ case DBLogEntry(stmt,
>>> duration) =>
>>> > > LogBoot.loggerByName("query").info(""+stmt + " took " + duration
>>> +
>>> > > "ms")})
>>> > >LogBoot.loggerByName("query").info("<<< End queries")
>>> > > }
>>> > >}
>>> >
>>> > > But it seems all executed statements are logged twice. I have this
>>> > > snippet:
>>> >
>>> > > def currentUser(xhtml: Group): NodeSeq =
>>> > > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + "
>>> " +
>>> > > user.lastName))
>>> >
>>> > > This logs:
>>> >
>>> > > 14:46:09.068 [tp-1029120287-4] INFO query
>>> -
>>> > > >>> All queries took 5ms:
>>> > > 14:46:09.068 [tp-1029120287-4] INFO query
>>> -
>>> > > Exec query "SELECT users.id, users.firstname, users.lastname,
>>> > > users.email, users.locale, users.timezone, users.password_pw,
>>> > > users.password_slt, users.account_id, users.superuser,
>>> users.uniqueid,
>>> > > users.validated FROM users WHERE id = 2 (scale -5)" :
>>> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
>>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>> -
>>> > > <<< End queries
>>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>> -
>>> > > >>> All queries took 8ms:
>>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>> -
>>> > > Exec query "SELECT users.id, users.firstname, users.lastname,
>>> > > users.email, users.locale, users.timezone, users.password_pw,
>>> > > users.password_slt, users.account_id, users.superuser,
>>> users.uniqueid,
>>> > > users.validated FROM users WHERE id = 2 (scale -5)" :
>>> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
>>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>> > > - <<< End queries
>>> >
>>> > > Note the same resultset. The postgres logs also shows that only a
>>> single
>>> > > statement is executed
>>> >
>>> > > So, what did I miss?
>>> >
>>> > > /Jeppe
>>>
>>>
>>
>>
>>
>
> >
>
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
"Lift" group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---
[Lift] Re: DB logging logs statements twice?
Is this related to a previous query dated 15 Sept, the title was
[Lift] Mapper: Why is every SQL query sent twice? (second time with NULL
parameters)
The response from @dpp was
"The SQL is not being sent twice. There are two different points (when the
Statement is created and after the Statement is executed) that the same
query is logged."
Cheers
Jono
2009/10/14 Derek Chen-Becker
> OK, I'm seeing the same thing here. I'll open an issue and work on it.
>
> Derek
>
>
> On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>
>>
>> I'm also seeing this double logging behavior (using PostgreSQL. I was
>> under the impression that it was happening because the SQL statement
>> is first prepared, and then executed (each of which cause a log
>> entry). It's not critical or anything, but it would be nice if this
>> could be fixed at some point.
>>
>> -harryh
>>
>> On Oct 13, 10:28 am, Derek Chen-Becker wrote:
>> > I'm not sure how that could be getting logged twice, especially since
>> it's
>> > the exact same ResultSet being returned. When I tested this on my local
>> app
>> > (against both PG and MySQL) I didn't get this behavior, but I'll try
>> pulling
>> > from master and testing again just in case something changed.
>> >
>> > Derek
>> >
>> > On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen > >wrote:
>> >
>> >
>> >
>> > > Hi,
>> >
>> > > Just wanted to update to the new db logging by adding the following to
>> > > boot:
>> >
>> > > DB.addLogFunc {
>> > > case (query:DBLog, time) => {
>> > >LogBoot.loggerByName("query").info(">>> All queries took " +
>> time +
>> > > "ms: ")
>> > >query.statementEntries.foreach({ case DBLogEntry(stmt,
>> duration) =>
>> > > LogBoot.loggerByName("query").info(""+stmt + " took " + duration +
>> > > "ms")})
>> > >LogBoot.loggerByName("query").info("<<< End queries")
>> > > }
>> > >}
>> >
>> > > But it seems all executed statements are logged twice. I have this
>> > > snippet:
>> >
>> > > def currentUser(xhtml: Group): NodeSeq =
>> > > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + " "
>> +
>> > > user.lastName))
>> >
>> > > This logs:
>> >
>> > > 14:46:09.068 [tp-1029120287-4] INFO query
>>-
>> > > >>> All queries took 5ms:
>> > > 14:46:09.068 [tp-1029120287-4] INFO query
>>-
>> > > Exec query "SELECT users.id, users.firstname, users.lastname,
>> > > users.email, users.locale, users.timezone, users.password_pw,
>> > > users.password_slt, users.account_id, users.superuser, users.uniqueid,
>> > > users.validated FROM users WHERE id = 2 (scale -5)" :
>> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>-
>> > > <<< End queries
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>-
>> > > >>> All queries took 8ms:
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>>-
>> > > Exec query "SELECT users.id, users.firstname, users.lastname,
>> > > users.email, users.locale, users.timezone, users.password_pw,
>> > > users.password_slt, users.account_id, users.superuser, users.uniqueid,
>> > > users.validated FROM users WHERE id = 2 (scale -5)" :
>> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
>> > > 14:46:09.069 [tp-1029120287-4] INFO query
>> > > - <<< End queries
>> >
>> > > Note the same resultset. The postgres logs also shows that only a
>> single
>> > > statement is executed
>> >
>> > > So, what did I miss?
>> >
>> > > /Jeppe
>>
>>
>
> >
>
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
"Lift" group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---
[Lift] Re: DB logging logs statements twice?
OK, I'm seeing the same thing here. I'll open an issue and work on it.
Derek
On Tue, Oct 13, 2009 at 10:07 AM, harryh wrote:
>
> I'm also seeing this double logging behavior (using PostgreSQL. I was
> under the impression that it was happening because the SQL statement
> is first prepared, and then executed (each of which cause a log
> entry). It's not critical or anything, but it would be nice if this
> could be fixed at some point.
>
> -harryh
>
> On Oct 13, 10:28 am, Derek Chen-Becker wrote:
> > I'm not sure how that could be getting logged twice, especially since
> it's
> > the exact same ResultSet being returned. When I tested this on my local
> app
> > (against both PG and MySQL) I didn't get this behavior, but I'll try
> pulling
> > from master and testing again just in case something changed.
> >
> > Derek
> >
> > On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen >wrote:
> >
> >
> >
> > > Hi,
> >
> > > Just wanted to update to the new db logging by adding the following to
> > > boot:
> >
> > > DB.addLogFunc {
> > > case (query:DBLog, time) => {
> > >LogBoot.loggerByName("query").info(">>> All queries took " +
> time +
> > > "ms: ")
> > >query.statementEntries.foreach({ case DBLogEntry(stmt, duration)
> =>
> > > LogBoot.loggerByName("query").info(""+stmt + " took " + duration +
> > > "ms")})
> > >LogBoot.loggerByName("query").info("<<< End queries")
> > > }
> > >}
> >
> > > But it seems all executed statements are logged twice. I have this
> > > snippet:
> >
> > > def currentUser(xhtml: Group): NodeSeq =
> > > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + " "
> +
> > > user.lastName))
> >
> > > This logs:
> >
> > > 14:46:09.068 [tp-1029120287-4] INFO query
>-
> > > >>> All queries took 5ms:
> > > 14:46:09.068 [tp-1029120287-4] INFO query
>-
> > > Exec query "SELECT users.id, users.firstname, users.lastname,
> > > users.email, users.locale, users.timezone, users.password_pw,
> > > users.password_slt, users.account_id, users.superuser, users.uniqueid,
> > > users.validated FROM users WHERE id = 2 (scale -5)" :
> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > <<< End queries
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > >>> All queries took 8ms:
> > > 14:46:09.069 [tp-1029120287-4] INFO query
>-
> > > Exec query "SELECT users.id, users.firstname, users.lastname,
> > > users.email, users.locale, users.timezone, users.password_pw,
> > > users.password_slt, users.account_id, users.superuser, users.uniqueid,
> > > users.validated FROM users WHERE id = 2 (scale -5)" :
> > > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > > 14:46:09.069 [tp-1029120287-4] INFO query
> > > - <<< End queries
> >
> > > Note the same resultset. The postgres logs also shows that only a
> single
> > > statement is executed
> >
> > > So, what did I miss?
> >
> > > /Jeppe
> >
>
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
"Lift" group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---
[Lift] Re: DB logging logs statements twice?
I'm also seeing this double logging behavior (using PostgreSQL. I was
under the impression that it was happening because the SQL statement
is first prepared, and then executed (each of which cause a log
entry). It's not critical or anything, but it would be nice if this
could be fixed at some point.
-harryh
On Oct 13, 10:28 am, Derek Chen-Becker wrote:
> I'm not sure how that could be getting logged twice, especially since it's
> the exact same ResultSet being returned. When I tested this on my local app
> (against both PG and MySQL) I didn't get this behavior, but I'll try pulling
> from master and testing again just in case something changed.
>
> Derek
>
> On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen wrote:
>
>
>
> > Hi,
>
> > Just wanted to update to the new db logging by adding the following to
> > boot:
>
> > DB.addLogFunc {
> > case (query:DBLog, time) => {
> > LogBoot.loggerByName("query").info(">>> All queries took " + time +
> > "ms: ")
> > query.statementEntries.foreach({ case DBLogEntry(stmt, duration) =>
> > LogBoot.loggerByName("query").info(" "+stmt + " took " + duration +
> > "ms")})
> > LogBoot.loggerByName("query").info("<<< End queries")
> > }
> > }
>
> > But it seems all executed statements are logged twice. I have this
> > snippet:
>
> > def currentUser(xhtml: Group): NodeSeq =
> > Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + " " +
> > user.lastName))
>
> > This logs:
>
> > 14:46:09.068 [tp-1029120287-4] INFO query -
> > >>> All queries took 5ms:
> > 14:46:09.068 [tp-1029120287-4] INFO query -
> > Exec query "SELECT users.id, users.firstname, users.lastname,
> > users.email, users.locale, users.timezone, users.password_pw,
> > users.password_slt, users.account_id, users.superuser, users.uniqueid,
> > users.validated FROM users WHERE id = 2 (scale -5)" :
> > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > 14:46:09.069 [tp-1029120287-4] INFO query -
> > <<< End queries
> > 14:46:09.069 [tp-1029120287-4] INFO query -
> > >>> All queries took 8ms:
> > 14:46:09.069 [tp-1029120287-4] INFO query -
> > Exec query "SELECT users.id, users.firstname, users.lastname,
> > users.email, users.locale, users.timezone, users.password_pw,
> > users.password_slt, users.account_id, users.superuser, users.uniqueid,
> > users.validated FROM users WHERE id = 2 (scale -5)" :
> > org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> > 14:46:09.069 [tp-1029120287-4] INFO query
> > - <<< End queries
>
> > Note the same resultset. The postgres logs also shows that only a single
> > statement is executed
>
> > So, what did I miss?
>
> > /Jeppe
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
"Lift" group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---
[Lift] Re: DB logging logs statements twice?
I'm not sure how that could be getting logged twice, especially since it's
the exact same ResultSet being returned. When I tested this on my local app
(against both PG and MySQL) I didn't get this behavior, but I'll try pulling
from master and testing again just in case something changed.
Derek
On Tue, Oct 13, 2009 at 6:56 AM, Jeppe Nejsum Madsen wrote:
>
> Hi,
>
> Just wanted to update to the new db logging by adding the following to
> boot:
>
> DB.addLogFunc {
> case (query:DBLog, time) => {
>LogBoot.loggerByName("query").info(">>> All queries took " + time +
> "ms: ")
>query.statementEntries.foreach({ case DBLogEntry(stmt, duration) =>
> LogBoot.loggerByName("query").info(""+stmt + " took " + duration +
> "ms")})
>LogBoot.loggerByName("query").info("<<< End queries")
> }
>}
>
> But it seems all executed statements are logged twice. I have this
> snippet:
>
> def currentUser(xhtml: Group): NodeSeq =
> Text(User.currentUser.dmap(S.?("Anonym"))(user => user.firstName + " " +
> user.lastName))
>
> This logs:
>
>
> 14:46:09.068 [tp-1029120287-4] INFO query-
> >>> All queries took 5ms:
> 14:46:09.068 [tp-1029120287-4] INFO query-
> Exec query "SELECT users.id, users.firstname, users.lastname,
> users.email, users.locale, users.timezone, users.password_pw,
> users.password_slt, users.account_id, users.superuser, users.uniqueid,
> users.validated FROM users WHERE id = 2 (scale -5)" :
> org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> 14:46:09.069 [tp-1029120287-4] INFO query-
> <<< End queries
> 14:46:09.069 [tp-1029120287-4] INFO query-
> >>> All queries took 8ms:
> 14:46:09.069 [tp-1029120287-4] INFO query-
> Exec query "SELECT users.id, users.firstname, users.lastname,
> users.email, users.locale, users.timezone, users.password_pw,
> users.password_slt, users.account_id, users.superuser, users.uniqueid,
> users.validated FROM users WHERE id = 2 (scale -5)" :
> org.postgresql.jdbc4.jdbc4result...@77f31432 took 4ms
> 14:46:09.069 [tp-1029120287-4] INFO query
> - <<< End queries
>
> Note the same resultset. The postgres logs also shows that only a single
> statement is executed
>
> So, what did I miss?
>
> /Jeppe
>
> >
>
--~--~-~--~~~---~--~~
You received this message because you are subscribed to the Google Groups
"Lift" group.
To post to this group, send email to liftweb@googlegroups.com
To unsubscribe from this group, send email to
liftweb+unsubscr...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/liftweb?hl=en
-~--~~~~--~~--~--~---
