Skip to content

Commit 4d35dfd

Browse files
alex268alex268
committed
Update transaction tracer
1 parent 9f6bbee commit 4d35dfd

File tree

4 files changed

+74
-25
lines changed

4 files changed

+74
-25
lines changed

‎jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java‎

Lines changed: 50 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@
33
import java.util.ArrayList;
44
import java.util.Date;
55
import java.util.List;
6+
import java.util.Objects;
67
import java.util.concurrent.atomic.AtomicLong;
78
import java.util.logging.Level;
89
import java.util.logging.Logger;
@@ -23,15 +24,18 @@ public class YdbTracer {
2324
private final List<Record> records = new ArrayList<>();
2425

2526
private String txID = null;
27+
private String label = null;
2628
private boolean isMarked = false;
2729
private boolean isClosed = false;
2830

2931
private class Record {
3032
private final long executedAt = System.currentTimeMillis();
3133
private final String message;
34+
private final boolean isRequest;
3235

33-
Record(String message) {
36+
Record(String message, boolean isRequest) {
3437
this.message = message;
38+
this.isRequest = isRequest;
3539
}
3640
}
3741

@@ -50,17 +54,33 @@ public static YdbTracer current() {
5054
}
5155

5256
public void trace(String message) {
53-
records.add(new Record(message));
57+
records.add(new Record(message, false));
58+
}
59+
60+
public void traceRequest(String message) {
61+
records.add(new Record(message, true));
5462
}
5563

5664
public void setId(String id) {
57-
this.txID = id;
58-
trace("set-id " + id);
65+
if (!Objects.equals(id, txID)) {
66+
this.txID = id;
67+
trace("set-id " + id);
68+
}
5969
}
6070

6171
public void markToPrint() {
62-
this.isMarked = true;
63-
trace("markToPrint");
72+
if (!isMarked) {
73+
this.isMarked = true;
74+
trace("markToPrint");
75+
}
76+
}
77+
78+
public void markToPrint(String label) {
79+
if (!isMarked) {
80+
this.isMarked = true;
81+
this.label = label;
82+
trace("markToPrint " + label);
83+
}
6484
}
6585

6686
public void close() {
@@ -74,15 +94,33 @@ public void close() {
7494
}
7595

7696
long finishedAt = System.currentTimeMillis();
97+
long requestsTime = 0;
7798

78-
final String id = txID != null ? txID : "anonymous-" + ANONYMOUS_COUNTER.incrementAndGet();
79-
LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] {id, startDate});
99+
String id = txID != null ? txID : "anonymous-" + ANONYMOUS_COUNTER.incrementAndGet();
100+
String traceID = label == null ? id : label + "-" + id;
101+
LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] {traceID, startDate});
80102
long last = startedAt;
103+
long requestsCount = 0;
104+
boolean lastIsRequest = false;
81105
for (Record record: records) {
82-
long ms = record.executedAt - last;
83-
LOGGER.log(level, "Trace[{0}] {1} ms {2}", new Object[] {id, ms, record.message});
84-
last = record.executedAt;
106+
if (record.isRequest) {
107+
requestsCount++;
108+
lastIsRequest = true;
109+
if (record.message != null) {
110+
LOGGER.log(level, "Query[{0}]: {1}", new Object[] {traceID, record.message.replaceAll("\\s", " ")});
111+
}
112+
} else {
113+
long ms = record.executedAt - last;
114+
if (lastIsRequest) {
115+
requestsTime += ms;
116+
lastIsRequest = false;
117+
}
118+
LOGGER.log(level, "Trace[{0}] {1} ms {2}", new Object[] {traceID, ms, record.message});
119+
last = record.executedAt;
120+
}
85121
}
86-
LOGGER.log(level, "Trace[{0}] finished in {1} ms", new Object[] {id, finishedAt - startedAt});
122+
LOGGER.log(level, "Trace[{0}] finished in {1} ms, {2} requests take {3} ms", new Object[] {
123+
traceID, finishedAt - startedAt, requestsCount, requestsTime
124+
});
87125
}
88126
}

‎jdbc/src/main/java/tech/ydb/jdbc/context/BaseYdbExecutor.java‎

Lines changed: 14 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -90,6 +90,16 @@ public YdbTracer trace(String message) {
9090
return tracer;
9191
}
9292

93+
protected YdbTracer traceRequest(String type, String message) {
94+
if (!traceEnabled) {
95+
return null;
96+
}
97+
YdbTracer tracer = YdbTracer.current();
98+
tracer.trace("--> " + type);
99+
tracer.traceRequest(message);
100+
return tracer;
101+
}
102+
93103
@Override
94104
public YdbQueryResult executeSchemeQuery(YdbStatement statement, YdbQuery query) throws SQLException {
95105
ensureOpened();
@@ -99,7 +109,8 @@ public YdbQueryResult executeSchemeQuery(YdbStatement statement, YdbQuery query)
99109
YdbValidator validator = statement.getValidator();
100110

101111
// Scheme query does not affect transactions or result sets
102-
YdbTracer tracer = trace("--> scheme >>\n" + yql);
112+
YdbTracer tracer = traceRequest("scheme query", yql);
113+
103114
ExecuteSchemeQuerySettings settings = ctx.withDefaultTimeout(new ExecuteSchemeQuerySettings());
104115
validator.execute(QueryType.SCHEME_QUERY + " >>\n" + yql, tracer,
105116
() -> retryCtx.supplyStatus(session -> session.executeSchemeQuery(yql, settings))
@@ -119,7 +130,7 @@ public YdbQueryResult executeBulkUpsert(YdbStatement statement, YdbQuery query,
119130

120131
String yql = prefixPragma + query.getPreparedYql();
121132
YdbValidator validator = statement.getValidator();
122-
YdbTracer tracer = trace("--> bulk upsert >>\n" + yql);
133+
YdbTracer tracer = traceRequest("bulk upsert", yql);
123134
validator.execute(QueryType.BULK_QUERY + " >>\n" + yql, tracer,
124135
() -> retryCtx.supplyStatus(session -> session.executeBulkUpsert(tablePath, rows))
125136
);
@@ -145,7 +156,7 @@ public YdbQueryResult executeScanQuery(YdbStatement statement, YdbQuery query, S
145156
.build();
146157
String msg = QueryType.SCAN_QUERY + " >>\n" + yql;
147158

148-
final YdbTracer tracer = trace("--> scan query >>\n" + yql);
159+
final YdbTracer tracer = traceRequest("scan query", yql);
149160
final Session session = createNewTableSession(validator);
150161

151162
StreamQueryResult lazy = validator.call(msg, null, () -> {

‎jdbc/src/main/java/tech/ydb/jdbc/context/QueryServiceExecutor.java‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -188,7 +188,7 @@ public void commit(YdbContext ctx, YdbValidator validator) throws SQLException {
188188
return;
189189
}
190190

191-
YdbTracer tracer = trace("--> commit");
191+
YdbTracer tracer = traceRequest("commit", null);
192192
CommitTransactionSettings settings = ctx.withRequestTimeout(CommitTransactionSettings.newBuilder()).build();
193193
try {
194194
validator.clearWarnings();
@@ -212,7 +212,7 @@ public void rollback(YdbContext ctx, YdbValidator validator) throws SQLException
212212
return;
213213
}
214214

215-
YdbTracer tracer = trace("--> rollback");
215+
YdbTracer tracer = traceRequest("rollback", null);
216216
RollbackTransactionSettings settings = ctx.withRequestTimeout(RollbackTransactionSettings.newBuilder())
217217
.build();
218218

@@ -257,7 +257,7 @@ public YdbQueryResult executeDataQuery(
257257
String yql = prefixPragma + preparedYql;
258258

259259
if (useStreamResultSet) {
260-
YdbTracer tracer = trace("--> stream query >>\n" + yql);
260+
YdbTracer tracer = traceRequest("stream query", yql);
261261
String msg = "STREAM_QUERY >>\n" + yql;
262262
StreamQueryResult lazy = validator.call(msg, null, () -> {
263263
final CompletableFuture<Result<StreamQueryResult>> future = new CompletableFuture<>();
@@ -316,7 +316,7 @@ public void onNextPart(QueryResultPart part) {
316316
return updateCurrentResult(lazy);
317317
}
318318

319-
YdbTracer tracer = trace("--> data query >>\n" + yql);
319+
YdbTracer tracer = traceRequest("data query", yql);
320320
try {
321321
QueryReader result = validator.call(QueryType.DATA_QUERY + " >>\n" + yql, tracer,
322322
() -> QueryReader.readFrom(localTx.createQuery(yql, isAutoCommit, params, settings))
@@ -354,7 +354,7 @@ public YdbQueryResult executeSchemeQuery(YdbStatement statement, YdbQuery query)
354354
YdbValidator validator = statement.getValidator();
355355

356356
// Scheme query does not affect transactions or result sets
357-
YdbTracer tracer = trace("--> scheme query >>\n" + yql);
357+
YdbTracer tracer = traceRequest("scheme query", yql);
358358
ExecuteQuerySettings settings = ctx.withRequestTimeout(ExecuteQuerySettings.newBuilder()).build();
359359
try (QuerySession session = createNewQuerySession(validator)) {
360360
validator.call(QueryType.SCHEME_QUERY + " >>\n" + yql, tracer, () -> session
@@ -383,7 +383,7 @@ public YdbQueryResult executeExplainQuery(YdbStatement statement, YdbQuery query
383383
ExecuteQuerySettings settings = ctx.withRequestTimeout(ExecuteQuerySettings.newBuilder())
384384
.withExecMode(QueryExecMode.EXPLAIN)
385385
.build();
386-
YdbTracer tracer = trace("--> explain query >>\n" + yql);
386+
YdbTracer tracer = traceRequest("explain query", yql);
387387

388388
try (QuerySession session = createNewQuerySession(validator)) {
389389
QueryInfo res = validator.call(QueryType.EXPLAIN_QUERY + " >>\n" + yql, tracer, () -> session

‎jdbc/src/main/java/tech/ydb/jdbc/context/TableServiceExecutor.java‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -118,7 +118,7 @@ public void commit(YdbContext ctx, YdbValidator validator) throws SQLException {
118118

119119
Session session = tx.getSession(validator);
120120
CommitTxSettings settings = ctx.withDefaultTimeout(new CommitTxSettings());
121-
YdbTracer tracer = trace("--> commit");
121+
YdbTracer tracer = traceRequest("commit", null);
122122

123123
try {
124124
validator.clearWarnings();
@@ -144,7 +144,7 @@ public void rollback(YdbContext ctx, YdbValidator validator) throws SQLException
144144

145145
Session session = tx.getSession(validator);
146146
RollbackTxSettings settings = ctx.withDefaultTimeout(new RollbackTxSettings());
147-
YdbTracer tracer = trace("--> rollback");
147+
YdbTracer tracer = traceRequest("rollback", null);
148148

149149
try {
150150
validator.clearWarnings();
@@ -181,7 +181,7 @@ public YdbQueryResult executeExplainQuery(YdbStatement statement, YdbQuery query
181181
YdbContext ctx = statement.getConnection().getCtx();
182182
YdbValidator validator = statement.getValidator();
183183
String yql = prefixPragma + query.getPreparedYql();
184-
YdbTracer tracer = trace("--> explain >>\n" + yql);
184+
YdbTracer tracer = traceRequest("explain", yql);
185185

186186
ExplainDataQuerySettings settings = ctx.withDefaultTimeout(new ExplainDataQuerySettings());
187187
try (Session session = createNewTableSession(validator)) {
@@ -203,7 +203,7 @@ public YdbQueryResult executeDataQuery(YdbStatement statement, YdbQuery query, S
203203
YdbValidator validator = statement.getValidator();
204204
Session session = tx.getSession(validator);
205205
String yql = prefixPragma + preparedYql;
206-
YdbTracer tracer = trace("--> data query >>\n" + yql);
206+
YdbTracer tracer = traceRequest("data query", yql);
207207
try {
208208
DataQueryResult result = validator.call(
209209
QueryType.DATA_QUERY + " >>\n" + yql, tracer,

0 commit comments

Comments
 (0)