[
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
{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 tx started
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
bind:[user_id:15] selected:1
DEBUG cayenne-sql tx committed{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 tx started
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) bind:[[id:3
name:'n3']..3..[id:2 name:'n2']] updated:5
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
INFO cayenne-sql also updated:10
INFO cayenne-sql also updated:20
INFO cayenne-sql also updated:30
{noformat}
h2. Legacy "Compact" Logger
_Note that 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_
_So I am trying to rethink the approach into something more compact by default,
but also more performant and configurable._
h2. Operation Observability Stack Changes
We may use this opportunity to rethink how logger callbacks are invoked.
Instead of logger being called directly from within Transaction and DataNode,
we may try to pass it from DataDomain via a combination of TransactionListener
and OperationObserver. Both will require slight API extension.
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
{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 tx started
INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
bind:[user_id:15] selected:1
DEBUG cayenne-sql tx committed{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 tx started
INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) bind:[[id:3
name:'n3']..3..[id:2 name:'n2']] updated:5
DEBUG cayenne-sql tx committed{noformat}
h2. Legacy "Compact" Logger
_Note that 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_
_So I am trying to rethink the approach into something more compact by default,
but also more performant and configurable._
h2. Operation Observability Stack Changes
We may use this opportunity to rethink how logger callbacks are invoked.
Instead of logger being called directly from within Transaction and DataNode,
we may try to pass it from DataDomain via a combination of TransactionListener
and OperationObserver. Both will require slight API extension.
> 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).
> 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 tx started
> INFO cayenne-sql SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?
> bind:[user_id:15] selected:1
> DEBUG cayenne-sql tx committed{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 tx started
> INFO cayenne-sql INSERT INTO table1(id, name) VALUES(?, ?) bind:[[id:3
> name:'n3']..3..[id:2 name:'n2']] updated:5
> 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
> INFO cayenne-sql also updated:10
> INFO cayenne-sql also updated:20
> INFO cayenne-sql also updated:30
> {noformat}
> h2. Legacy "Compact" Logger
> _Note that 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_
> _So I am trying to rethink the approach into something more compact by
> default, but also more performant and configurable._
> h2. Operation Observability Stack Changes
> We may use this opportunity to rethink how logger callbacks are invoked.
> Instead of logger being called directly from within Transaction and DataNode,
> we may try to pass it from DataDomain via a combination of
> TransactionListener and OperationObserver. Both will require slight API
> extension.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
