[jira] [Commented] (CAY-2912) Compact SQL logger

["Andrus Adamchik (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/CAY-2912?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=18093555#comment-18093555 ] 

Andrus Adamchik commented on CAY-2912:
--------------------------------------

There will be a few follow up jiras to replace things taken out of the logger:
 * queries attached to exceptions
 * operation timers

> 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 [selected: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. Exception Handling
> Previously we'd log the SQL before starting the query, and the result - after success. So if an exception occurred, you could still see the SQL that caused it. With single-line logs, you won't (only successes will be logged). This affects operation exception handling - upon exception SQL String and bindings will need to be added to the exception and become a part of its message.
> Hopefully, this won't be hard to implement based on the new TranslatedSelect/TranslatedSQL/TranslatedProcedure/TranslatedBatch classes that capture all this information. 
> 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)