Skip to content

Commit 5ea1eae

Browse files
andrusandrus
committed
CAY-2912 Compact SQL logger
adding a timer adding error log
1 parent 17d1154 commit 5ea1eae

6 files changed

Lines changed: 156 additions & 24 deletions

File tree

‎cayenne/src/main/java/org/apache/cayenne/access/LoggingObserver.java‎

Lines changed: 17 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -47,6 +47,7 @@ class LoggingObserver implements OperationObserver {
4747
private boolean headerEmitted;
4848
private boolean batchHasUpdate;
4949
private int batchUpdateSum;
50+
private long startNanos;
5051

5152
// lazily allocated on the first nextGeneratedRows call, since most statements produce no generated keys
5253
private List<Map<String, ?>> generatedKeys;
@@ -60,7 +61,7 @@ class LoggingObserver implements OperationObserver {
6061
// single "updated:N" line once the batch is done, i.e. at the next statement or on success.
6162
private void flushPendingBatchUpdate() {
6263
if (!headerEmitted && batchHasUpdate && current != null) {
63-
logger.logUpdate(current, batchUpdateSum, generatedKeys != null ? generatedKeys : List.of());
64+
logger.logUpdate(current, batchUpdateSum, generatedKeys != null ? generatedKeys : List.of(), elapsedMillis());
6465
headerEmitted = true;
6566
}
6667
}
@@ -69,7 +70,7 @@ private void reportSelect(int rowCount) {
6970
if (headerEmitted) {
7071
logger.logAlsoSelect(rowCount);
7172
} else {
72-
logger.logSelect(current, rowCount);
73+
logger.logSelect(current, rowCount, elapsedMillis());
7374
headerEmitted = true;
7475
}
7576
}
@@ -78,11 +79,15 @@ private void reportUpdate(int rowCount) {
7879
if (headerEmitted) {
7980
logger.logAlsoUpdate(rowCount);
8081
} else {
81-
logger.logUpdate(current, rowCount, generatedKeys != null ? generatedKeys : List.of());
82+
logger.logUpdate(current, rowCount, generatedKeys != null ? generatedKeys : List.of(), elapsedMillis());
8283
headerEmitted = true;
8384
}
8485
}
8586

87+
private long elapsedMillis() {
88+
return (System.nanoTime() - startNanos) / 1_000_000;
89+
}
90+
8691
private static int sum(int[] counts) {
8792
int total = 0;
8893
for (int c : counts) {
@@ -109,6 +114,7 @@ public void nextStatement(Query query, TranslatedStatement statement) {
109114
this.batchHasUpdate = false;
110115
this.batchUpdateSum = 0;
111116
this.generatedKeys = null;
117+
this.startNanos = System.nanoTime();
112118
delegate.nextStatement(query, statement);
113119
}
114120

@@ -169,6 +175,13 @@ public void nextGeneratedRows(Query query, List<DataRow> keys, List<ObjectId> id
169175

170176
@Override
171177
public void nextQueryException(Query query, Exception ex) {
178+
// if a statement was in progress, emit an immediate ERROR line identifying the SQL that failed, then clear
179+
// it so the trailing onSuccess() (still called by DataNode after a failed query) won't re-log it as a
180+
// pending batch update
181+
if (current != null) {
182+
logger.logQueryError(current, ex, elapsedMillis());
183+
current = null;
184+
}
172185
delegate.nextQueryException(query, ex);
173186
}
174187

@@ -224,7 +237,7 @@ public void skipRow() {
224237
@Override
225238
public void close() {
226239
delegate.close();
227-
logger.logSelect(statement, count);
240+
logger.logSelect(statement, count, elapsedMillis());
228241
}
229242

230243
@Override

‎cayenne/src/main/java/org/apache/cayenne/log/NoopSqlLogger.java‎

Lines changed: 7 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -47,11 +47,16 @@ public boolean isEnabled() {
4747
}
4848

4949
@Override
50-
public void logSelect(TranslatedStatement statement, int rowCount) {
50+
public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) {
5151
}
5252

5353
@Override
54-
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys) {
54+
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys,
55+
long durationMillis) {
56+
}
57+
58+
@Override
59+
public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) {
5560
}
5661

5762
@Override

‎cayenne/src/main/java/org/apache/cayenne/log/Slf4jSqlLogger.java‎

Lines changed: 31 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -51,12 +51,17 @@ public boolean isEnabled() {
5151
}
5252

5353
@Override
54-
public void logSelect(TranslatedStatement statement, int rowCount) {
55-
logStatement(statement, "selected:", rowCount);
54+
public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) {
55+
if (LOGGER.isInfoEnabled()) {
56+
StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "selected:", rowCount));
57+
appendDuration(buffer, durationMillis);
58+
LOGGER.info(buffer.toString());
59+
}
5660
}
5761

5862
@Override
59-
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys) {
63+
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys,
64+
long durationMillis) {
6065
if (LOGGER.isInfoEnabled()) {
6166
StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "updated:", rowCount));
6267
if (generatedKeys != null && !generatedKeys.isEmpty()) {
@@ -66,23 +71,42 @@ public void logUpdate(TranslatedStatement statement, int rowCount, List<? extend
6671
}
6772
buffer.append(']');
6873
}
74+
appendDuration(buffer, durationMillis);
6975
LOGGER.info(buffer.toString());
7076
}
7177
}
7278

73-
protected void logStatement(TranslatedStatement statement, String resultLabel, int rowCount) {
74-
if (LOGGER.isInfoEnabled()) {
75-
LOGGER.info(buildStatementLine(statement, resultLabel, rowCount));
79+
@Override
80+
public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) {
81+
if (LOGGER.isErrorEnabled()) {
82+
LOGGER.error(buildErrorLine(statement, error, durationMillis));
7683
}
7784
}
7885

7986
protected String buildStatementLine(TranslatedStatement statement, String resultLabel, int rowCount) {
87+
StringBuilder buffer = buildSqlAndBindings(statement);
88+
return buffer.append('[').append(resultLabel).append(rowCount).append(']').toString();
89+
}
90+
91+
protected String buildErrorLine(TranslatedStatement statement, Throwable error, long durationMillis) {
92+
StringBuilder buffer = buildSqlAndBindings(statement);
93+
buffer.append("[time_ms:").append(durationMillis).append(']');
94+
buffer.append(" [*** error: ").append(error != null ? error.getMessage() : null).append(']');
95+
return buffer.toString();
96+
}
97+
98+
// builds "SQL [bind:[...]] " with a guaranteed trailing space, ready for a result or error suffix
99+
private StringBuilder buildSqlAndBindings(TranslatedStatement statement) {
80100
StringBuilder buffer = new StringBuilder(statement.sql()).append(' ');
81101
SqlBindingRenderer.appendBindings(buffer, statement, batchRowThreshold);
82102
if (buffer.charAt(buffer.length() - 1) != ' ') {
83103
buffer.append(' ');
84104
}
85-
return buffer.append('[').append(resultLabel).append(rowCount).append(']').toString();
105+
return buffer;
106+
}
107+
108+
private static void appendDuration(StringBuilder buffer, long durationMillis) {
109+
buffer.append(" [time_ms:").append(durationMillis).append(']');
86110
}
87111

88112
@Override

‎cayenne/src/main/java/org/apache/cayenne/log/SqlLogger.java‎

Lines changed: 25 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -38,22 +38,38 @@ public interface SqlLogger {
3838
boolean isEnabled();
3939

4040
/**
41-
* Logs the main line for a statement that returned a result set: SQL + {@code bind:[...]} + {@code selected:N}.
41+
* Logs the main line for a statement that returned a result set: SQL + {@code bind:[...]} + {@code selected:N},
42+
* followed by a trailing {@code time_ms:N} block with the statement's execution time.
4243
*
43-
* @param statement the translated statement carrying SQL and bindings
44-
* @param rowCount the number of selected rows
44+
* @param statement the translated statement carrying SQL and bindings
45+
* @param rowCount the number of selected rows
46+
* @param durationMillis the statement's execution time in milliseconds
4547
*/
46-
void logSelect(TranslatedStatement statement, int rowCount);
48+
void logSelect(TranslatedStatement statement, int rowCount, long durationMillis);
4749

4850
/**
4951
* Logs the main line for a statement that performed an update: SQL + {@code bind:[...]} + {@code updated:N},
50-
* optionally followed by a {@code generated:[...]} block listing any database-generated keys.
52+
* optionally followed by a {@code generated:[...]} block listing any database-generated keys, and a trailing
53+
* {@code time_ms:N} block with the statement's execution time.
5154
*
52-
* @param statement the translated statement carrying SQL and bindings
53-
* @param rowCount the number of updated rows
54-
* @param generatedKeys the database-generated keys of the inserted rows, or an empty list if none
55+
* @param statement the translated statement carrying SQL and bindings
56+
* @param rowCount the number of updated rows
57+
* @param generatedKeys the database-generated keys of the inserted rows, or an empty list if none
58+
* @param durationMillis the statement's execution time in milliseconds
5559
*/
56-
void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys);
60+
void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys,
61+
long durationMillis);
62+
63+
/**
64+
* Logs, at the ERROR level, the statement that was in progress when a query exception occurred:
65+
* SQL + {@code bind:[...]} + the error message, followed by a trailing {@code time_ms:N} block with the time
66+
* elapsed until the failure.
67+
*
68+
* @param statement the translated statement carrying SQL and bindings
69+
* @param error the exception thrown while executing the statement
70+
* @param durationMillis the time in milliseconds elapsed until the failure
71+
*/
72+
void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis);
5773

5874
/**
5975
* Logs a select count continuation line for the statement whose header was already logged.

‎cayenne/src/test/java/org/apache/cayenne/access/LoggingObserverTest.java‎

Lines changed: 64 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -37,6 +37,7 @@
3737

3838
import static java.util.Arrays.asList;
3939
import static org.junit.jupiter.api.Assertions.assertEquals;
40+
import static org.junit.jupiter.api.Assertions.assertTrue;
4041
import static org.mockito.Mockito.mock;
4142

4243
public class LoggingObserverTest {
@@ -62,20 +63,32 @@ public boolean isEnabled() {
6263
return true;
6364
}
6465

66+
// captured durations are non-deterministic, so they are asserted separately from the result strings
67+
final List<Long> durations = new ArrayList<>();
68+
6569
@Override
66-
public void logSelect(TranslatedStatement statement, int rowCount) {
70+
public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) {
71+
durations.add(durationMillis);
6772
calls.add("selected:" + rowCount);
6873
}
6974

7075
@Override
71-
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys) {
76+
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys,
77+
long durationMillis) {
78+
durations.add(durationMillis);
7279
StringBuilder buffer = new StringBuilder("updated:").append(rowCount);
7380
for (Map<String, ?> keys : generatedKeys) {
7481
keys.forEach((name, value) -> buffer.append(" generated:").append(name).append('=').append(value));
7582
}
7683
calls.add(buffer.toString());
7784
}
7885

86+
@Override
87+
public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) {
88+
durations.add(durationMillis);
89+
calls.add("error:" + error.getMessage());
90+
}
91+
7992
@Override
8093
public void logAlsoSelect(int rowCount) {
8194
calls.add("also selected:" + rowCount);
@@ -194,4 +207,53 @@ public void newStatementFlushesPreviousBatch() {
194207

195208
assertEquals(List.of("updated:2", "updated:3"), logger.calls);
196209
}
210+
211+
@Test
212+
public void queryExceptionLogsErrorForCurrentStatement() {
213+
CapturingLogger logger = new CapturingLogger();
214+
LoggingObserver observer = observer(logger);
215+
216+
observer.nextStatement(null, select());
217+
observer.nextQueryException(null, new RuntimeException("boom"));
218+
219+
assertEquals(List.of("error:boom"), logger.calls);
220+
}
221+
222+
@Test
223+
public void queryExceptionWithoutCurrentStatementLogsNothing() {
224+
CapturingLogger logger = new CapturingLogger();
225+
LoggingObserver observer = observer(logger);
226+
227+
observer.nextQueryException(null, new RuntimeException("boom"));
228+
229+
assertEquals(List.of(), logger.calls);
230+
}
231+
232+
@Test
233+
public void failedBatchNotReloggedOnTrailingSuccess() {
234+
// DataNode still calls onSuccess() after a failed query - the pending batch update must not be flushed on
235+
// top of the error line
236+
CapturingLogger logger = new CapturingLogger();
237+
LoggingObserver observer = observer(logger);
238+
239+
observer.nextStatement(null, batch());
240+
observer.nextCount(null, 1);
241+
observer.nextQueryException(null, new RuntimeException("boom"));
242+
observer.onSuccess();
243+
244+
assertEquals(List.of("error:boom"), logger.calls);
245+
}
246+
247+
@Test
248+
public void everyLoggedLineCarriesNonNegativeDuration() {
249+
CapturingLogger logger = new CapturingLogger();
250+
LoggingObserver observer = observer(logger);
251+
252+
observer.nextStatement(null, select());
253+
observer.nextRows(null, asList(new Object(), new Object()));
254+
observer.onSuccess();
255+
256+
assertEquals(1, logger.durations.size());
257+
assertTrue(logger.durations.get(0) >= 0);
258+
}
197259
}

‎cayenne/src/test/java/org/apache/cayenne/log/Slf4jSqlLoggerTest.java‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -80,6 +80,18 @@ public void selectLineWithSingleBinding() {
8080
logger.buildStatementLine(select, "selected:", 1));
8181
}
8282

83+
@Test
84+
public void errorLineCarriesBindingsMessageAndDuration() {
85+
TranslatedSelect select = new TranslatedSelect(
86+
"SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?",
87+
new PSParameter<?>[]{ps("user_id", 15)},
88+
new RSColumn[0], false, false);
89+
90+
assertEquals("SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? [bind:[user_id:15]] "
91+
+ "[time_ms:1000] [*** error: bad column]",
92+
logger.buildErrorLine(select, new RuntimeException("bad column"), 1000));
93+
}
94+
8395
@Test
8496
public void selectLineWithoutBindings() {
8597
TranslatedSelect select = new TranslatedSelect(

0 commit comments

Comments
 (0)