From 137a03734b1fe02bdec6c62eee4ff312f7403149 Mon Sep 17 00:00:00 2001 From: Alexandr Gorshenin Date: Mon, 14 Oct 2024 14:05:33 +0100 Subject: [PATCH 1/3] Removed tracing from YdbValidator --- .../tech/ydb/jdbc/context/YdbValidator.java | 57 +------------------ .../tech/ydb/jdbc/impl/BaseYdbStatement.java | 2 +- .../tech/ydb/jdbc/impl/YdbConnectionImpl.java | 2 +- .../jdbc/impl/YdbDatabaseMetaDataImpl.java | 2 +- 4 files changed, 4 insertions(+), 59 deletions(-) diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java index 6f2993d..8bf1143 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java @@ -7,10 +7,6 @@ import java.util.List; import java.util.concurrent.CompletableFuture; import java.util.function.Supplier; -import java.util.logging.Level; -import java.util.logging.Logger; - -import com.google.common.base.Stopwatch; import tech.ydb.core.Issue; import tech.ydb.core.Result; @@ -23,16 +19,8 @@ * @author Aleksandr Gorshenin */ public class YdbValidator { - @SuppressWarnings("NonConstantLogger") - private final Logger logger; - private final boolean isDebug; private final List issues = new ArrayList<>(); - public YdbValidator(Logger logger) { - this.logger = logger; - this.isDebug = logger.isLoggable(Level.FINE); - } - public SQLWarning toSQLWarnings() { SQLWarning firstWarning = null; SQLWarning warning = null; @@ -62,48 +50,6 @@ public void clearWarnings() { } public void execute(String msg, Supplier> fn) throws SQLException { - if (!isDebug) { - runImpl(msg, fn); - return; - } - - logger.finest(msg); - Stopwatch sw = Stopwatch.createStarted(); - - try { - runImpl(msg, fn); - logger.log(Level.FINEST, "[{0}] OK ", sw.stop()); - } catch (SQLException ex) { - logger.log(Level.FINE, "[{0}] {1} ", new Object[] {sw.stop(), ex.getMessage()}); - throw ex; - } catch (Exception ex) { - logger.log(Level.WARNING, "ERROR ", ex); - throw ex; - } - } - - public R call(String msg, Supplier>> fn) throws SQLException { - if (!isDebug) { - return callImpl(msg, fn); - } - - logger.finest(msg); - Stopwatch sw = Stopwatch.createStarted(); - - try { - R value = callImpl(msg, fn); - logger.log(Level.FINEST, "[{0}] OK ", sw.stop()); - return value; - } catch (SQLException ex) { - logger.log(Level.FINE, "[{0}] FAIL {1} ", new Object[] {sw.stop(), ex.getMessage()}); - throw ex; - } catch (Exception ex) { - logger.log(Level.WARNING, "ERROR ", ex); - throw ex; - } - } - - private void runImpl(String msg, Supplier> fn) throws SQLException { Status status = fn.get().join(); addStatusIssues(status); @@ -113,7 +59,7 @@ private void runImpl(String msg, Supplier> fn) throws } } - private R callImpl(String msg, Supplier>> fn) throws SQLException { + public R call(String msg, Supplier>> fn) throws SQLException { try { Result result = fn.get().join(); addStatusIssues(result.getStatus()); @@ -122,5 +68,4 @@ private R callImpl(String msg, Supplier>> fn) th throw ExceptionFactory.createException("Cannot call '" + msg + "' with " + ex.getStatus(), ex); } } - } diff --git a/jdbc/src/main/java/tech/ydb/jdbc/impl/BaseYdbStatement.java b/jdbc/src/main/java/tech/ydb/jdbc/impl/BaseYdbStatement.java index 5f42cd7..e2ba550 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/impl/BaseYdbStatement.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/impl/BaseYdbStatement.java @@ -43,7 +43,7 @@ public abstract class BaseYdbStatement implements YdbStatement { public BaseYdbStatement(Logger logger, YdbConnection connection, int resultSetType, boolean isPoolable) { this.connection = Objects.requireNonNull(connection); - this.validator = new YdbValidator(logger); + this.validator = new YdbValidator(); this.resultSetType = resultSetType; this.isPoolable = isPoolable; diff --git a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java index 2487216..b84652e 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java @@ -42,7 +42,7 @@ public class YdbConnectionImpl implements YdbConnection { public YdbConnectionImpl(YdbContext context) throws SQLException { this.ctx = context; - this.validator = new YdbValidator(LOGGER); + this.validator = new YdbValidator(); this.executor = ctx.createExecutor(); this.ctx.register(); } diff --git a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java index 367df70..c5cb405 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java @@ -56,7 +56,7 @@ public class YdbDatabaseMetaDataImpl implements YdbDatabaseMetaData { public YdbDatabaseMetaDataImpl(YdbConnection connection) { this.connection = Objects.requireNonNull(connection); this.executor = new SchemeExecutor(connection.getCtx()); - this.validator = new YdbValidator(LOGGER); + this.validator = new YdbValidator(); } @Override From ba0e1127f3ca282d9dba3ba891deae6be06f36f5 Mon Sep 17 00:00:00 2001 From: Alexandr Gorshenin Date: Mon, 14 Oct 2024 14:05:55 +0100 Subject: [PATCH 2/3] Added YdbTracer to keep trace of whole transaction --- .../main/java/tech/ydb/jdbc/YdbTracer.java | 89 +++++++++++++++++++ 1 file changed, 89 insertions(+) create mode 100644 jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java diff --git a/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java b/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java new file mode 100644 index 0000000..cf58f85 --- /dev/null +++ b/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java @@ -0,0 +1,89 @@ +package tech.ydb.jdbc; + +import java.util.ArrayList; +import java.util.Date; +import java.util.List; +import java.util.concurrent.ThreadLocalRandom; +import java.util.logging.Level; +import java.util.logging.Logger; + + + +/** + * + * @author Aleksandr Gorshenin + */ +public class YdbTracer { + private static final Logger LOGGER = Logger.getLogger(YdbTracer.class.getName()); + private static final ThreadLocal LOCAL = new ThreadLocal<>(); + + private final Date startDate = new Date(); + private final long startedAt = System.currentTimeMillis(); + private final List records = new ArrayList<>(); + + private String txID = null; + private boolean isMarked = false; + private boolean isClosed = false; + + private class Record { + private final long executedAt = System.currentTimeMillis(); + private final String type; + private final String comment; + + public Record(String type, String comment) { + this.type = type; + this.comment = comment; + } + } + + public static void clear() { + LOCAL.remove(); + } + + public static YdbTracer current() { + YdbTracer tracer = LOCAL.get(); + if (tracer == null || tracer.isClosed) { + tracer = new YdbTracer(); + LOCAL.set(tracer); + } + + return tracer; + } + + public void trace(String type, String comment) { + records.add(new Record(type, comment)); + } + + public void setId(String id) { + this.txID = id; + trace("SET ID", id); + } + + public void markToPrint() { + this.isMarked = true; + trace("MARK TO PRINT", ""); + } + + public void close() { + isClosed = true; + + LOCAL.remove(); + + final Level level = isMarked ? Level.INFO : Level.FINE; + if (!LOGGER.isLoggable(level) || records.isEmpty()) { + return; + } + + long finishedAt = System.currentTimeMillis(); + + final String id = txID != null ? txID : "UKNOWN-" + ThreadLocalRandom.current().nextLong(); + LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] { id, startDate }); + long last = startedAt; + for (Record record: records) { + long ms = record.executedAt - last; + LOGGER.log(level, "Trace[{0}] {1} ms {2}: {3}", new Object[] { id, ms, record.type, record.comment }); + last = record.executedAt; + } + LOGGER.log(level, "Trace[{0}] finished in {1} ms", new Object[] { id, finishedAt - startedAt }); + } +} From 3d213110ff4ce947611feab01d8317f777ed1351 Mon Sep 17 00:00:00 2001 From: Alexandr Gorshenin Date: Mon, 14 Oct 2024 15:23:52 +0100 Subject: [PATCH 3/3] Customized transaction tracer --- .../main/java/tech/ydb/jdbc/YdbDriver.java | 5 ++ .../main/java/tech/ydb/jdbc/YdbTracer.java | 27 +++++---- .../ydb/jdbc/context/BaseYdbExecutor.java | 43 ++++++++++++-- .../jdbc/context/QueryServiceExecutor.java | 58 +++++++++++++++++-- .../jdbc/context/TableServiceExecutor.java | 33 +++++++++-- .../tech/ydb/jdbc/context/YdbContext.java | 4 ++ .../tech/ydb/jdbc/context/YdbExecutor.java | 3 + .../tech/ydb/jdbc/context/YdbValidator.java | 11 +++- .../tech/ydb/jdbc/impl/YdbConnectionImpl.java | 6 +- .../jdbc/impl/YdbDatabaseMetaDataImpl.java | 6 +- .../tech/ydb/jdbc/settings/YdbConfig.java | 10 +++- .../tech/ydb/jdbc/YdbDriverTablesTest.java | 2 +- .../impl/helper/JdbcConnectionExtention.java | 1 + 13 files changed, 172 insertions(+), 37 deletions(-) diff --git a/jdbc/src/main/java/tech/ydb/jdbc/YdbDriver.java b/jdbc/src/main/java/tech/ydb/jdbc/YdbDriver.java index b25a8bc..a3cb405 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/YdbDriver.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/YdbDriver.java @@ -98,6 +98,11 @@ public boolean acceptsURL(String url) { return YdbConfig.isYdb(url); } + @Override + public String toString() { + return YdbDriverInfo.DRIVER_FULL_NAME; + } + @Override public DriverPropertyInfo[] getPropertyInfo(String url, Properties info) throws SQLException { YdbConfig config = YdbConfig.from(url, info); diff --git a/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java b/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java index cf58f85..a4152a0 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/YdbTracer.java @@ -3,7 +3,7 @@ import java.util.ArrayList; import java.util.Date; import java.util.List; -import java.util.concurrent.ThreadLocalRandom; +import java.util.concurrent.atomic.AtomicLong; import java.util.logging.Level; import java.util.logging.Logger; @@ -16,6 +16,7 @@ public class YdbTracer { private static final Logger LOGGER = Logger.getLogger(YdbTracer.class.getName()); private static final ThreadLocal LOCAL = new ThreadLocal<>(); + private static final AtomicLong ANONYMOUS_COUNTER = new AtomicLong(0); private final Date startDate = new Date(); private final long startedAt = System.currentTimeMillis(); @@ -27,12 +28,10 @@ public class YdbTracer { private class Record { private final long executedAt = System.currentTimeMillis(); - private final String type; - private final String comment; + private final String message; - public Record(String type, String comment) { - this.type = type; - this.comment = comment; + Record(String message) { + this.message = message; } } @@ -50,18 +49,18 @@ public static YdbTracer current() { return tracer; } - public void trace(String type, String comment) { - records.add(new Record(type, comment)); + public void trace(String message) { + records.add(new Record(message)); } public void setId(String id) { this.txID = id; - trace("SET ID", id); + trace("set-id " + id); } public void markToPrint() { this.isMarked = true; - trace("MARK TO PRINT", ""); + trace("markToPrint"); } public void close() { @@ -76,14 +75,14 @@ public void close() { long finishedAt = System.currentTimeMillis(); - final String id = txID != null ? txID : "UKNOWN-" + ThreadLocalRandom.current().nextLong(); - LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] { id, startDate }); + final String id = txID != null ? txID : "anonymous-" + ANONYMOUS_COUNTER.incrementAndGet(); + LOGGER.log(level, "Trace[{0}] started at {1}", new Object[] {id, startDate}); long last = startedAt; for (Record record: records) { long ms = record.executedAt - last; - LOGGER.log(level, "Trace[{0}] {1} ms {2}: {3}", new Object[] { id, ms, record.type, record.comment }); + LOGGER.log(level, "Trace[{0}] {1} ms {2}", new Object[] {id, ms, record.message}); last = record.executedAt; } - LOGGER.log(level, "Trace[{0}] finished in {1} ms", new Object[] { id, finishedAt - startedAt }); + LOGGER.log(level, "Trace[{0}] finished in {1} ms", new Object[] {id, finishedAt - startedAt}); } } diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/BaseYdbExecutor.java b/jdbc/src/main/java/tech/ydb/jdbc/context/BaseYdbExecutor.java index 3adee19..d4cced7 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/BaseYdbExecutor.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/BaseYdbExecutor.java @@ -11,6 +11,7 @@ import tech.ydb.core.grpc.GrpcReadStream; import tech.ydb.jdbc.YdbConst; import tech.ydb.jdbc.YdbStatement; +import tech.ydb.jdbc.YdbTracer; import tech.ydb.jdbc.exception.ExceptionFactory; import tech.ydb.jdbc.impl.YdbQueryResult; import tech.ydb.jdbc.query.QueryType; @@ -33,9 +34,11 @@ public abstract class BaseYdbExecutor implements YdbExecutor { private final Duration sessionTimeout; private final TableClient tableClient; private final AtomicReference currResult; + protected final boolean traceEnabled; public BaseYdbExecutor(YdbContext ctx) { this.retryCtx = ctx.getRetryCtx(); + this.traceEnabled = ctx.isTxTracerEnabled(); this.sessionTimeout = ctx.getOperationProperties().getSessionTimeout(); this.tableClient = ctx.getTableClient(); this.currResult = new AtomicReference<>(); @@ -74,6 +77,16 @@ public void ensureOpened() throws SQLException { } } + @Override + public YdbTracer trace(String message) { + if (!traceEnabled) { + return null; + } + YdbTracer tracer = YdbTracer.current(); + tracer.trace(message); + return tracer; + } + @Override public YdbQueryResult executeSchemeQuery(YdbStatement statement, YdbQuery query) throws SQLException { ensureOpened(); @@ -83,11 +96,16 @@ public YdbQueryResult executeSchemeQuery(YdbStatement statement, YdbQuery query) YdbValidator validator = statement.getValidator(); // Scheme query does not affect transactions or result sets + YdbTracer tracer = trace("--> scheme >>\n" + yql); ExecuteSchemeQuerySettings settings = ctx.withDefaultTimeout(new ExecuteSchemeQuerySettings()); - validator.execute(QueryType.SCHEME_QUERY + " >>\n" + yql, + validator.execute(QueryType.SCHEME_QUERY + " >>\n" + yql, tracer, () -> retryCtx.supplyStatus(session -> session.executeSchemeQuery(yql, settings)) ); + if (tracer != null && !isInsideTransaction()) { + tracer.close(); + } + return updateCurrentResult(new StaticQueryResult(query, Collections.emptyList())); } @@ -98,10 +116,15 @@ public YdbQueryResult executeBulkUpsert(YdbStatement statement, YdbQuery query, String yql = query.getPreparedYql(); YdbValidator validator = statement.getValidator(); - validator.execute(QueryType.BULK_QUERY + " >>\n" + yql, + YdbTracer tracer = trace("--> bulk upsert >>\n" + yql); + validator.execute(QueryType.BULK_QUERY + " >>\n" + yql, tracer, () -> retryCtx.supplyStatus(session -> session.executeBulkUpsert(tablePath, rows)) ); + if (tracer != null && !isInsideTransaction()) { + tracer.close(); + } + return updateCurrentResult(new StaticQueryResult(query, Collections.emptyList())); } @@ -116,11 +139,11 @@ public YdbQueryResult executeScanQuery(YdbStatement statement, YdbQuery query, S ExecuteScanQuerySettings settings = ExecuteScanQuerySettings.newBuilder() .withRequestTimeout(scanQueryTimeout) .build(); - + String msg = QueryType.SCAN_QUERY + " >>\n" + yql; + final YdbTracer tracer = trace("--> scan query >>\n" + yql); final Session session = createNewTableSession(validator); - String msg = QueryType.SCAN_QUERY + " >>\n" + yql; - StreamQueryResult lazy = validator.call(msg, () -> { + StreamQueryResult lazy = validator.call(msg, null, () -> { final CompletableFuture> future = new CompletableFuture<>(); final GrpcReadStream stream = session.executeScanQuery(yql, params, settings); final StreamQueryResult result = new StreamQueryResult(msg, statement, query, stream::cancel); @@ -134,11 +157,21 @@ public YdbQueryResult executeScanQuery(YdbStatement statement, YdbQuery query, S if (th != null) { result.onStreamFinished(th); future.completeExceptionally(th); + + if (tracer != null) { + tracer.trace("<-- " + th.getMessage()); + tracer.close(); + } } if (st != null) { validator.addStatusIssues(st); result.onStreamFinished(st); future.complete(st.isSuccess() ? Result.success(result) : Result.fail(st)); + + if (tracer != null) { + tracer.trace("<-- " + st.toString()); + tracer.close(); + } } }); diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/QueryServiceExecutor.java b/jdbc/src/main/java/tech/ydb/jdbc/context/QueryServiceExecutor.java index dea2023..1ddf46c 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/QueryServiceExecutor.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/QueryServiceExecutor.java @@ -19,6 +19,7 @@ import tech.ydb.jdbc.YdbConst; import tech.ydb.jdbc.YdbResultSet; import tech.ydb.jdbc.YdbStatement; +import tech.ydb.jdbc.YdbTracer; import tech.ydb.jdbc.exception.ExceptionFactory; import tech.ydb.jdbc.impl.YdbQueryResult; import tech.ydb.jdbc.impl.YdbStaticResultSet; @@ -187,14 +188,18 @@ public void commit(YdbContext ctx, YdbValidator validator) throws SQLException { return; } + YdbTracer tracer = trace("--> commit"); CommitTransactionSettings settings = ctx.withRequestTimeout(CommitTransactionSettings.newBuilder()).build(); try { validator.clearWarnings(); - validator.call("Commit TxId: " + localTx.getId(), () -> localTx.commit(settings)); + validator.call("Commit TxId: " + localTx.getId(), tracer, () -> localTx.commit(settings)); } finally { if (tx.compareAndSet(localTx, null)) { localTx.getSession().close(); } + if (tracer != null) { + tracer.close(); + } } } @@ -207,16 +212,20 @@ public void rollback(YdbContext ctx, YdbValidator validator) throws SQLException return; } + YdbTracer tracer = trace("--> rollback"); RollbackTransactionSettings settings = ctx.withRequestTimeout(RollbackTransactionSettings.newBuilder()) .build(); try { validator.clearWarnings(); - validator.execute("Rollback TxId: " + localTx.getId(), () -> localTx.rollback(settings)); + validator.execute("Rollback TxId: " + localTx.getId(), tracer, () -> localTx.rollback(settings)); } finally { if (tx.compareAndSet(localTx, null)) { localTx.getSession().close(); } + if (tracer != null) { + tracer.close(); + } } } @@ -246,8 +255,9 @@ public YdbQueryResult executeDataQuery( final QueryTransaction localTx = nextTx; if (useStreamResultSet) { + YdbTracer tracer = trace("--> stream query >>\n" + yql); String msg = "STREAM_QUERY >>\n" + yql; - StreamQueryResult lazy = validator.call(msg, () -> { + StreamQueryResult lazy = validator.call(msg, null, () -> { final CompletableFuture> future = new CompletableFuture<>(); final QueryStream stream = localTx.createQuery(yql, isAutoCommit, params, settings); final StreamQueryResult result = new StreamQueryResult(msg, statement, query, stream::cancel); @@ -274,11 +284,27 @@ public void onNextPart(QueryResultPart part) { if (th != null) { future.completeExceptionally(th); result.onStreamFinished(th); + if (tracer != null) { + tracer.trace("<-- " + th.getMessage()); + if (localTx.isActive()) { + tracer.setId(localTx.getId()); + } else { + tracer.close(); + } + } } if (res != null) { validator.addStatusIssues(res.getStatus()); future.complete(res.isSuccess() ? Result.success(result) : Result.fail(res.getStatus())); result.onStreamFinished(res.getStatus()); + if (tracer != null) { + tracer.trace("<-- " + res.getStatus().toString()); + if (localTx.isActive()) { + tracer.setId(localTx.getId()); + } else { + tracer.close(); + } + } } }); @@ -288,8 +314,9 @@ public void onNextPart(QueryResultPart part) { return updateCurrentResult(lazy); } + YdbTracer tracer = trace("--> data query >>\n" + yql); try { - QueryReader result = validator.call(QueryType.DATA_QUERY + " >>\n" + yql, + QueryReader result = validator.call(QueryType.DATA_QUERY + " >>\n" + yql, tracer, () -> QueryReader.readFrom(localTx.createQuery(yql, isAutoCommit, params, settings)) ); validator.addStatusIssues(result.getIssueList()); @@ -305,6 +332,14 @@ public void onNextPart(QueryResultPart part) { localTx.getSession().close(); } } + + if (tracer != null) { + if (localTx.isActive()) { + tracer.setId(localTx.getId()); + } else { + tracer.close(); + } + } } } @@ -317,14 +352,20 @@ public YdbQueryResult executeSchemeQuery(YdbStatement statement, YdbQuery query) YdbValidator validator = statement.getValidator(); // Scheme query does not affect transactions or result sets + YdbTracer tracer = trace("--> scheme query >>\n" + yql); ExecuteQuerySettings settings = ctx.withRequestTimeout(ExecuteQuerySettings.newBuilder()).build(); try (QuerySession session = createNewQuerySession(validator)) { - validator.call(QueryType.SCHEME_QUERY + " >>\n" + yql, () -> session + validator.call(QueryType.SCHEME_QUERY + " >>\n" + yql, tracer, () -> session .createQuery(yql, TxMode.NONE, Params.empty(), settings) .execute(new IssueHandler(validator)) ); + } finally { + if (tracer != null && tx.get() == null) { + tracer.close(); + } } + return updateCurrentResult(new StaticQueryResult(query, Collections.emptyList())); } @@ -340,9 +381,10 @@ public YdbQueryResult executeExplainQuery(YdbStatement statement, YdbQuery query ExecuteQuerySettings settings = ctx.withRequestTimeout(ExecuteQuerySettings.newBuilder()) .withExecMode(QueryExecMode.EXPLAIN) .build(); + YdbTracer tracer = trace("--> explain query >>\n" + yql); try (QuerySession session = createNewQuerySession(validator)) { - QueryInfo res = validator.call(QueryType.EXPLAIN_QUERY + " >>\n" + yql, () -> session + QueryInfo res = validator.call(QueryType.EXPLAIN_QUERY + " >>\n" + yql, tracer, () -> session .createQuery(yql, TxMode.NONE, Params.empty(), settings) .execute(new IssueHandler(validator)) ); @@ -354,6 +396,10 @@ public YdbQueryResult executeExplainQuery(YdbStatement statement, YdbQuery query return updateCurrentResult( new StaticQueryResult(statement, res.getStats().getQueryAst(), res.getStats().getQueryPlan()) ); + } finally { + if (tracer != null && tx.get() == null) { + tracer.close(); + } } } diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/TableServiceExecutor.java b/jdbc/src/main/java/tech/ydb/jdbc/context/TableServiceExecutor.java index d5d39a5..7543313 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/TableServiceExecutor.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/TableServiceExecutor.java @@ -10,6 +10,7 @@ import tech.ydb.jdbc.YdbConst; import tech.ydb.jdbc.YdbResultSet; import tech.ydb.jdbc.YdbStatement; +import tech.ydb.jdbc.YdbTracer; import tech.ydb.jdbc.impl.YdbQueryResult; import tech.ydb.jdbc.impl.YdbStaticResultSet; import tech.ydb.jdbc.query.QueryType; @@ -117,15 +118,19 @@ public void commit(YdbContext ctx, YdbValidator validator) throws SQLException { Session session = tx.getSession(validator); CommitTxSettings settings = ctx.withDefaultTimeout(new CommitTxSettings()); + YdbTracer tracer = trace("--> commit"); try { validator.clearWarnings(); validator.execute( - "Commit TxId: " + tx.txID(), + "Commit TxId: " + tx.txID(), tracer, () -> session.commitTransaction(tx.txID(), settings) ); } finally { updateState(tx.withCommit(session)); + if (tracer != null) { + tracer.close(); + } } } @@ -139,15 +144,19 @@ public void rollback(YdbContext ctx, YdbValidator validator) throws SQLException Session session = tx.getSession(validator); RollbackTxSettings settings = ctx.withDefaultTimeout(new RollbackTxSettings()); + YdbTracer tracer = trace("--> rollback"); try { validator.clearWarnings(); validator.execute( - "Rollback TxId: " + tx.txID(), + "Rollback TxId: " + tx.txID(), tracer, () -> session.rollbackTransaction(tx.txID(), settings) ); } finally { updateState(tx.withRollback(session)); + if (tracer != null) { + tracer.close(); + } } } @@ -172,12 +181,17 @@ public YdbQueryResult executeExplainQuery(YdbStatement statement, YdbQuery query YdbContext ctx = statement.getConnection().getCtx(); YdbValidator validator = statement.getValidator(); String yql = query.getPreparedYql(); + YdbTracer tracer = trace("--> explain >>\n" + yql); ExplainDataQuerySettings settings = ctx.withDefaultTimeout(new ExplainDataQuerySettings()); try (Session session = createNewTableSession(validator)) { String msg = QueryType.EXPLAIN_QUERY + " >>\n" + yql; - ExplainDataQueryResult res = validator.call(msg, () -> session.explainDataQuery(yql, settings)); + ExplainDataQueryResult res = validator.call(msg, tracer, () -> session.explainDataQuery(yql, settings)); return updateCurrentResult(new StaticQueryResult(statement, res.getQueryAst(), res.getQueryPlan())); + } finally { + if (tracer != null && !tx.isInsideTransaction()) { + tracer.close(); + } } } @@ -188,9 +202,10 @@ public YdbQueryResult executeDataQuery(YdbStatement statement, YdbQuery query, S YdbValidator validator = statement.getValidator(); final Session session = tx.getSession(validator); + YdbTracer tracer = trace("--> data query >>\n" + yql); try { DataQueryResult result = validator.call( - QueryType.DATA_QUERY + " >>\n" + yql, + QueryType.DATA_QUERY + " >>\n" + yql, tracer, () -> session.executeDataQuery(yql, tx.txControl(), params, dataQuerySettings(timeout, keepInCache)) ); updateState(tx.withDataQuery(session, result.getTxId())); @@ -210,6 +225,14 @@ public YdbQueryResult executeDataQuery(YdbStatement statement, YdbQuery query, S } catch (SQLException | RuntimeException ex) { updateState(tx.withRollback(session)); throw ex; + } finally { + if (tracer != null) { + if (tx.isInsideTransaction()) { + tracer.setId(tx.txID()); + } else { + tracer.close(); + } + } } } @@ -221,7 +244,7 @@ public boolean isValid(YdbValidator validator, int timeout) throws SQLException try { KeepAliveSessionSettings settings = new KeepAliveSessionSettings().setTimeout(Duration.ofSeconds(timeout)); Session.State keepAlive = validator.call( - "Keep alive: " + tx.txID(), + "Keep alive: " + tx.txID(), null, () -> session.keepAlive(settings) ); return keepAlive == Session.State.READY; diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbContext.java b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbContext.java index 12f7aa1..56874c6 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbContext.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbContext.java @@ -159,6 +159,10 @@ public String getUsername() { return config.getUsername(); } + public boolean isTxTracerEnabled() { + return config.isTxTracedEnabled(); + } + public YdbExecutor createExecutor() throws SQLException { if (config.isUseQueryService()) { return new QueryServiceExecutor(this, operationProps.getTransactionLevel(), operationProps.isAutoCommit()); diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbExecutor.java b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbExecutor.java index fdf1feb..33e95ee 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbExecutor.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbExecutor.java @@ -3,6 +3,7 @@ import java.sql.SQLException; import tech.ydb.jdbc.YdbStatement; +import tech.ydb.jdbc.YdbTracer; import tech.ydb.jdbc.impl.YdbQueryResult; import tech.ydb.jdbc.query.YdbQuery; import tech.ydb.table.query.Params; @@ -41,4 +42,6 @@ YdbQueryResult executeDataQuery(YdbStatement statement, YdbQuery query, String y void rollback(YdbContext ctx, YdbValidator validator) throws SQLException; boolean isValid(YdbValidator validator, int timeout) throws SQLException; + + YdbTracer trace(String message); } diff --git a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java index 8bf1143..9a63566 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/context/YdbValidator.java @@ -12,6 +12,7 @@ import tech.ydb.core.Result; import tech.ydb.core.Status; import tech.ydb.core.UnexpectedResultException; +import tech.ydb.jdbc.YdbTracer; import tech.ydb.jdbc.exception.ExceptionFactory; /** @@ -49,20 +50,26 @@ public void clearWarnings() { this.issues.clear(); } - public void execute(String msg, Supplier> fn) throws SQLException { + public void execute(String msg, YdbTracer tracer, Supplier> fn) throws SQLException { Status status = fn.get().join(); addStatusIssues(status); + if (tracer != null) { + tracer.trace("<-- " + status.toString()); + } if (!status.isSuccess()) { throw ExceptionFactory.createException("Cannot execute '" + msg + "' with " + status, new UnexpectedResultException("Unexpected status", status)); } } - public R call(String msg, Supplier>> fn) throws SQLException { + public R call(String msg, YdbTracer tracer, Supplier>> fn) throws SQLException { try { Result result = fn.get().join(); addStatusIssues(result.getStatus()); + if (tracer != null) { + tracer.trace("<-- " + result.getStatus().toString()); + } return result.getValue(); } catch (UnexpectedResultException ex) { throw ExceptionFactory.createException("Cannot call '" + msg + "' with " + ex.getStatus(), ex); diff --git a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java index b84652e..c12d1f8 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbConnectionImpl.java @@ -26,6 +26,7 @@ import tech.ydb.jdbc.YdbPrepareMode; import tech.ydb.jdbc.YdbPreparedStatement; import tech.ydb.jdbc.YdbStatement; +import tech.ydb.jdbc.YdbTracer; import tech.ydb.jdbc.context.YdbContext; import tech.ydb.jdbc.context.YdbExecutor; import tech.ydb.jdbc.context.YdbValidator; @@ -108,6 +109,7 @@ public void close() throws SQLException { validator.clearWarnings(); executor.close(); ctx.deregister(); + YdbTracer.clear(); } @Override @@ -209,6 +211,7 @@ public int getHoldability() throws SQLException { public YdbStatement createStatement(int resultSetType, int resultSetConcurrency, int resultSetHoldability) throws SQLException { executor.ensureOpened(); + executor.trace("create statement"); checkStatementParams(resultSetType, resultSetConcurrency, resultSetHoldability); return new YdbStatementImpl(this, resultSetType); } @@ -239,9 +242,10 @@ private YdbPreparedStatement prepareStatement(String sql, int resultSetType, Ydb executor.ensureOpened(); validator.clearWarnings(); + executor.trace("--> prepare statement"); YdbQuery query = ctx.findOrParseYdbQuery(sql); - YdbPreparedQuery params = ctx.findOrPrepareParams(query, mode); + executor.trace("<-- OK"); return new YdbPreparedStatementImpl(this, query, params, resultSetType); } diff --git a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java index c5cb405..6914204 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/impl/YdbDatabaseMetaDataImpl.java @@ -1320,7 +1320,9 @@ private List listTables(Predicate filter) throws SQLException { } private List tables(String databasePrefix, String path, Predicate filter) throws SQLException { - ListDirectoryResult result = validator.call("List tables from " + path, () -> executor.listDirectory(path)); + ListDirectoryResult result = validator.call( + "List tables from " + path, null, () -> executor.listDirectory(path) + ); List tables = new ArrayList<>(); String pathPrefix = withSuffix(path); @@ -1352,7 +1354,7 @@ private TableDescription describeTable(String table) throws SQLException { String databaseWithSuffix = withSuffix(connection.getCtx().getDatabase()); - return validator.call("Describe table " + table, () -> executor + return validator.call("Describe table " + table, null, () -> executor .describeTable(databaseWithSuffix + table, settings) .thenApply(result -> { // ignore scheme errors like path not found diff --git a/jdbc/src/main/java/tech/ydb/jdbc/settings/YdbConfig.java b/jdbc/src/main/java/tech/ydb/jdbc/settings/YdbConfig.java index c8778ed..2dd320e 100644 --- a/jdbc/src/main/java/tech/ydb/jdbc/settings/YdbConfig.java +++ b/jdbc/src/main/java/tech/ydb/jdbc/settings/YdbConfig.java @@ -43,7 +43,9 @@ public class YdbConfig { static final YdbProperty FULLSCAN_DETECTOR_ENABLED = YdbProperty.bool( "jdbcFullScanDetector", "Enable analizator for collecting query stats", false ); - + static final YdbProperty TRANSACTION_TRACER = YdbProperty.bool( + "enableTxTracer", "Enable collecting of transaction execution traces", false + ); private final String url; private final String username; @@ -57,6 +59,7 @@ public class YdbConfig { private final int preparedStatementsCacheSize; private final boolean useQueryService; private final boolean fullScanDetectorEnabled; + private final boolean txTracerEnabled; private YdbConfig( String url, String safeUrl, String connectionString, String username, String password, Properties props @@ -71,6 +74,7 @@ private YdbConfig( this.preparedStatementsCacheSize = Math.max(0, PREPARED_STATEMENT_CACHE_SIZE.readValue(props).getValue()); this.useQueryService = USE_QUERY_SERVICE.readValue(props).getValue(); this.fullScanDetectorEnabled = FULLSCAN_DETECTOR_ENABLED.readValue(props).getValue(); + this.txTracerEnabled = TRANSACTION_TRACER.readValue(props).getValue(); } public Properties getSafeProps() { @@ -105,6 +109,10 @@ public boolean isFullScanDetectorEnabled() { return fullScanDetectorEnabled; } + public boolean isTxTracedEnabled() { + return txTracerEnabled; + } + static boolean isSensetive(String key) { return TOKEN_KEY.equalsIgnoreCase(key) || PASSWORD_KEY.equalsIgnoreCase(key); } diff --git a/jdbc/src/test/java/tech/ydb/jdbc/YdbDriverTablesTest.java b/jdbc/src/test/java/tech/ydb/jdbc/YdbDriverTablesTest.java index e1070f3..cce772f 100644 --- a/jdbc/src/test/java/tech/ydb/jdbc/YdbDriverTablesTest.java +++ b/jdbc/src/test/java/tech/ydb/jdbc/YdbDriverTablesTest.java @@ -26,7 +26,7 @@ public class YdbDriverTablesTest { @RegisterExtension private static final YdbHelperExtension ydb = new YdbHelperExtension(); - private static final JdbcUrlHelper jdbcURL = new JdbcUrlHelper(ydb); + private static final JdbcUrlHelper jdbcURL = new JdbcUrlHelper(ydb).withArg("enableTxTracer", "true"); private final static String ERROR_BULK_UNSUPPORTED = "BULK mode is available only for prepared statement with one UPSERT"; diff --git a/jdbc/src/test/java/tech/ydb/jdbc/impl/helper/JdbcConnectionExtention.java b/jdbc/src/test/java/tech/ydb/jdbc/impl/helper/JdbcConnectionExtention.java index 8ae3c52..6bcf666 100644 --- a/jdbc/src/test/java/tech/ydb/jdbc/impl/helper/JdbcConnectionExtention.java +++ b/jdbc/src/test/java/tech/ydb/jdbc/impl/helper/JdbcConnectionExtention.java @@ -39,6 +39,7 @@ private JdbcConnectionExtention(JdbcUrlHelper jdbcURL) { public JdbcConnectionExtention(YdbHelperExtension ydb, boolean autoCommit) { this(new JdbcUrlHelper(ydb) .withArg("failOnTruncatedResult", "true") + .withArg("enableTxTracer", "true") .withArg("autoCommit", String.valueOf(autoCommit)) // .withArg("useQueryService", "true") );