[
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
{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
{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. 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.
h2. Deprecate 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 deprecated in favor of what we are
doing per this task_
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. 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.
> 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
> {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
> {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. 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.
> h2. Deprecate 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 deprecated in favor of what we are
> doing per this task_
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
