This is an automated email from the ASF dual-hosted git repository. asf-gitbox-commits pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/cayenne.git
commit 5ea1eae1425afa669c0fa3e44be1f79b13959b52 Author: Andrus Adamchik <[email protected]> AuthorDate: Sat Jul 4 18:20:46 2026 -0400 CAY-2912 Compact SQL logger adding a timer adding error log --- .../org/apache/cayenne/access/LoggingObserver.java | 21 +++++-- .../java/org/apache/cayenne/log/NoopSqlLogger.java | 9 ++- .../org/apache/cayenne/log/Slf4jSqlLogger.java | 38 ++++++++++--- .../java/org/apache/cayenne/log/SqlLogger.java | 34 ++++++++--- .../apache/cayenne/access/LoggingObserverTest.java | 66 +++++++++++++++++++++- .../org/apache/cayenne/log/Slf4jSqlLoggerTest.java | 12 ++++ 6 files changed, 156 insertions(+), 24 deletions(-) diff --git a/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java b/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java index 2168ecce1..04feb4793 100644 --- a/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java +++ b/cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java @@ -47,6 +47,7 @@ class LoggingObserver implements OperationObserver { private boolean headerEmitted; private boolean batchHasUpdate; private int batchUpdateSum; + private long startNanos; // lazily allocated on the first nextGeneratedRows call, since most statements produce no generated keys private List<Map<String, ?>> generatedKeys; @@ -60,7 +61,7 @@ class LoggingObserver implements OperationObserver { // single "updated:N" line once the batch is done, i.e. at the next statement or on success. private void flushPendingBatchUpdate() { if (!headerEmitted && batchHasUpdate && current != null) { - logger.logUpdate(current, batchUpdateSum, generatedKeys != null ? generatedKeys : List.of()); + logger.logUpdate(current, batchUpdateSum, generatedKeys != null ? generatedKeys : List.of(), elapsedMillis()); headerEmitted = true; } } @@ -69,7 +70,7 @@ class LoggingObserver implements OperationObserver { if (headerEmitted) { logger.logAlsoSelect(rowCount); } else { - logger.logSelect(current, rowCount); + logger.logSelect(current, rowCount, elapsedMillis()); headerEmitted = true; } } @@ -78,11 +79,15 @@ class LoggingObserver implements OperationObserver { if (headerEmitted) { logger.logAlsoUpdate(rowCount); } else { - logger.logUpdate(current, rowCount, generatedKeys != null ? generatedKeys : List.of()); + logger.logUpdate(current, rowCount, generatedKeys != null ? generatedKeys : List.of(), elapsedMillis()); headerEmitted = true; } } + private long elapsedMillis() { + return (System.nanoTime() - startNanos) / 1_000_000; + } + private static int sum(int[] counts) { int total = 0; for (int c : counts) { @@ -109,6 +114,7 @@ class LoggingObserver implements OperationObserver { this.batchHasUpdate = false; this.batchUpdateSum = 0; this.generatedKeys = null; + this.startNanos = System.nanoTime(); delegate.nextStatement(query, statement); } @@ -169,6 +175,13 @@ class LoggingObserver implements OperationObserver { @Override public void nextQueryException(Query query, Exception ex) { + // if a statement was in progress, emit an immediate ERROR line identifying the SQL that failed, then clear + // it so the trailing onSuccess() (still called by DataNode after a failed query) won't re-log it as a + // pending batch update + if (current != null) { + logger.logQueryError(current, ex, elapsedMillis()); + current = null; + } delegate.nextQueryException(query, ex); } @@ -224,7 +237,7 @@ class LoggingObserver implements OperationObserver { @Override public void close() { delegate.close(); - logger.logSelect(statement, count); + logger.logSelect(statement, count, elapsedMillis()); } @Override diff --git a/cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java index 248842d96..a72eb0420 100644 --- a/cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java +++ b/cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java @@ -47,11 +47,16 @@ public class NoopSqlLogger implements SqlLogger { } @Override - public void logSelect(TranslatedStatement statement, int rowCount) { + public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) { } @Override - public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys) { + public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys, + long durationMillis) { + } + + @Override + public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) { } @Override diff --git a/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java index c482eabe2..5a44635c8 100644 --- a/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java +++ b/cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java @@ -51,12 +51,17 @@ public class Slf4jSqlLogger implements SqlLogger { } @Override - public void logSelect(TranslatedStatement statement, int rowCount) { - logStatement(statement, "selected:", rowCount); + public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) { + if (LOGGER.isInfoEnabled()) { + StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "selected:", rowCount)); + appendDuration(buffer, durationMillis); + LOGGER.info(buffer.toString()); + } } @Override - public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys) { + public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys, + long durationMillis) { if (LOGGER.isInfoEnabled()) { StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "updated:", rowCount)); if (generatedKeys != null && !generatedKeys.isEmpty()) { @@ -66,23 +71,42 @@ public class Slf4jSqlLogger implements SqlLogger { } buffer.append(']'); } + appendDuration(buffer, durationMillis); LOGGER.info(buffer.toString()); } } - protected void logStatement(TranslatedStatement statement, String resultLabel, int rowCount) { - if (LOGGER.isInfoEnabled()) { - LOGGER.info(buildStatementLine(statement, resultLabel, rowCount)); + @Override + public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) { + if (LOGGER.isErrorEnabled()) { + LOGGER.error(buildErrorLine(statement, error, durationMillis)); } } protected String buildStatementLine(TranslatedStatement statement, String resultLabel, int rowCount) { + StringBuilder buffer = buildSqlAndBindings(statement); + return buffer.append('[').append(resultLabel).append(rowCount).append(']').toString(); + } + + protected String buildErrorLine(TranslatedStatement statement, Throwable error, long durationMillis) { + StringBuilder buffer = buildSqlAndBindings(statement); + buffer.append("[time_ms:").append(durationMillis).append(']'); + buffer.append(" [*** error: ").append(error != null ? error.getMessage() : null).append(']'); + return buffer.toString(); + } + + // builds "SQL [bind:[...]] " with a guaranteed trailing space, ready for a result or error suffix + private StringBuilder buildSqlAndBindings(TranslatedStatement statement) { StringBuilder buffer = new StringBuilder(statement.sql()).append(' '); SqlBindingRenderer.appendBindings(buffer, statement, batchRowThreshold); if (buffer.charAt(buffer.length() - 1) != ' ') { buffer.append(' '); } - return buffer.append('[').append(resultLabel).append(rowCount).append(']').toString(); + return buffer; + } + + private static void appendDuration(StringBuilder buffer, long durationMillis) { + buffer.append(" [time_ms:").append(durationMillis).append(']'); } @Override diff --git a/cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java b/cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java index 91120a750..d0eb08c33 100644 --- a/cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java +++ b/cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java @@ -38,22 +38,38 @@ public interface SqlLogger { boolean isEnabled(); /** - * Logs the main line for a statement that returned a result set: SQL + {@code bind:[...]} + {@code selected:N}. + * Logs the main line for a statement that returned a result set: SQL + {@code bind:[...]} + {@code selected:N}, + * followed by a trailing {@code time_ms:N} block with the statement's execution time. * - * @param statement the translated statement carrying SQL and bindings - * @param rowCount the number of selected rows + * @param statement the translated statement carrying SQL and bindings + * @param rowCount the number of selected rows + * @param durationMillis the statement's execution time in milliseconds */ - void logSelect(TranslatedStatement statement, int rowCount); + void logSelect(TranslatedStatement statement, int rowCount, long durationMillis); /** * Logs the main line for a statement that performed an update: SQL + {@code bind:[...]} + {@code updated:N}, - * optionally followed by a {@code generated:[...]} block listing any database-generated keys. + * optionally followed by a {@code generated:[...]} block listing any database-generated keys, and a trailing + * {@code time_ms:N} block with the statement's execution time. * - * @param statement the translated statement carrying SQL and bindings - * @param rowCount the number of updated rows - * @param generatedKeys the database-generated keys of the inserted rows, or an empty list if none + * @param statement the translated statement carrying SQL and bindings + * @param rowCount the number of updated rows + * @param generatedKeys the database-generated keys of the inserted rows, or an empty list if none + * @param durationMillis the statement's execution time in milliseconds */ - void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys); + void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys, + long durationMillis); + + /** + * Logs, at the ERROR level, the statement that was in progress when a query exception occurred: + * SQL + {@code bind:[...]} + the error message, followed by a trailing {@code time_ms:N} block with the time + * elapsed until the failure. + * + * @param statement the translated statement carrying SQL and bindings + * @param error the exception thrown while executing the statement + * @param durationMillis the time in milliseconds elapsed until the failure + */ + void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis); /** * Logs a select count continuation line for the statement whose header was already logged. diff --git a/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java b/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java index 9b7b50491..9358eb794 100644 --- a/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java +++ b/cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java @@ -37,6 +37,7 @@ import java.util.Map; import static java.util.Arrays.asList; import static org.junit.jupiter.api.Assertions.assertEquals; +import static org.junit.jupiter.api.Assertions.assertTrue; import static org.mockito.Mockito.mock; public class LoggingObserverTest { @@ -62,13 +63,19 @@ public class LoggingObserverTest { return true; } + // captured durations are non-deterministic, so they are asserted separately from the result strings + final List<Long> durations = new ArrayList<>(); + @Override - public void logSelect(TranslatedStatement statement, int rowCount) { + public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) { + durations.add(durationMillis); calls.add("selected:" + rowCount); } @Override - public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys) { + public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys, + long durationMillis) { + durations.add(durationMillis); StringBuilder buffer = new StringBuilder("updated:").append(rowCount); for (Map<String, ?> keys : generatedKeys) { keys.forEach((name, value) -> buffer.append(" generated:").append(name).append('=').append(value)); @@ -76,6 +83,12 @@ public class LoggingObserverTest { calls.add(buffer.toString()); } + @Override + public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) { + durations.add(durationMillis); + calls.add("error:" + error.getMessage()); + } + @Override public void logAlsoSelect(int rowCount) { calls.add("also selected:" + rowCount); @@ -194,4 +207,53 @@ public class LoggingObserverTest { assertEquals(List.of("updated:2", "updated:3"), logger.calls); } + + @Test + public void queryExceptionLogsErrorForCurrentStatement() { + CapturingLogger logger = new CapturingLogger(); + LoggingObserver observer = observer(logger); + + observer.nextStatement(null, select()); + observer.nextQueryException(null, new RuntimeException("boom")); + + assertEquals(List.of("error:boom"), logger.calls); + } + + @Test + public void queryExceptionWithoutCurrentStatementLogsNothing() { + CapturingLogger logger = new CapturingLogger(); + LoggingObserver observer = observer(logger); + + observer.nextQueryException(null, new RuntimeException("boom")); + + assertEquals(List.of(), logger.calls); + } + + @Test + public void failedBatchNotReloggedOnTrailingSuccess() { + // DataNode still calls onSuccess() after a failed query - the pending batch update must not be flushed on + // top of the error line + CapturingLogger logger = new CapturingLogger(); + LoggingObserver observer = observer(logger); + + observer.nextStatement(null, batch()); + observer.nextCount(null, 1); + observer.nextQueryException(null, new RuntimeException("boom")); + observer.onSuccess(); + + assertEquals(List.of("error:boom"), logger.calls); + } + + @Test + public void everyLoggedLineCarriesNonNegativeDuration() { + CapturingLogger logger = new CapturingLogger(); + LoggingObserver observer = observer(logger); + + observer.nextStatement(null, select()); + observer.nextRows(null, asList(new Object(), new Object())); + observer.onSuccess(); + + assertEquals(1, logger.durations.size()); + assertTrue(logger.durations.get(0) >= 0); + } } diff --git a/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java b/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java index ae43b3e2d..337edb1b9 100644 --- a/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java +++ b/cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java @@ -80,6 +80,18 @@ public class Slf4jSqlLoggerTest { logger.buildStatementLine(select, "selected:", 1)); } + @Test + public void errorLineCarriesBindingsMessageAndDuration() { + TranslatedSelect select = new TranslatedSelect( + "SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?", + new PSParameter<?>[]{ps("user_id", 15)}, + new RSColumn[0], false, false); + + assertEquals("SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? [bind:[user_id:15]] " + + "[time_ms:1000] [*** error: bad column]", + logger.buildErrorLine(select, new RuntimeException("bad column"), 1000)); + } + @Test public void selectLineWithoutBindings() { TranslatedSelect select = new TranslatedSelect(
