You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@cayenne.apache.org by "Andrus Adamchik (Jira)" <ji...@apache.org> on 2026/05/30 20:59:00 UTC
[jira] [Updated] (CAY-2912) Compact SQL logger
[ 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 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. 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}
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).
_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. 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 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. 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}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)