[
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).
_Note that we do have a "compact" logger implemented per CAY-2485 which_
* _It is parses every piece of SQL on every query. I suspect it is slow. A
logger shouldn't be doing that_
* _It generates output like "SELECT (60 columns) FROM ..."_ _so hiding the
interesting parts of the query_
* _It still displays a multi-line logs_
* _Parameters logging is still sparse_
* _TX boundaries are not logged under any circumstances_
_So I am trying to rethink the approach into something more compact by default,
but also more performant and configurable._
h2. SELECT
h3. Current
{noformat}
INFO o.a.c.l.JdbcEventLogger --- transaction started.
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.
INFO o.a.c.l.JdbcEventLogger +++ transaction committed.
{noformat}
h3. New default
Single line, no query timer, no tx boundaries, terse params
{noformat}
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
bind:[user_id:15] selected:1
{noformat}
h3. New default with DEBUG on
Same as default, but adds tx boundaries
{noformat}
DEBUG cayenne-sql started tx
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
bind:[user_id:15] selected:1
DEBUG cayenne-sql committed tx
{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 trucation 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
{noformat}
h3. New default with DEBUG on
Same as default, but adds tx boundaries
{noformat}
DEBUG cayenne-sql started tx
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) bind:[[id:3
name:'n3']..3..[id:2 name:'n2']] updated:5
DEBUG cayenne-sql committed tx
{noformat}
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 or less verbose (less verbose by default). So...
h2. SELECT
h3. Current
{noformat}
INFO o.a.c.l.JdbcEventLogger --- transaction started.
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.
INFO o.a.c.l.JdbcEventLogger +++ transaction committed.
{noformat}
h3. New default
Single line, no query timer, no tx boundaries, terse params
{noformat}
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
bind:[user_id:15] selected:1
{noformat}
h3. New default with DEBUG on
Same as default, but adds tx boundaries
{noformat}
DEBUG cayenne-sql started tx
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
bind:[user_id:15] selected:1
DEBUG cayenne-sql committed tx
{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 trucation 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
{noformat}
h3. New default with DEBUG on
Same as default, but adds tx boundaries
{noformat}
DEBUG cayenne-sql started tx
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) bind:[[id:3
name:'n3']..3..[id:2 name:'n2']] updated:5
DEBUG cayenne-sql committed tx
{noformat}
> 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-M2
>
>
> 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).
> _Note that we do have a "compact" logger implemented per CAY-2485 which_
> * _It is parses every piece of SQL on every query. I suspect it is slow. A
> logger shouldn't be doing that_
> * _It generates output like "SELECT (60 columns) FROM ..."_ _so hiding the
> interesting parts of the query_
> * _It still displays a multi-line logs_
> * _Parameters logging is still sparse_
> * _TX boundaries are not logged under any circumstances_
> _So I am trying to rethink the approach into something more compact by
> default, but also more performant and configurable._
> h2. SELECT
> h3. Current
> {noformat}
> INFO o.a.c.l.JdbcEventLogger --- transaction started.
> 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.
> INFO o.a.c.l.JdbcEventLogger +++ transaction committed.
> {noformat}
> h3. New default
> Single line, no query timer, no tx boundaries, terse params
> {noformat}
> INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
> bind:[user_id:15] selected:1
> {noformat}
> h3. New default with DEBUG on
> Same as default, but adds tx boundaries
> {noformat}
> DEBUG cayenne-sql started tx
> INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
> bind:[user_id:15] selected:1
> DEBUG cayenne-sql committed tx
> {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 trucation 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
> {noformat}
> h3. New default with DEBUG on
> Same as default, but adds tx boundaries
> {noformat}
> DEBUG cayenne-sql started tx
> INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) bind:[[id:3
> name:'n3']..3..[id:2 name:'n2']] updated:5
> DEBUG cayenne-sql committed tx
> {noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
