[
https://issues.apache.org/jira/browse/CAY-2912?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrus Adamchik updated CAY-2912:
---------------------------------
Description:
Our good old JdbcEventLogger provides a bunch of good information about each
query, but is also very verbose and splits each query into multiple log lines.
This leads to problems at scale - very large log files and the need to locate
and aggregate multiple lines for a unified view. Let's switch to a more terse
version of the logger, with a user-configurable option to make it more verbose
or less verbose (less by default).
h2. SELECT
h3. Current
_Note that in 5.0, we no longer wrap selects in transactions, so this saves
some logging too_
{noformat}
INFO o.a.c.l.JdbcEventLogger SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
[bind: 1->user_id:15]
INFO o.a.c.l.JdbcEventLogger === returned 1 row. - took 1 ms.{noformat}
h3. New default
Single line, no query timer, terse params
{noformat}
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? |
bind[user_id:15] selected:1 time_ms:1{noformat}
h2. UPDATE
h3. Current
{noformat}
INFO o.a.c.l.JdbcEventLogger --- transaction started.
INFO o.a.c.l.JdbcEventLogger INSERT INTO table1(id, name) VALUES(?, ?)
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:3, 2->name:'n3']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:1, 2->name:'n1']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:5, 2->name:'n5']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:4, 2->name:'n4']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:2, 2->name:'n2']
INFO o.a.c.l.JdbcEventLogger === updated 5 rows.
INFO o.a.c.l.JdbcEventLogger +++ transaction committed.
{noformat}
h3. New default
Single line, no query timer, no tx boundaries, terse params, truncate long
batches. Batch param truncation will be controlled by a config setting
{noformat}
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) |
bind:[id:3,name:'n3']..3..[id:2,name:'n2'] updated:5 time_ms:11{noformat}
h3. New default with DEBUG on
Same as default, but adds tx boundaries
{noformat}
DEBUG cayenne-sql tx started
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) |
bind:[id:3,name:'n3']..3..[id:2,name:'n2'] updated:5 time_ms:11
DEBUG cayenne-sql tx committed{noformat}
h2. MIXED
A mix of select and update operations is a tricky one. I guess we keep it
multi-line, replacing the query and the bindings with "also ... "
{noformat}
INFO cayenne-sql call my_proc(?, ?) | bind:[id:3 name:'n3']..3..[id:2
name:'n2'] selected:5 time_ms:11
INFO cayenne-sql also updated:10
INFO cayenne-sql also selected:20
INFO cayenne-sql also updated:30{noformat}
h2. On Error
{noformat}
ERROR cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) |
bind:[id:3,name:'n3']..3..[id:2,name:'n2'] time_ms:11 error: ....{noformat}
h2. Get rid of the Legacy "Compact" Logger
_We do have a "compact" logger implemented per CAY-2485 that_
* _parses every piece of SQL on every query. For a typical query it does 1
Pattern.match(..), 1 toUpperCase(), 2 "indexOf(..)" and 1 "split"!! This is
gotta be slow. A logger shouldn't be doing that_
* _generates output like "SELECT (60 columns) FROM ..."_ _so hiding the
interesting parts of the query_
* _still displays multi-line logs_
* _Parameters logging is still sparse_
* _TX boundaries are not logged under any circumstances_
_It is not a good approach and should be removed in favor of what we are doing
per this task_
h2. Get rid of the Legacy "Format" Logger
There's a {color:#000000}FormattedSlf4jJdbcEventLogger that makes a (fairly
weak) attempt at SQL statement wrapping. As a part of this task, it will have
to go away. Perhaps at some point we can simply add a "fold SQL" flag to the
main new logger. Or even better - we can add it to the SQL translators that
internally keep a syntax tree and can do a really nice folding.{color}
was:
Our good old JdbcEventLogger provides a bunch of good information about each
query, but is also very verbose and splits each query into multiple log lines.
This leads to problems at scale - very large log files and the need to locate
and aggregate multiple lines for a unified view. Let's switch to a more terse
version of the logger, with a user-configurable option to make it more verbose
or less verbose (less by default).
h2. SELECT
h3. Current
_Note that in 5.0, we no longer wrap selects in transactions, so this saves
some logging too_
{noformat}
INFO o.a.c.l.JdbcEventLogger SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
[bind: 1->user_id:15]
INFO o.a.c.l.JdbcEventLogger === returned 1 row. - took 1 ms.{noformat}
h3. New default
Single line, no query timer, terse params
{noformat}
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
[bind[user_id:15]] [selected:1] [time_ms:1]
{noformat}
h2. UPDATE
h3. Current
{noformat}
INFO o.a.c.l.JdbcEventLogger --- transaction started.
INFO o.a.c.l.JdbcEventLogger INSERT INTO table1(id, name) VALUES(?, ?)
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:3, 2->name:'n3']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:1, 2->name:'n1']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:5, 2->name:'n5']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:4, 2->name:'n4']
INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:2, 2->name:'n2']
INFO o.a.c.l.JdbcEventLogger === updated 5 rows.
INFO o.a.c.l.JdbcEventLogger +++ transaction committed.
{noformat}
h3. New default
Single line, no query timer, no tx boundaries, terse params, truncate long
batches. Batch param truncation will be controlled by a config setting
{noformat}
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?)
[bind:[id:3,name:'n3']..3..[id:2,name:'n2']] [updated:5] [time_ms:11]{noformat}
h3. New default with DEBUG on
Same as default, but adds tx boundaries
{noformat}
DEBUG cayenne-sql tx started
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?)
[bind:[id:3,name:'n3']..3..[id:2,name:'n2']] [updated:5] [time_ms:11]
DEBUG cayenne-sql tx committed{noformat}
h2. MIXED
A mix of select and update operations is a tricky one. I guess we keep it
multi-line, replacing the query and the bindings with "also ... "
{noformat}
INFO cayenne-sql call my_proc(?, ?) [bind:[id:3 name:'n3']..3..[id:2
name:'n2']] [selected:5] [time_ms:11] INFO cayenne-sql also [updated:10]
INFO cayenne-sql also [selected:20]
INFO cayenne-sql also [updated:30]
{noformat}
h2. On Error
{noformat}
ERROR cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?)
[bind:[id:3,name:'n3']..3..[id:2,name:'n2']] [updated:5] [time_ms:11]
message{noformat}
{noformat}
ERROR cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
[bind[user_id:15]] [selected:1] [time_ms:1] message{noformat}
h2. Get rid of the Legacy "Compact" Logger
_We do have a "compact" logger implemented per CAY-2485 that_
* _parses every piece of SQL on every query. For a typical query it does 1
Pattern.match(..), 1 toUpperCase(), 2 "indexOf(..)" and 1 "split"!! This is
gotta be slow. A logger shouldn't be doing that_
* _generates output like "SELECT (60 columns) FROM ..."_ _so hiding the
interesting parts of the query_
* _still displays multi-line logs_
* _Parameters logging is still sparse_
* _TX boundaries are not logged under any circumstances_
_It is not a good approach and should be removed in favor of what we are doing
per this task_
h2. Get rid of the Legacy "Format" Logger
There's a {color:#000000}FormattedSlf4jJdbcEventLogger that makes a (fairly
weak) attempt at SQL statement wrapping. As a part of this task, it will have
to go away. Perhaps at some point we can simply add a "fold SQL" flag to the
main new logger. Or even better - we can add it to the SQL translators that
internally keep a syntax tree and can do a really nice folding.{color}
> Compact SQL logger
> ------------------
>
> Key: CAY-2912
> URL: https://issues.apache.org/jira/browse/CAY-2912
> Project: Cayenne
> Issue Type: Improvement
> Reporter: Andrus Adamchik
> Assignee: Andrus Adamchik
> Priority: Major
> Fix For: 5.0-M3
>
>
> Our good old JdbcEventLogger provides a bunch of good information about each
> query, but is also very verbose and splits each query into multiple log
> lines. This leads to problems at scale - very large log files and the need to
> locate and aggregate multiple lines for a unified view. Let's switch to a
> more terse version of the logger, with a user-configurable option to make it
> more verbose or less verbose (less by default).
> h2. SELECT
> h3. Current
> _Note that in 5.0, we no longer wrap selects in transactions, so this saves
> some logging too_
> {noformat}
> INFO o.a.c.l.JdbcEventLogger SELECT t0.id FROM my_table t0 WHERE t0.user_id =
> ? [bind: 1->user_id:15]
> INFO o.a.c.l.JdbcEventLogger === returned 1 row. - took 1 ms.{noformat}
> h3. New default
> Single line, no query timer, terse params
> {noformat}
> INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? |
> bind[user_id:15] selected:1 time_ms:1{noformat}
> h2. UPDATE
> h3. Current
> {noformat}
> INFO o.a.c.l.JdbcEventLogger --- transaction started.
> INFO o.a.c.l.JdbcEventLogger INSERT INTO table1(id, name) VALUES(?, ?)
> INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:3, 2->name:'n3']
> INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:1, 2->name:'n1']
> INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:5, 2->name:'n5']
> INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:4, 2->name:'n4']
> INFO o.a.c.l.JdbcEventLogger [batch bind: 1->id:2, 2->name:'n2']
> INFO o.a.c.l.JdbcEventLogger === updated 5 rows.
> INFO o.a.c.l.JdbcEventLogger +++ transaction committed.
> {noformat}
> h3. New default
> Single line, no query timer, no tx boundaries, terse params, truncate long
> batches. Batch param truncation will be controlled by a config setting
> {noformat}
> INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) |
> bind:[id:3,name:'n3']..3..[id:2,name:'n2'] updated:5 time_ms:11{noformat}
> h3. New default with DEBUG on
> Same as default, but adds tx boundaries
> {noformat}
> DEBUG cayenne-sql tx started
> INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) |
> bind:[id:3,name:'n3']..3..[id:2,name:'n2'] updated:5 time_ms:11
> DEBUG cayenne-sql tx committed{noformat}
> h2. MIXED
> A mix of select and update operations is a tricky one. I guess we keep it
> multi-line, replacing the query and the bindings with "also ... "
> {noformat}
> INFO cayenne-sql call my_proc(?, ?) | bind:[id:3 name:'n3']..3..[id:2
> name:'n2'] selected:5 time_ms:11
> INFO cayenne-sql also updated:10
> INFO cayenne-sql also selected:20
> INFO cayenne-sql also updated:30{noformat}
> h2. On Error
> {noformat}
> ERROR cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) |
> bind:[id:3,name:'n3']..3..[id:2,name:'n2'] time_ms:11 error: ....{noformat}
> h2. Get rid of the Legacy "Compact" Logger
> _We do have a "compact" logger implemented per CAY-2485 that_
> * _parses every piece of SQL on every query. For a typical query it does 1
> Pattern.match(..), 1 toUpperCase(), 2 "indexOf(..)" and 1 "split"!! This is
> gotta be slow. A logger shouldn't be doing that_
> * _generates output like "SELECT (60 columns) FROM ..."_ _so hiding the
> interesting parts of the query_
> * _still displays multi-line logs_
> * _Parameters logging is still sparse_
> * _TX boundaries are not logged under any circumstances_
> _It is not a good approach and should be removed in favor of what we are
> doing per this task_
> h2. Get rid of the Legacy "Format" Logger
> There's a {color:#000000}FormattedSlf4jJdbcEventLogger that makes a (fairly
> weak) attempt at SQL statement wrapping. As a part of this task, it will have
> to go away. Perhaps at some point we can simply add a "fold SQL" flag to the
> main new logger. Or even better - we can add it to the SQL translators that
> internally keep a syntax tree and can do a really nice folding.{color}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
