Skip to content

Commit c69fd67

Browse files
andrusandrus
committed
CAY-2912 Compact SQL logger
trying a new format
1 parent 5ea1eae commit c69fd67

5 files changed

Lines changed: 99 additions & 79 deletions

File tree

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

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -77,7 +77,11 @@ private void reportSelect(int rowCount) {
7777

7878
private void reportUpdate(int rowCount) {
7979
if (headerEmitted) {
80-
logger.logAlsoUpdate(rowCount);
80+
// a trailing zero update count is driver noise (e.g. a stored procedure's completion status reported
81+
// after its result set), so skip the stray "also updated:0" line
82+
if (rowCount != 0) {
83+
logger.logAlsoUpdate(rowCount);
84+
}
8185
} else {
8286
logger.logUpdate(current, rowCount, generatedKeys != null ? generatedKeys : List.of(), elapsedMillis());
8387
headerEmitted = true;

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

Lines changed: 26 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -53,8 +53,9 @@ public boolean isEnabled() {
5353
@Override
5454
public void logSelect(TranslatedStatement statement, int rowCount, long durationMillis) {
5555
if (LOGGER.isInfoEnabled()) {
56-
StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "selected:", rowCount));
57-
appendDuration(buffer, durationMillis);
56+
StringBuilder buffer = new StringBuilder();
57+
appendStatementLine(buffer, statement, "selected:", rowCount);
58+
buffer.append(" time_ms:").append(durationMillis);
5859
LOGGER.info(buffer.toString());
5960
}
6061
}
@@ -63,63 +64,61 @@ public void logSelect(TranslatedStatement statement, int rowCount, long duration
6364
public void logUpdate(TranslatedStatement statement, int rowCount, List<? extends Map<String, ?>> generatedKeys,
6465
long durationMillis) {
6566
if (LOGGER.isInfoEnabled()) {
66-
StringBuilder buffer = new StringBuilder(buildStatementLine(statement, "updated:", rowCount));
67+
StringBuilder buffer = new StringBuilder();
68+
appendStatementLine(buffer, statement, "updated:", rowCount);
6769
if (generatedKeys != null && !generatedKeys.isEmpty()) {
68-
buffer.append(" [generated:");
70+
buffer.append(" generated:");
6971
for (Map<String, ?> keys : generatedKeys) {
7072
SqlBindingRenderer.appendGeneratedKeys(buffer, keys);
7173
}
72-
buffer.append(']');
7374
}
74-
appendDuration(buffer, durationMillis);
75+
buffer.append(" time_ms:").append(durationMillis);
7576
LOGGER.info(buffer.toString());
7677
}
7778
}
7879

7980
@Override
8081
public void logQueryError(TranslatedStatement statement, Throwable error, long durationMillis) {
8182
if (LOGGER.isErrorEnabled()) {
82-
LOGGER.error(buildErrorLine(statement, error, durationMillis));
83+
StringBuilder buffer = new StringBuilder();
84+
appendErrorLine(buffer, statement, error, durationMillis);
85+
LOGGER.error(buffer.toString());
8386
}
8487
}
8588

86-
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+
void appendStatementLine(StringBuilder buffer, TranslatedStatement statement, String resultLabel, int rowCount) {
90+
appendSqlAndBindings(buffer, statement);
91+
buffer.append(' ').append(resultLabel).append(rowCount);
8992
}
9093

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();
94+
void appendErrorLine(StringBuilder buffer, TranslatedStatement statement, Throwable error, long durationMillis) {
95+
appendSqlAndBindings(buffer, statement);
96+
buffer.append(" time_ms:").append(durationMillis);
97+
buffer.append(" error: ").append(error != null ? error.getMessage() : null);
9698
}
9799

98-
// builds "SQL [bind:[...]] " with a guaranteed trailing space, ready for a result or error suffix
99-
private StringBuilder buildSqlAndBindings(TranslatedStatement statement) {
100-
StringBuilder buffer = new StringBuilder(statement.sql()).append(' ');
100+
private void appendSqlAndBindings(StringBuilder buffer, TranslatedStatement statement) {
101+
buffer.append(statement.sql()).append(" |");
102+
int lengthWithoutBindings = buffer.length();
103+
buffer.append(' ');
101104
SqlBindingRenderer.appendBindings(buffer, statement, batchRowThreshold);
102-
if (buffer.charAt(buffer.length() - 1) != ' ') {
103-
buffer.append(' ');
105+
if (buffer.length() == lengthWithoutBindings + 1) {
106+
// no bindings were rendered - drop the separator space so the next block follows "|" directly
107+
buffer.setLength(lengthWithoutBindings);
104108
}
105-
return buffer;
106-
}
107-
108-
private static void appendDuration(StringBuilder buffer, long durationMillis) {
109-
buffer.append(" [time_ms:").append(durationMillis).append(']');
110109
}
111110

112111
@Override
113112
public void logAlsoSelect(int rowCount) {
114113
if (LOGGER.isInfoEnabled()) {
115-
LOGGER.info("also [selected:{}]", rowCount);
114+
LOGGER.info("also selected:{}", rowCount);
116115
}
117116
}
118117

119118
@Override
120119
public void logAlsoUpdate(int rowCount) {
121120
if (LOGGER.isInfoEnabled()) {
122-
LOGGER.info("also [updated:{}]", rowCount);
121+
LOGGER.info("also updated:{}", rowCount);
123122
}
124123
}
125124

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

Lines changed: 8 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -33,16 +33,10 @@
3333

3434
/**
3535
* Renders the parameter bindings of a {@link TranslatedStatement} in the compact {@code bind:[...]} form used by
36-
* {@link SqlLogger} and by exception messages. Shared so that logged and thrown SQL look identical.
36+
* {@link SqlLogger}.
3737
*/
3838
class SqlBindingRenderer {
3939

40-
/**
41-
* Appends the {@code bind:[...]} fragment for the given statement to the buffer, or nothing if the statement has
42-
* no bindings. Batch bindings with more rows than {@code batchRowThreshold} are truncated to first row,
43-
* {@code ..<eliddedCount>..}, last row.
44-
*/
45-
@SuppressWarnings({"rawtypes", "unchecked"})
4640
public static void appendBindings(StringBuilder buffer, TranslatedStatement statement, int batchRowThreshold) {
4741
switch (statement) {
4842
case TranslatedSelect s -> appendParameters(buffer, s.bindings());
@@ -73,30 +67,30 @@ private static void appendParameters(StringBuilder buffer, PSParameter<?>[] bind
7367
if (bindings.length == 0) {
7468
return;
7569
}
76-
buffer.append("[bind:[");
70+
buffer.append("bind:[");
7771
for (int i = 0; i < bindings.length; i++) {
7872
if (i > 0) {
7973
buffer.append(",");
8074
}
8175
PSParameter<?> b = bindings[i];
8276
appendNamedValue(buffer, b.attribute() != null ? b.attribute().getName() : null, b.binder(), b.value());
8377
}
84-
buffer.append("]]");
78+
buffer.append("]");
8579
}
8680

8781
private static void appendCallParameters(StringBuilder buffer, CSParameter<?>[] params) {
8882
if (params.length == 0) {
8983
return;
9084
}
91-
buffer.append("[bind:[");
85+
buffer.append("bind:[");
9286
for (int i = 0; i < params.length; i++) {
9387
if (i > 0) {
9488
buffer.append(",");
9589
}
9690
CSParameter<?> b = params[i];
9791
appendNamedValue(buffer, b.param() != null ? b.param().getName() : null, b.binder(), b.value());
9892
}
99-
buffer.append("]]");
93+
buffer.append("]");
10094
}
10195

10296
private static void appendBatch(StringBuilder buffer, PSBatchParameter[] bindings, int batchRowThreshold) {
@@ -118,8 +112,8 @@ private static void appendBatch(StringBuilder buffer, PSBatchParameter[] binding
118112
}
119113

120114
// rows are delimited by their own [...] brackets, so no extra list bracket is needed: a single-row batch
121-
// reads as [bind:[...]] and a multi-row batch as [bind:[...][...]] - never a doubled [[...]]
122-
buffer.append("[bind:");
115+
// reads as bind:[...] and a multi-row batch as bind:[...][...] - never a doubled [[...]]
116+
buffer.append("bind:");
123117
if (rows > batchRowThreshold) {
124118
// show up to batchRowThreshold rows split evenly between head and tail, eliding the middle. For an odd
125119
// threshold the head gets the extra row, so head + tail == batchRowThreshold and the elided count is
@@ -138,7 +132,6 @@ private static void appendBatch(StringBuilder buffer, PSBatchParameter[] binding
138132
appendBatchRow(buffer, bindings, r);
139133
}
140134
}
141-
buffer.append(']');
142135
}
143136

144137
private static void appendBatchRow(StringBuilder buffer, PSBatchParameter[] bindings, int row) {
@@ -157,8 +150,7 @@ private static void appendBatchRowFields(StringBuilder buffer, PSBatchParameter[
157150
}
158151
}
159152

160-
@SuppressWarnings({"rawtypes", "unchecked"})
161-
private static void appendNamedValue(StringBuilder buffer, String name, ExtendedType binder, Object value) {
153+
private static void appendNamedValue(StringBuilder buffer, String name, ExtendedType<?> binder, Object value) {
162154
if (name != null) {
163155
buffer.append(name).append(':');
164156
}

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

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -160,6 +160,21 @@ public void procedureReportsExtraResultsAsAlsoLines() {
160160
assertEquals(List.of("selected:5", "also updated:10", "also updated:20"), logger.calls);
161161
}
162162

163+
@Test
164+
public void trailingZeroUpdateCountNotReportedAsAlso() {
165+
// a stored procedure reports its completion status as a 0 update count after the result set - this must not
166+
// surface as a stray "also updated:0" line
167+
CapturingLogger logger = new CapturingLogger();
168+
LoggingObserver observer = observer(logger);
169+
170+
observer.nextStatement(null, procedure());
171+
observer.nextRows(null, List.of(new Object()));
172+
observer.nextCount(null, 0);
173+
observer.onSuccess();
174+
175+
assertEquals(List.of("selected:1"), logger.calls);
176+
}
177+
163178
@Test
164179
public void emptyBatchCountDoesNotEmitStrayUpdate() {
165180
// a SQLTemplate SELECT reports its (absent) update counts via an empty nextBatchCount - must not log

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

Lines changed: 45 additions & 35 deletions
Original file line numberDiff line numberDiff line change
@@ -24,6 +24,7 @@
2424
import org.apache.cayenne.access.jdbc.RSColumn;
2525
import org.apache.cayenne.access.translator.TranslatedBatch;
2626
import org.apache.cayenne.access.translator.TranslatedSelect;
27+
import org.apache.cayenne.access.translator.TranslatedStatement;
2728
import org.apache.cayenne.configuration.Constants;
2829
import org.apache.cayenne.configuration.RuntimeProperties;
2930
import org.apache.cayenne.map.DbAttribute;
@@ -55,8 +56,16 @@ private static Slf4jSqlLogger loggerWithThreshold(int threshold) {
5556
return new Slf4jSqlLogger(props);
5657
}
5758

58-
private static PSParameter<?> ps(String name, Object value) {
59-
return new PSParameter<>(value, 1, Types.INTEGER, 0, null, new DbAttribute(name));
59+
private static String line(Slf4jSqlLogger logger, TranslatedStatement statement, String label, int count) {
60+
StringBuilder buffer = new StringBuilder();
61+
logger.appendStatementLine(buffer, statement, label, count);
62+
return buffer.toString();
63+
}
64+
65+
private static String errorLine(Slf4jSqlLogger logger, TranslatedStatement statement, Throwable error, long durationMillis) {
66+
StringBuilder buffer = new StringBuilder();
67+
logger.appendErrorLine(buffer, statement, error, durationMillis);
68+
return buffer.toString();
6069
}
6170

6271
// a single-placeholder batch whose id values are 0..rows-1, so each logged row is identifiable by its value
@@ -73,32 +82,34 @@ private static TranslatedBatch idBatch(int rows) {
7382
public void selectLineWithSingleBinding() {
7483
TranslatedSelect select = new TranslatedSelect(
7584
"SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?",
76-
new PSParameter<?>[]{ps("user_id", 15)},
85+
new PSParameter<?>[]{new PSParameter<>(15, 1, Types.INTEGER, 0, null, new DbAttribute("user_id"))},
7786
new RSColumn[0], false, false);
7887

79-
assertEquals("SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? [bind:[user_id:15]] [selected:1]",
80-
logger.buildStatementLine(select, "selected:", 1));
88+
assertEquals(
89+
"SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? | bind:[user_id:15] selected:1",
90+
line(logger, select, "selected:", 1));
8191
}
8292

8393
@Test
8494
public void errorLineCarriesBindingsMessageAndDuration() {
8595
TranslatedSelect select = new TranslatedSelect(
8696
"SELECT t0.id FROM my_table t0 WHERE t0.user_id = ?",
87-
new PSParameter<?>[]{ps("user_id", 15)},
97+
new PSParameter<?>[]{new PSParameter<>(15, 1, Types.INTEGER, 0, null, new DbAttribute("user_id"))},
8898
new RSColumn[0], false, false);
8999

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));
100+
assertEquals(
101+
"SELECT t0.id FROM my_table t0 WHERE t0.user_id = ? | bind:[user_id:15] time_ms:1000 error: bad column",
102+
errorLine(logger, select, new RuntimeException("bad column"), 1000));
93103
}
94104

95105
@Test
96106
public void selectLineWithoutBindings() {
97107
TranslatedSelect select = new TranslatedSelect(
98108
"SELECT t0.id FROM my_table t0", new PSParameter<?>[0], new RSColumn[0], false, false);
99109

100-
assertEquals("SELECT t0.id FROM my_table t0 [selected:0]",
101-
logger.buildStatementLine(select, "selected:", 0));
110+
assertEquals(
111+
"SELECT t0.id FROM my_table t0 | selected:0",
112+
line(logger, select, "selected:", 0));
102113
}
103114

104115
@Test
@@ -112,9 +123,9 @@ public void batchLineSplitsHeadAndTailAroundElision() {
112123
TranslatedBatch batch = new TranslatedBatch(
113124
"INSERT INTO table1(id, name) VALUES(?, ?)", new PSBatchParameter[]{id, name});
114125

115-
assertEquals("INSERT INTO table1(id, name) VALUES(?, ?) "
116-
+ "[bind:[id:3,name:'n3'][id:1,name:'n1']..2..[id:2,name:'n2']] [updated:5]",
117-
logger.buildStatementLine(batch, "updated:", 5));
126+
assertEquals(
127+
"INSERT INTO table1(id, name) VALUES(?, ?) | bind:[id:3,name:'n3'][id:1,name:'n1']..2..[id:2,name:'n2'] updated:5",
128+
line(logger, batch, "updated:", 5));
118129
}
119130

120131
@Test
@@ -127,58 +138,57 @@ public void singleRowBatchHasNoDoubleBrackets() {
127138
TranslatedBatch batch = new TranslatedBatch(
128139
"INSERT INTO ARTIST(ARTIST_ID, ARTIST_NAME) VALUES(?, ?)", new PSBatchParameter[]{id, name});
129140

130-
assertEquals("INSERT INTO ARTIST(ARTIST_ID, ARTIST_NAME) VALUES(?, ?) [bind:[ARTIST_ID:200,ARTIST_NAME:'Test']] [updated:1]",
131-
logger.buildStatementLine(batch, "updated:", 1));
141+
assertEquals(
142+
"INSERT INTO ARTIST(ARTIST_ID, ARTIST_NAME) VALUES(?, ?) | bind:[ARTIST_ID:200,ARTIST_NAME:'Test'] updated:1",
143+
line(logger, batch, "updated:", 1));
132144
}
133145

134146
@Test
135147
public void batchLineShowsAllRowsBelowThreshold() {
136148
PSBatchParameter id = new PSBatchParameter(
137149
new Object[]{3, 2}, 1, Types.INTEGER, 0, new DbAttribute("id"));
138150

139-
TranslatedBatch batch = new TranslatedBatch(
140-
"INSERT INTO table1(id) VALUES(?)", new PSBatchParameter[]{id});
141-
142-
assertEquals("INSERT INTO table1(id) VALUES(?) [bind:[id:3][id:2]] [updated:2]",
143-
logger.buildStatementLine(batch, "updated:", 2));
151+
TranslatedBatch batch = new TranslatedBatch("INSERT INTO table1(id) VALUES(?)", new PSBatchParameter[]{id});
152+
assertEquals("INSERT INTO table1(id) VALUES(?) | bind:[id:3][id:2] updated:2",
153+
line(logger, batch, "updated:", 2));
144154
}
145155

146156
@Test
147157
public void batchLineEvenThresholdSplitsEvenly() {
148158
// even threshold 4 -> head 2, tail 2; 10 rows -> middle 6 elided
149-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1]..6..[id:8][id:9]] [updated:10]",
150-
loggerWithThreshold(4).buildStatementLine(idBatch(10), "updated:", 10));
159+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1]..6..[id:8][id:9] updated:10",
160+
line(loggerWithThreshold(4), idBatch(10), "updated:", 10));
151161
}
152162

153163
@Test
154164
public void batchLineShowsAllRowsAtThreshold() {
155165
// exactly threshold rows -> nothing elided
156-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1][id:2][id:3]] [updated:4]",
157-
loggerWithThreshold(4).buildStatementLine(idBatch(4), "updated:", 4));
166+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1][id:2][id:3] updated:4",
167+
line(loggerWithThreshold(4), idBatch(4), "updated:", 4));
158168
}
159169

160170
@Test
161171
public void batchLineElidesExactlyOneAboveThreshold() {
162172
// one row above threshold 4 -> head 2, tail 2, a single row elided
163-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1]..1..[id:3][id:4]] [updated:5]",
164-
loggerWithThreshold(4).buildStatementLine(idBatch(5), "updated:", 5));
173+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1]..1..[id:3][id:4] updated:5",
174+
line(loggerWithThreshold(4), idBatch(5), "updated:", 5));
165175
}
166176

167177
@Test
168178
public void batchLineThresholdOfOneOrTwoClampsToTwo() {
169179
// threshold 1 and 2 both clamp to 2 -> head 1, tail 1
170-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0]..3..[id:4]] [updated:5]",
171-
loggerWithThreshold(1).buildStatementLine(idBatch(5), "updated:", 5));
172-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0]..3..[id:4]] [updated:5]",
173-
loggerWithThreshold(2).buildStatementLine(idBatch(5), "updated:", 5));
180+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0]..3..[id:4] updated:5",
181+
line(loggerWithThreshold(1), idBatch(5), "updated:", 5));
182+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0]..3..[id:4] updated:5",
183+
line(loggerWithThreshold(2), idBatch(5), "updated:", 5));
174184
}
175185

176186
@Test
177187
public void batchLineNonPositiveThresholdDisablesTruncation() {
178188
// threshold 0 or negative -> no truncation, every row logged
179-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1][id:2][id:3][id:4]] [updated:5]",
180-
loggerWithThreshold(0).buildStatementLine(idBatch(5), "updated:", 5));
181-
assertEquals("INSERT INTO t(id) VALUES(?) [bind:[id:0][id:1][id:2][id:3][id:4]] [updated:5]",
182-
loggerWithThreshold(-1).buildStatementLine(idBatch(5), "updated:", 5));
189+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1][id:2][id:3][id:4] updated:5",
190+
line(loggerWithThreshold(0), idBatch(5), "updated:", 5));
191+
assertEquals("INSERT INTO t(id) VALUES(?) | bind:[id:0][id:1][id:2][id:3][id:4] updated:5",
192+
line(loggerWithThreshold(-1), idBatch(5), "updated:", 5));
183193
}
184194
}

0 commit comments

Comments
 (0)