Skip to content

Commit f82b438

Browse files
committed
Added TestTxTracer
1 parent cdc4a9b commit f82b438

File tree

6 files changed

+159
-95
lines changed

6 files changed

+159
-95
lines changed

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

Lines changed: 2 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -9,20 +9,12 @@
99
* @author Aleksandr Gorshenin
1010
*/
1111
public interface YdbTracer {
12-
interface Storage {
13-
YdbTracer get();
14-
15-
default void clear() {
16-
17-
}
18-
}
19-
2012
static YdbTracer current() {
21-
return YdbTracerImpl.ENABLED.get();
13+
return YdbTracerImpl.get();
2214
}
2315

2416
static void clear() {
25-
YdbTracerImpl.ENABLED.clear();
17+
YdbTracerImpl.clear();
2618
}
2719

2820
void setId(String id);

jdbc/src/main/java/tech/ydb/jdbc/context/YdbContext.java

Lines changed: 4 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -27,7 +27,6 @@
2727
import tech.ydb.jdbc.YdbTracer;
2828
import tech.ydb.jdbc.common.YdbTypes;
2929
import tech.ydb.jdbc.exception.ExceptionFactory;
30-
import tech.ydb.jdbc.impl.YdbTracerImpl;
3130
import tech.ydb.jdbc.impl.YdbTracerNone;
3231
import tech.ydb.jdbc.query.QueryKey;
3332
import tech.ydb.jdbc.query.QueryType;
@@ -92,8 +91,6 @@ public class YdbContext implements AutoCloseable {
9291
private final boolean autoResizeSessionPool;
9392
private final AtomicInteger connectionsCount = new AtomicInteger();
9493

95-
private YdbTracer.Storage tracerStorage;
96-
9794
private YdbContext(
9895
YdbConfig config,
9996
YdbOperationProperties operationProperties,
@@ -141,18 +138,12 @@ private YdbContext(
141138
prefixPath = transport.getDatabase();
142139
prefixPragma = "";
143140
}
144-
145-
this.tracerStorage = config.isTxTracedEnabled() ? YdbTracerImpl.ENABLED : YdbTracerNone.DISABLED;
146141
}
147142

148143
public YdbTypes getTypes() {
149144
return types;
150145
}
151146

152-
public void setTracerStorage(YdbTracer.Storage storage) {
153-
this.tracerStorage = storage;
154-
}
155-
156147
/**
157148
* Grpc Transport for other API YDB server clients
158149
*
@@ -163,7 +154,7 @@ public GrpcTransport getGrpcTransport() {
163154
}
164155

165156
public YdbTracer getTracer() {
166-
return tracerStorage.get();
157+
return config.isTxTracedEnabled() ? YdbTracer.current() : YdbTracerNone.DISABLED;
167158
}
168159

169160
private String joined(String path1, String path2) {
@@ -270,7 +261,7 @@ public void register() {
270261
}
271262

272263
public void deregister() {
273-
tracerStorage.clear();
264+
YdbTracer.clear();
274265

275266
int actual = connectionsCount.decrementAndGet();
276267
int maxSize = tableClient.sessionPoolStats().getMaxSize();
@@ -416,7 +407,7 @@ public YdbPreparedQuery findOrPrepareParams(YdbQuery query, YdbPrepareMode mode)
416407
String tablePath = joined(getPrefixPath(), query.getYqlBatcher().getTableName());
417408
TableDescription description = tableDescribeCache.getIfPresent(tablePath);
418409
if (description == null) {
419-
YdbTracer tracer = tracerStorage.get();
410+
YdbTracer tracer = getTracer();
420411
tracer.trace("--> describe table");
421412
tracer.trace(tablePath);
422413

@@ -459,7 +450,7 @@ public YdbPreparedQuery findOrPrepareParams(YdbQuery query, YdbPrepareMode mode)
459450
Map<String, Type> queryTypes = queryParamsCache.getIfPresent(query.getOriginQuery());
460451
if (queryTypes == null) {
461452
String yql = prefixPragma + query.getPreparedYql();
462-
YdbTracer tracer = tracerStorage.get();
453+
YdbTracer tracer = getTracer();
463454
tracer.trace("--> prepare data query");
464455
tracer.trace(yql);
465456

jdbc/src/main/java/tech/ydb/jdbc/impl/YdbTracerImpl.java

Lines changed: 91 additions & 68 deletions
Original file line numberDiff line numberDiff line change
@@ -19,32 +19,6 @@ public class YdbTracerImpl implements YdbTracer {
1919
private static final ThreadLocal<YdbTracer> LOCAL = new ThreadLocal<>();
2020
private static final AtomicLong ANONYMOUS_COUNTER = new AtomicLong(0);
2121

22-
public static final Storage ENABLED = new Storage() {
23-
@Override
24-
public YdbTracer get() {
25-
YdbTracer tracer = LOCAL.get();
26-
if (tracer == null) {
27-
tracer = new YdbTracerImpl();
28-
LOCAL.set(tracer);
29-
}
30-
31-
return tracer;
32-
}
33-
34-
@Override
35-
public void clear() {
36-
LOCAL.remove();
37-
}
38-
};
39-
40-
private final Date startDate = new Date();
41-
private final long startedAt = System.currentTimeMillis();
42-
private final List<Record> records = new ArrayList<>();
43-
44-
private String txID = null;
45-
private String label = null;
46-
private boolean isMarked = false;
47-
4822
private class Record {
4923
private final long executedAt = System.currentTimeMillis();
5024
private final String message;
@@ -56,70 +30,119 @@ private class Record {
5630
}
5731
}
5832

33+
private class Tx {
34+
private final Date startDate = new Date();
35+
private final long startedAt = System.currentTimeMillis();
36+
private final List<Record> records = new ArrayList<>();
37+
38+
private String id = null;
39+
private String label = null;
40+
private boolean isMarked = false;
41+
42+
private void log(Level level) {
43+
if (!LOGGER.isLoggable(level) || records.isEmpty()) {
44+
return;
45+
}
46+
47+
long finishedAt = System.currentTimeMillis();
48+
long requestsTime = 0;
49+
50+
String idName = id != null ? id : "anonymous-" + ANONYMOUS_COUNTER.incrementAndGet();
51+
String traceID = label == null ? idName : label + "-" + idName;
52+
LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] {traceID, startDate});
53+
long last = startedAt;
54+
long requestsCount = 0;
55+
boolean lastIsRequest = false;
56+
for (Record record: records) {
57+
if (record.isRequest) {
58+
requestsCount++;
59+
lastIsRequest = true;
60+
if (record.message != null) {
61+
String clean = record.message.replaceAll("\\s", " ");
62+
LOGGER.log(level, "Query[{0}] {1}", new Object[] {traceID, clean});
63+
}
64+
} else {
65+
long ms = record.executedAt - last;
66+
if (lastIsRequest) {
67+
requestsTime += ms;
68+
lastIsRequest = false;
69+
}
70+
LOGGER.log(level, "Trace[{0}] {1} ms {2}", new Object[] {traceID, ms, record.message});
71+
last = record.executedAt;
72+
}
73+
}
74+
LOGGER.log(level, "Trace[{0}] finished in {1} ms, {2} requests take {3} ms", new Object[] {
75+
traceID, finishedAt - startedAt, requestsCount, requestsTime
76+
});
77+
}
78+
}
79+
80+
private Tx tx = null;
81+
82+
public static <T extends YdbTracer> T use(T tracer) {
83+
LOCAL.set(tracer);
84+
return tracer;
85+
}
86+
87+
public static YdbTracer get() {
88+
YdbTracer tracer = LOCAL.get();
89+
if (tracer == null) {
90+
tracer = new YdbTracerImpl();
91+
LOCAL.set(tracer);
92+
}
93+
94+
return tracer;
95+
}
96+
97+
public static void clear() {
98+
YdbTracer tracer = LOCAL.get();
99+
if (tracer != null) {
100+
tracer.close();
101+
}
102+
LOCAL.remove();
103+
}
104+
105+
private Tx ensureOpen() {
106+
if (tx == null) {
107+
tx = new Tx();
108+
}
109+
return tx;
110+
}
111+
59112
@Override
60113
public void trace(String message) {
61-
records.add(new Record(message, false));
114+
ensureOpen().records.add(new Record(message, false));
62115
}
63116

64117
@Override
65118
public void query(String queryText) {
66-
records.add(new Record(queryText, true));
119+
ensureOpen().records.add(new Record(queryText, true));
67120
}
68121

69122
@Override
70123
public void setId(String id) {
71-
if (!Objects.equals(id, txID)) {
72-
this.txID = id;
124+
Tx local = ensureOpen();
125+
if (!Objects.equals(id, local.id)) {
126+
local.id = id;
73127
trace("set-id " + id);
74128
}
75129
}
76130

77131
@Override
78132
public void markToPrint(String label) {
79-
if (!isMarked || !Objects.equals(label, this.label)) {
80-
this.isMarked = true;
81-
this.label = label;
133+
Tx local = ensureOpen();
134+
if (!local.isMarked || !Objects.equals(label, local.label)) {
135+
local.isMarked = true;
136+
local.label = label;
82137
trace("markToPrint " + label);
83138
}
84139
}
85140

86141
@Override
87142
public void close() {
88-
LOCAL.remove();
89-
90-
final Level level = isMarked ? Level.INFO : Level.FINE;
91-
if (!LOGGER.isLoggable(level) || records.isEmpty()) {
92-
return;
93-
}
94-
95-
long finishedAt = System.currentTimeMillis();
96-
long requestsTime = 0;
97-
98-
String id = txID != null ? txID : "anonymous-" + ANONYMOUS_COUNTER.incrementAndGet();
99-
String traceID = label == null ? id : label + "-" + id;
100-
LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] {traceID, startDate});
101-
long last = startedAt;
102-
long requestsCount = 0;
103-
boolean lastIsRequest = false;
104-
for (Record record: records) {
105-
if (record.isRequest) {
106-
requestsCount++;
107-
lastIsRequest = true;
108-
if (record.message != null) {
109-
LOGGER.log(level, "Query[{0}] {1}", new Object[] {traceID, record.message.replaceAll("\\s", " ")});
110-
}
111-
} else {
112-
long ms = record.executedAt - last;
113-
if (lastIsRequest) {
114-
requestsTime += ms;
115-
lastIsRequest = false;
116-
}
117-
LOGGER.log(level, "Trace[{0}] {1} ms {2}", new Object[] {traceID, ms, record.message});
118-
last = record.executedAt;
119-
}
143+
if (tx != null) {
144+
tx.log(tx.isMarked ? Level.INFO : Level.FINE);
145+
tx = null;
120146
}
121-
LOGGER.log(level, "Trace[{0}] finished in {1} ms, {2} requests take {3} ms", new Object[] {
122-
traceID, finishedAt - startedAt, requestsCount, requestsTime
123-
});
124147
}
125148
}

jdbc/src/main/java/tech/ydb/jdbc/impl/YdbTracerNone.java

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,8 +7,7 @@
77
* @author Aleksandr Gorshenin
88
*/
99
public class YdbTracerNone implements YdbTracer {
10-
private static final YdbTracer NONE = new YdbTracerNone();
11-
public static final YdbTracer.Storage DISABLED = () -> NONE;
10+
public static final YdbTracer DISABLED = new YdbTracerNone();
1211

1312
@Override
1413
public void trace(String message) { }

jdbc/src/test/java/tech/ydb/jdbc/impl/YdbPreparedStatementTest.java

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@
3636
import tech.ydb.jdbc.impl.helper.ExceptionAssert;
3737
import tech.ydb.jdbc.impl.helper.JdbcConnectionExtention;
3838
import tech.ydb.jdbc.impl.helper.SqlQueries;
39+
import tech.ydb.jdbc.impl.helper.TestTxTracer;
3940
import tech.ydb.jdbc.impl.helper.TextSelectAssert;
4041
import tech.ydb.table.values.DecimalType;
4142
import tech.ydb.table.values.PrimitiveType;
@@ -53,7 +54,8 @@ public class YdbPreparedStatementTest {
5354
private static final YdbHelperExtension ydb = new YdbHelperExtension();
5455

5556
@RegisterExtension
56-
private static final JdbcConnectionExtention jdbc = new JdbcConnectionExtention(ydb);
57+
private static final JdbcConnectionExtention jdbc = new JdbcConnectionExtention(ydb)
58+
.withArg("enableTxTracer", "true");
5759

5860
private static final SqlQueries TEST_TABLE = new SqlQueries("ydb_prepared_test");
5961

@@ -261,8 +263,10 @@ public void simpleUpsertTest(SqlQueries.JdbcQuery query) throws SQLException {
261263
@EnumSource(SqlQueries.JdbcQuery.class)
262264
public void batchUpsertTest(SqlQueries.JdbcQuery query) throws SQLException {
263265
String upsert = TEST_TABLE.upsertOne(query, "c_Text", "Text");
264-
266+
boolean batched = query != SqlQueries.JdbcQuery.TYPED && query != SqlQueries.JdbcQuery.IN_MEMORY;
265267
try (PreparedStatement statement = jdbc.connection().prepareStatement(upsert)) {
268+
TestTxTracer tracer = YdbTracerImpl.use(new TestTxTracer());
269+
266270
// ----- base usage -----
267271
statement.setInt(1, 1);
268272
statement.setString(2, "value-1");
@@ -273,6 +277,7 @@ public void batchUpsertTest(SqlQueries.JdbcQuery query) throws SQLException {
273277
statement.addBatch();
274278

275279
statement.executeBatch();
280+
tracer.assertQueriesCount(batched ? 1 : 2);
276281

277282
// ----- executeBatch without addBatch -----
278283
statement.setInt(1, 3);
@@ -283,6 +288,7 @@ public void batchUpsertTest(SqlQueries.JdbcQuery query) throws SQLException {
283288
statement.setString(2, "value-4");
284289

285290
statement.executeBatch();
291+
tracer.assertQueriesCount(1);
286292

287293
// ----- execute instead of executeBatch -----
288294
statement.setInt(1, 5);
@@ -293,6 +299,7 @@ public void batchUpsertTest(SqlQueries.JdbcQuery query) throws SQLException {
293299
statement.setString(2, "value-6");
294300

295301
statement.execute();
302+
tracer.assertQueriesCount(1);
296303
}
297304

298305
String select = TEST_TABLE.selectColumn("c_Text");

0 commit comments

Comments
 (0)