From d4729fa9c18b34bf3afc830f90baf04f47950721 Mon Sep 17 00:00:00 2001 From: Nikolai Amelichev Date: Fri, 30 May 2025 22:24:31 +0200 Subject: [PATCH] #143: Lazy and lenient logging of statements and statement parameters --- repository-inmemory/pom.xml | 14 +++ .../InMemoryRepositoryTransaction.java | 36 +++----- .../test/inmemory/InMemoryTable.java | 13 +-- repository-test/pom.xml | 4 + .../yoj/repository/test/RepositoryTest.java | 85 ++++++++++++++++--- .../repository/test/entity/TestEntities.java | 4 +- .../test/sample/model/BadToStringEntity.java | 34 ++++++++ repository-ydb-v2/pom.xml | 21 +++++ .../ydb/YdbRepositoryTransaction.java | 46 +++++----- .../ydb/statement/CountAllStatement.java | 5 +- .../ydb/statement/DeleteByIdStatement.java | 6 +- .../ydb/statement/FindInStatement.java | 53 ++++++------ .../ydb/statement/FindRangeStatement.java | 5 +- .../ydb/statement/FindStatement.java | 5 +- .../ydb/statement/FindYqlStatement.java | 5 +- .../ydb/statement/InsertYqlStatement.java | 6 +- .../statement/MultipleVarsYqlStatement.java | 12 +-- .../repository/ydb/statement/Statement.java | 6 +- .../ydb/statement/UpdateByIdStatement.java | 5 +- .../ydb/statement/UpdateInStatement.java | 5 +- .../ydb/statement/UpsertYqlStatement.java | 6 +- .../yoj/repository/ydb/table/YdbTable.java | 2 +- .../yoj/repository/ydb/yql/YqlPredicate.java | 36 ++++---- .../ydb/YdbRepositoryIntegrationTest.java | 2 +- .../ydb/statement/FindInStatementTest.java | 4 +- .../tech/ydb/yoj/repository/db/Table.java | 1 + .../tech/ydb/yoj/repository/db/TxImpl.java | 16 ++-- .../repository/db/cache/TransactionLog.java | 8 +- .../internal/RepositoryTransactionImpl.java | 31 +++++++ .../db/{ => internal}/TableQueryImpl.java | 9 +- .../repository/db/internal/package-info.java | 4 + .../ydb/yoj/util/function/LazyToString.java | 15 ++++ .../java/tech/ydb/yoj/util/lang/Strings.java | 22 +++++ 33 files changed, 367 insertions(+), 159 deletions(-) create mode 100644 repository-test/src/main/java/tech/ydb/yoj/repository/test/sample/model/BadToStringEntity.java create mode 100644 repository/src/main/java/tech/ydb/yoj/repository/db/internal/RepositoryTransactionImpl.java rename repository/src/main/java/tech/ydb/yoj/repository/db/{ => internal}/TableQueryImpl.java (91%) create mode 100644 repository/src/main/java/tech/ydb/yoj/repository/db/internal/package-info.java create mode 100644 util/src/main/java/tech/ydb/yoj/util/function/LazyToString.java diff --git a/repository-inmemory/pom.xml b/repository-inmemory/pom.xml index de850b8b..a2397d4e 100644 --- a/repository-inmemory/pom.xml +++ b/repository-inmemory/pom.xml @@ -60,6 +60,11 @@ log4j-core test + + org.apache.logging.log4j + log4j-jul + test + com.fasterxml.jackson.core @@ -79,6 +84,15 @@ org.apache.maven.plugins maven-jar-plugin + + org.apache.maven.plugins + maven-surefire-plugin + + + org.apache.logging.log4j.jul.LogManager + + + diff --git a/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryRepositoryTransaction.java b/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryRepositoryTransaction.java index 67e2d917..a336b288 100644 --- a/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryRepositoryTransaction.java +++ b/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryRepositoryTransaction.java @@ -1,7 +1,6 @@ package tech.ydb.yoj.repository.test.inmemory; import com.google.common.base.Stopwatch; -import com.google.common.collect.Iterables; import lombok.Getter; import tech.ydb.yoj.repository.BaseDb; import tech.ydb.yoj.repository.db.Entity; @@ -21,8 +20,12 @@ import java.util.function.Function; import java.util.function.Supplier; +import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.EMPTY_RESULT; +import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.logStatementError; +import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.logStatementResult; + public class InMemoryRepositoryTransaction implements BaseDb, RepositoryTransaction { - private final static AtomicLong txIdGenerator = new AtomicLong(); + private static final AtomicLong txIdGenerator = new AtomicLong(); private final long txId = txIdGenerator.incrementAndGet(); private final Stopwatch txStopwatch = Stopwatch.createStarted(); @@ -109,7 +112,7 @@ private void endTransaction(String action, Runnable runnable) { } } finally { closeAction = action; - transactionLocal.log().info("[[%s]] TOTAL (since tx start)", txStopwatch); + transactionLocal.log().info("[[%s]] TOTAL (since tx start)", txStopwatch.stop()); } } @@ -126,7 +129,7 @@ private boolean isFinalActionNeeded(String action) { } final > void doInWriteTransaction( - String log, TableDescriptor tableDescriptor, Consumer> consumer + Object action, TableDescriptor tableDescriptor, Consumer> consumer ) { if (options.isScan()) { throw new IllegalTransactionScanException("Mutable operations"); @@ -135,7 +138,7 @@ final > void doInWriteTransaction( throw new IllegalTransactionIsolationLevelException("Mutable operations", options.getIsolationLevel()); } - Runnable query = () -> logTransaction(log, () -> { + Runnable query = () -> logTransaction(action, () -> { WriteTxDataShard shard = storage.getWriteTxDataShard(tableDescriptor, txId, getVersion()); consumer.accept(shard); @@ -150,7 +153,7 @@ final > void doInWriteTransaction( } final , R> R doInTransaction( - String action, TableDescriptor tableDescriptor, Function, R> func + Object action, TableDescriptor tableDescriptor, Function, R> func ) { return logTransaction(action, () -> { InMemoryTxLockWatcher findWatcher = hasWrites ? watcher : InMemoryTxLockWatcher.NO_LOCKS; @@ -166,14 +169,14 @@ tableDescriptor, txId, getVersion(), findWatcher }); } - private void logTransaction(String action, Runnable runnable) { + private void logTransaction(Object action, Runnable runnable) { logTransaction(action, () -> { runnable.run(); - return null; + return EMPTY_RESULT; }); } - private R logTransaction(String action, Supplier supplier) { + private R logTransaction(Object action, Supplier supplier) { if (closeAction != null) { throw new IllegalStateException("Transaction already closed by " + closeAction); } @@ -181,22 +184,11 @@ private R logTransaction(String action, Supplier supplier) { Stopwatch sw = Stopwatch.createStarted(); try { R result = supplier.get(); - transactionLocal.log().debug("[ %s ] %s -> %s", sw, action, printResult(result)); + logStatementResult(transactionLocal.log(), sw.stop(), action, result); return result; } catch (Throwable t) { - transactionLocal.log().debug("[ %s ] %s => %s", sw, action, t); + logStatementError(transactionLocal.log(), sw.stop(), action, t); throw t; } } - - private String printResult(Object result) { - if (result instanceof Iterable) { - long size = Iterables.size((Iterable) result); - return size == 1 - ? String.valueOf(Iterables.getOnlyElement((Iterable) result)) - : "[" + size + "]"; - } else { - return String.valueOf(result); - } - } } diff --git a/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryTable.java b/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryTable.java index b4c2f084..c62a1ed3 100644 --- a/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryTable.java +++ b/repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryTable.java @@ -14,10 +14,10 @@ import tech.ydb.yoj.repository.db.Range; import tech.ydb.yoj.repository.db.Table; import tech.ydb.yoj.repository.db.TableDescriptor; -import tech.ydb.yoj.repository.db.TableQueryImpl; import tech.ydb.yoj.repository.db.ViewSchema; import tech.ydb.yoj.repository.db.cache.FirstLevelCache; import tech.ydb.yoj.repository.db.exception.IllegalTransactionIsolationLevelException; +import tech.ydb.yoj.repository.db.internal.TableQueryImpl; import tech.ydb.yoj.repository.db.list.InMemoryQueries; import tech.ydb.yoj.repository.db.readtable.ReadTableParams; import tech.ydb.yoj.repository.db.statement.Changeset; @@ -32,6 +32,7 @@ import static java.util.stream.Collectors.toList; import static java.util.stream.Collectors.toUnmodifiableMap; import static java.util.stream.Collectors.toUnmodifiableSet; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; public class InMemoryTable> implements Table { private final EntitySchema schema; @@ -178,7 +179,7 @@ public T find(Entity.Id id) { } return transaction.getTransactionLocal().firstLevelCache(tableDescriptor).get(id, __ -> { markKeyRead(id); - T entity = transaction.doInTransaction("find(" + id + ")", tableDescriptor, shard -> shard.find(id)); + T entity = transaction.doInTransaction(lazyDebugMsg("find(%s)", id), tableDescriptor, shard -> shard.find(id)); return postLoad(entity); }); } @@ -202,7 +203,7 @@ public V find(Class viewType, Entity.Id id) { } markKeyRead(id); - return transaction.doInTransaction("find(" + id + ")", tableDescriptor, shard -> shard.find(id, viewType)); + return transaction.doInTransaction(lazyDebugMsg("find(%s)", id), tableDescriptor, shard -> shard.find(id, viewType)); } @Override @@ -425,7 +426,7 @@ public > List findIds(Set ids) { public T insert(T tt) { T t = tt.preSave(); transaction.getWatcher().markRowRead(tableDescriptor, t.getId()); - transaction.doInWriteTransaction("insert(" + t + ")", tableDescriptor, shard -> shard.insert(t)); + transaction.doInWriteTransaction(lazyDebugMsg("insert(%s)", t), tableDescriptor, shard -> shard.insert(t)); transaction.getTransactionLocal().firstLevelCache(tableDescriptor).put(t); transaction.getTransactionLocal().projectionCache().save(t); return t; @@ -434,7 +435,7 @@ public T insert(T tt) { @Override public T save(T tt) { T t = tt.preSave(); - transaction.doInWriteTransaction("save(" + t + ")", tableDescriptor, shard -> shard.save(t)); + transaction.doInWriteTransaction(lazyDebugMsg("save(%s)", t), tableDescriptor, shard -> shard.save(t)); transaction.getTransactionLocal().firstLevelCache(tableDescriptor).put(t); transaction.getTransactionLocal().projectionCache().save(t); return t; @@ -442,7 +443,7 @@ public T save(T tt) { @Override public void delete(Entity.Id id) { - transaction.doInWriteTransaction("delete(" + id + ")", tableDescriptor, shard -> shard.delete(id)); + transaction.doInWriteTransaction(lazyDebugMsg("delete(%s)", id), tableDescriptor, shard -> shard.delete(id)); transaction.getTransactionLocal().firstLevelCache(tableDescriptor).putEmpty(id); transaction.getTransactionLocal().projectionCache().delete(id); } diff --git a/repository-test/pom.xml b/repository-test/pom.xml index 4d533140..9e09b6c2 100644 --- a/repository-test/pom.xml +++ b/repository-test/pom.xml @@ -45,6 +45,10 @@ org.eclipse.collections eclipse-collections + + org.apache.logging.log4j + log4j-core + com.fasterxml.jackson.core diff --git a/repository-test/src/main/java/tech/ydb/yoj/repository/test/RepositoryTest.java b/repository-test/src/main/java/tech/ydb/yoj/repository/test/RepositoryTest.java index ef2271d3..89e4e49b 100644 --- a/repository-test/src/main/java/tech/ydb/yoj/repository/test/RepositoryTest.java +++ b/repository-test/src/main/java/tech/ydb/yoj/repository/test/RepositoryTest.java @@ -4,6 +4,9 @@ import com.google.common.collect.Iterables; import com.google.common.collect.Iterators; import lombok.SneakyThrows; +import org.apache.logging.log4j.Level; +import org.apache.logging.log4j.core.LoggerContext; +import org.apache.logging.log4j.core.config.Configurator; import org.assertj.core.api.Assertions; import org.junit.Assert; import org.junit.Test; @@ -36,6 +39,7 @@ import tech.ydb.yoj.repository.test.sample.TestDb; import tech.ydb.yoj.repository.test.sample.TestDbImpl; import tech.ydb.yoj.repository.test.sample.TestEntityOperations; +import tech.ydb.yoj.repository.test.sample.model.BadToStringEntity; import tech.ydb.yoj.repository.test.sample.model.Book; import tech.ydb.yoj.repository.test.sample.model.Bubble; import tech.ydb.yoj.repository.test.sample.model.BytePkEntity; @@ -69,6 +73,7 @@ import tech.ydb.yoj.repository.test.sample.model.annotations.UniqueEntity; import tech.ydb.yoj.repository.test.sample.model.annotations.UniqueEntityNative; +import java.time.Duration; import java.time.Instant; import java.util.ArrayList; import java.util.Arrays; @@ -1655,24 +1660,22 @@ public void optimisticLockRead() { RepositoryTransaction tx1 = startTransaction(); tx1.table(Project.class).insert(new Project(new Project.Id("3"), "p3")); tx1.table(Project.class).find(new Project.Id("1")); - { - RepositoryTransaction tx2 = startTransaction(); - tx2.table(Project.class).save(new Project(new Project.Id("1"), "p1-1")); - tx2.commit(); - } + + RepositoryTransaction tx2 = startTransaction(); + tx2.table(Project.class).save(new Project(new Project.Id("1"), "p1-1")); + tx2.commit(); + // read object was touched -> rollback on any operation - //не prepare запросы валятся при обращении - //prepare запросы валятся на комите assertThatExceptionOfType(OptimisticLockException.class) .isThrownBy(() -> { - //не prepare запросы валятся при обращении + // non-prepared statements fail on statement execution try { tx1.table(Project.class).find(new Project.Id("1")); } catch (Exception e) { tx1.rollback(); throw e; } - //prepare запросы валятся на комите + // prepared statements fail on tx commit tx1.commit(); }); } @@ -2464,14 +2467,14 @@ public void noOptimisticLockOnScan() { tx2.commit(); } - //не prepare запросы не валятся при обращении + // non-prepared statements should not fail on statement execution, because scan reads from a database snapshot try { tx1.table(Project.class).find(new Project.Id("1")); } catch (Exception e) { tx1.rollback(); throw e; } - //prepare запросы не валятся на комите + // prepared statements should not fail on commit, because scan reads from a database snapshot tx1.commit(); } @@ -2953,8 +2956,66 @@ public void multiWrapperEntity2WithCustomConverterFullyWrapped() { )).isEmpty(); } + @Test + public void toStringThrows() { + var entity = new BadToStringEntity(new BadToStringEntity.Id("id"), null); + db.tx(() -> db.table(BadToStringEntity.class).save(entity)); + assertThatExceptionOfType(EntityAlreadyExistsException.class) + .isThrownBy(() -> db.withMaxRetries(0).tx(() -> db.table(BadToStringEntity.class).insert(entity))); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(entity.getId()))).isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(Set.of(entity.getId())))) + .singleElement().isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).query() + .ids(Set.of(entity.getId())) + .findOne()) + ).isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).query() + .where("id").in(entity.getId()) + .findOne()) + ).isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).query() + .where("id").eq(entity.getId()) + .and("toStringDuration").isNull() + .findOne()) + ).isEqualTo(entity); + } + + @Test(timeout = 30_000L) + public void toStringSlow() { + var loggerName = "tech.ydb.yoj.repository.db"; + var config = LoggerContext.getContext().getConfiguration(); + var prevLoggerLevel = config.getLoggerConfig(loggerName).getLevel(); + try { + Configurator.setLevel(loggerName, Level.ERROR); + + var entity = new BadToStringEntity(new BadToStringEntity.Id("id"), Duration.ofMinutes(5)); + db.tx(() -> db.table(BadToStringEntity.class).save(entity)); + assertThatExceptionOfType(EntityAlreadyExistsException.class) + .isThrownBy(() -> db.withMaxRetries(0).tx(() -> db.table(BadToStringEntity.class).insert(entity))); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(entity.getId()))).isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(Set.of(entity.getId())))) + .singleElement().isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).query() + .ids(Set.of(entity.getId())) + .findOne()) + ).isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).query() + .where("id").in(entity.getId()) + .findOne()) + ).isEqualTo(entity); + assertThat(db.tx(() -> db.table(BadToStringEntity.class).query() + .where("id").eq(entity.getId()) + .and("toStringDuration").isNotNull() + .findOne()) + ).isEqualTo(entity); + } finally { + Configurator.setLevel(loggerName, prevLoggerLevel); + } + } + protected void runInTx(Consumer action) { - // We do not retry transactions, because we do not expect conflicts in our test scenarios. + // We do *not* retry low-level transactions (`RepositoryTransaction`s) because we don't expect to get conflicts + // in our test scenarios RepositoryTransaction transaction = startTransaction(); try { action.accept(transaction); diff --git a/repository-test/src/main/java/tech/ydb/yoj/repository/test/entity/TestEntities.java b/repository-test/src/main/java/tech/ydb/yoj/repository/test/entity/TestEntities.java index e8ba3750..3b11279b 100644 --- a/repository-test/src/main/java/tech/ydb/yoj/repository/test/entity/TestEntities.java +++ b/repository-test/src/main/java/tech/ydb/yoj/repository/test/entity/TestEntities.java @@ -4,6 +4,7 @@ import tech.ydb.yoj.repository.db.Entity; import tech.ydb.yoj.repository.db.Repository; import tech.ydb.yoj.repository.db.TableDescriptor; +import tech.ydb.yoj.repository.test.sample.model.BadToStringEntity; import tech.ydb.yoj.repository.test.sample.model.Book; import tech.ydb.yoj.repository.test.sample.model.Bubble; import tech.ydb.yoj.repository.test.sample.model.BytePkEntity; @@ -62,7 +63,8 @@ private TestEntities() { MultiWrappedEntity.class, MultiWrappedEntity2.class, UniqueEntity.class, - UniqueEntityNative.class + UniqueEntityNative.class, + BadToStringEntity.class ); public static final List> ALL_TABLE_DESCRIPTORS = List.of( diff --git a/repository-test/src/main/java/tech/ydb/yoj/repository/test/sample/model/BadToStringEntity.java b/repository-test/src/main/java/tech/ydb/yoj/repository/test/sample/model/BadToStringEntity.java new file mode 100644 index 00000000..d1691c03 --- /dev/null +++ b/repository-test/src/main/java/tech/ydb/yoj/repository/test/sample/model/BadToStringEntity.java @@ -0,0 +1,34 @@ +package tech.ydb.yoj.repository.test.sample.model; + +import com.google.common.util.concurrent.Uninterruptibles; +import lombok.EqualsAndHashCode; +import lombok.NonNull; +import lombok.Value; +import tech.ydb.yoj.repository.db.Entity; + +import javax.annotation.Nullable; +import java.time.Duration; +import java.util.Objects; + +@Value +@EqualsAndHashCode(doNotUseGetters = true) +public class BadToStringEntity implements Entity { + @NonNull + Id id; + + @Nullable + Duration toStringDuration; + + @SuppressWarnings("unused") + public Duration getToStringDuration() { + // Mwahahahahahah #1: NPE if a nullable field is null + Objects.requireNonNull(toStringDuration, "toStringDuration"); + // Mwahahahahahah #2: Delay if a nullable field is not null + Uninterruptibles.sleepUninterruptibly(toStringDuration); + + return toStringDuration; + } + + public record Id(@NonNull String id) implements Entity.Id { + } +} diff --git a/repository-ydb-v2/pom.xml b/repository-ydb-v2/pom.xml index 968bbba5..57409ce0 100644 --- a/repository-ydb-v2/pom.xml +++ b/repository-ydb-v2/pom.xml @@ -142,6 +142,16 @@ log4j-slf4j-impl test + + org.apache.logging.log4j + log4j-core + test + + + org.apache.logging.log4j + log4j-jul + test + com.fasterxml.jackson.core jackson-databind @@ -166,5 +176,16 @@ os-maven-plugin + + + org.apache.maven.plugins + maven-surefire-plugin + + + org.apache.logging.log4j.jul.LogManager + + + + diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/YdbRepositoryTransaction.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/YdbRepositoryTransaction.java index b8c60d2e..f0906e33 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/YdbRepositoryTransaction.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/YdbRepositoryTransaction.java @@ -2,7 +2,6 @@ import com.google.common.base.Preconditions; import com.google.common.base.Stopwatch; -import com.google.common.collect.Iterables; import io.grpc.Context; import io.grpc.Deadline; import lombok.Getter; @@ -88,8 +87,13 @@ import static java.lang.String.format; import static java.util.stream.Collectors.toList; import static lombok.AccessLevel.PRIVATE; +import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.EMPTY_RESULT; +import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.logStatementError; +import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.logStatementResult; import static tech.ydb.yoj.repository.ydb.client.YdbValidator.validatePkConstraint; import static tech.ydb.yoj.repository.ydb.client.YdbValidator.validateTruncatedResults; +import static tech.ydb.yoj.util.lang.Strings.debugResult; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; public class YdbRepositoryTransaction implements BaseDb, RepositoryTransaction, YdbTable.QueryExecutor { @@ -151,16 +155,16 @@ public void commit() { rollback(); throw t; } - endTransaction("commit", this::doCommit); + endTransaction("commit()", this::doCommit); } @Override public void rollback() { Interrupts.runInCleanupMode(() -> { try { - endTransaction("rollback", () -> { + endTransaction("rollback()", () -> { Status status = YdbOperations.safeJoin(session.rollbackTransaction(txId, new RollbackTxSettings())); - validate("rollback", status.getCode(), status.toString()); + validate("rollback()", status.getCode(), status.toString()); }); } catch (Throwable t) { log.info("Failed to rollback the transaction", t); @@ -172,7 +176,7 @@ private void doCommit() { try { Status status = YdbOperations.safeJoin(session.commitTransaction(txId, new CommitTxSettings())); validatePkConstraint(status.getIssues()); - validate("commit", status.getCode(), status.toString()); + validate("commit()", status.getCode(), status.toString()); } catch (YdbComponentUnavailableException | YdbOverloadedException e) { throw new UnavailableException("Unknown transaction state: commit was sent, but result is unknown", e); } @@ -243,7 +247,7 @@ private void endTransaction(String actionName, Runnable finalAction) { } finally { closeAction = actionName; if (session != null) { - transactionLocal.log().info("[[%s]] TOTAL (txId=%s,sessionId=%s)", sessionSw, firstNonNullTxId, session.getId()); + transactionLocal.log().info("[[%s]] TOTAL (txId=%s,sessionId=%s)", sessionSw.stop(), firstNonNullTxId, session.getId()); // NB: We use getSessionManager() method to allow mocking YdbRepository repo.getSessionManager().release(session); session = null; @@ -285,17 +289,19 @@ private void flushPendingWrites() { @Override public List execute(Statement statement, PARAMS params) { + Object action = statement.toDebugString(params); + + Stopwatch cacheSw = Stopwatch.createStarted(); List result = statement.readFromCache(params, cache); if (result != null) { - String actionStr = statement.toDebugString(params); - String resultStr = debugResult(result); - transactionLocal.log().debug("[statement cache] %s -> %s", actionStr, resultStr); + Object cacheAction = lazyDebugMsg("[statement cache] %s", action); + logStatementResult(transactionLocal.log(), cacheSw.stop(), cacheAction, result); return result; } Exception thrown = null; try { - result = doCall(statement.toDebugString(params), () -> { + result = doCall(action, () -> { if (options.isScan()) { return options.getScanOptions().isUseNewSpliterator() ? doExecuteScanQueryList(statement, params) @@ -609,7 +615,7 @@ public CompletableFuture getStatusFuture() { private void doCall(String actionStr, Runnable call) { doCall(actionStr, () -> { call.run(); - return null; + return EMPTY_RESULT; }); } @@ -624,29 +630,17 @@ private void initSession() { } } - private R doCall(String actionStr, Supplier call) { + private R doCall(Object action, Supplier call) { initSession(); Stopwatch sw = Stopwatch.createStarted(); - String resultStr = ""; try { R result = call.get(); - resultStr = (result == null ? "" : " -> " + debugResult(result)); + logStatementResult(transactionLocal.log(), sw.stop(), action, result); return result; } catch (Exception e) { - resultStr = " => " + e.getClass().getName(); + logStatementError(transactionLocal.log(), sw.stop(), action, e); throw e; - } finally { - transactionLocal.log().debug("[ %s ] %s", sw, actionStr + resultStr); - } - } - - private static String debugResult(Object result) { - if (result instanceof Iterable) { - int size = Iterables.size((Iterable) result); - return size == 1 ? String.valueOf(((Iterable) result).iterator().next()) : "[" + size + "]"; - } else { - return String.valueOf(result); } } diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/CountAllStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/CountAllStatement.java index b4b8985c..226c169f 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/CountAllStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/CountAllStatement.java @@ -12,6 +12,7 @@ import static java.util.Comparator.comparing; import static java.util.stream.Collectors.joining; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; public class CountAllStatement> extends PredicateStatement>, ENTITY, Count> { private final List> parts; @@ -41,7 +42,7 @@ public QueryType getQueryType() { } @Override - public String toDebugString(Collection> yqlStatementParts) { - return "count(" + parts + ")"; + public Object toDebugString(Collection> yqlStatementParts) { + return parts.isEmpty() ? "count()" : lazyDebugMsg("count(%s)", parts); } } diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/DeleteByIdStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/DeleteByIdStatement.java index f3172fcd..c00419f6 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/DeleteByIdStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/DeleteByIdStatement.java @@ -7,6 +7,8 @@ import java.util.Map; import java.util.function.Function; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; + public class DeleteByIdStatement> extends MultipleVarsYqlStatement.Simple { public DeleteByIdStatement(TableDescriptor tableDescriptor, EntitySchema schema) { super(tableDescriptor, schema); @@ -30,7 +32,7 @@ protected Function> flattenInputVariables() { } @Override - public String toDebugString(IN in) { - return "delete(" + toDebugParams(in) + ")"; + public Object toDebugString(IN in) { + return lazyDebugMsg("delete(%s)", toDebugParams(in)); } } diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindInStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindInStatement.java index b550e5a2..a8e652dd 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindInStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindInStatement.java @@ -33,6 +33,7 @@ import static java.util.stream.Collectors.toCollection; import static java.util.stream.Collectors.toUnmodifiableMap; import static java.util.stream.Collectors.toUnmodifiableSet; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; /** *

Creates statement for {@code SELECT ... WHERE PK IN (PK1, PK2, ...)}. {@code PK} can be both @@ -114,7 +115,7 @@ public final class FindInStatement, RESULT> extends Mult private final String indexName; private final Schema keySchema; private final Set keyFields; - private final PredicateClause predicate; + private final PredicateClause predicateClause; private final OrderExpression orderBy; private final Integer limit; @@ -183,9 +184,9 @@ private FindInStatement( this.keySchema = keySchema; this.keyFields = keyFields; if (filter != null) { - this.predicate = new PredicateClause<>(tableDescriptor, schema, YqlListingQuery.toYqlPredicate(filter)); + this.predicateClause = new PredicateClause<>(tableDescriptor, schema, YqlListingQuery.toYqlPredicate(filter)); } else { - this.predicate = null; + this.predicateClause = null; } validateOrderByFields(); @@ -332,11 +333,11 @@ public QueryType getQueryType() { public String getQuery(String tablespace) { return declarations() + "SELECT " + outNames() + "\n" + - (hasPredicate() ? "FROM (\nSELECT " + allColumnNames() + "\n" : "") + + (hasPredicateClause() ? "FROM (\nSELECT " + allColumnNames() + "\n" : "") + "FROM AS_TABLE(" + listName + ") AS k\n" + "JOIN " + table(tablespace) + indexUsage() + " AS t\n" + "ON " + joinExpression() + "\n" + - (hasPredicate() ? ")\n" : "") + + (hasPredicateClause() ? ")\n" : "") + predicateClause() + orderByClause() + limitClause(); @@ -352,10 +353,10 @@ public List getParams() { @Override public Map toQueryParameters(IN in) { - if (hasPredicate()) { + if (hasPredicateClause()) { return ImmutableMap.builder() .putAll(super.toQueryParameters(in)) - .putAll(predicate.toQueryParameters()) + .putAll(predicateClause.toQueryParameters()) .build(); } @@ -381,7 +382,7 @@ private String allColumnNames() { } private String getOutName(JavaField field) { - return hasPredicate() ? escape(field.getName()) : getAliasedName(field); + return hasPredicateClause() ? escape(field.getName()) : getAliasedName(field); } private String getAliasedName(JavaField field) { @@ -415,21 +416,21 @@ private String limitClause() { } private String predicateClauseDeclarations() { - return hasPredicate() ? predicate.declarations() : ""; + return hasPredicateClause() ? predicateClause.declarations() : ""; } private String predicateClause() { - return hasPredicate() ? predicate.getClause() : ""; + return hasPredicateClause() ? predicateClause.getClause() : ""; } @Override - public String toDebugString(IN in) { - return "findIn(" + toDebugParams(in) + - (isFindByIndex() ? " by index " + escape(indexName) : "") + - (hasPredicate() ? ", filter [" + predicate.toDebugString() + "]" : "") + - (hasOrderBy() ? ", orderBy [" + orderBy + "]" : "") + - (hasLimit() ? ", limit [" + limit + "]" : "") + - ")"; + public Object toDebugString(IN in) { + return lazyDebugMsg("findIn(%s%s%s%s%s)", + toDebugParams(in), + (isFindByIndex() ? ", index [" + indexName + "]" : ""), + (hasPredicateClause() ? lazyDebugMsg(", filter [%s]", predicateClause.predicate) : ""), + (hasOrderBy() ? ", orderBy [" + orderBy + "]" : ""), + (hasLimit() ? ", limit [" + limit + "]" : "")); } private boolean isFindByIndex() { @@ -444,16 +445,15 @@ private boolean hasOrderBy() { return orderBy != null; } - private boolean hasPredicate() { - return predicate != null; + private boolean hasPredicateClause() { + return predicateClause != null; } - private static class PredicateClause> extends PredicateStatement, T, T> { + private static final class PredicateClause> extends PredicateStatement, T, T> { private final YqlPredicate predicate; public PredicateClause(TableDescriptor tableDescriptor, EntitySchema schema, YqlPredicate predicate) { super(tableDescriptor, schema, schema, Void.class, __ -> predicate); - this.predicate = predicate; } @@ -468,11 +468,12 @@ public String getClause() { @Override public String getQuery(String tablespace) { - return "SELECT 1"; + throw new UnsupportedOperationException("FindInStatement.PredicateClause.getQuery()"); } - public String toDebugString() { - return toDebugString(Void.TYPE); + @Override + public String toString() { + return "FindInStatement.PredicateClause[" + predicate + "]"; } public Map toQueryParameters() { @@ -480,8 +481,8 @@ public Map toQueryParameters() { } @Override - public String toDebugString(Class in) { - return predicate.toString(); + public Object toDebugString(Class in) { + throw new UnsupportedOperationException("FindInStatement.PredicateClause.toDebugString()"); } } } diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindRangeStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindRangeStatement.java index d85775c4..7d391a61 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindRangeStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindRangeStatement.java @@ -19,6 +19,7 @@ import static java.util.stream.Collectors.joining; import static java.util.stream.Collectors.toList; import static java.util.stream.Collectors.toMap; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; public class FindRangeStatement, ID extends Entity.Id, RESULT> extends YqlStatement, ENTITY, RESULT> { @Getter @@ -58,8 +59,8 @@ public QueryType getQueryType() { } @Override - public String toDebugString(Range idRange) { - return "find(" + idRange + ")"; + public Object toDebugString(Range idRange) { + return lazyDebugMsg("find(%s)", idRange); } @Override diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindStatement.java index b972ad30..cca9e8d3 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindStatement.java @@ -15,6 +15,7 @@ import static java.util.Comparator.comparing; import static java.util.stream.Collectors.joining; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; public class FindStatement, RESULT> extends PredicateStatement>, ENTITY, RESULT> { private final boolean distinct; @@ -67,7 +68,7 @@ public Statement.QueryType getQueryType() { } @Override - public String toDebugString(Collection> yqlStatementParts) { - return "find(" + yqlStatementParts + ")"; + public Object toDebugString(Collection> yqlStatementParts) { + return yqlStatementParts.isEmpty() ? "find()" : lazyDebugMsg("find(%s)", yqlStatementParts); } } diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindYqlStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindYqlStatement.java index efec47c1..af8fc113 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindYqlStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/FindYqlStatement.java @@ -11,6 +11,7 @@ import java.util.List; import static java.util.stream.Collectors.toList; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; public class FindYqlStatement, RESULT> extends YqlStatement { public FindYqlStatement( @@ -59,7 +60,7 @@ public QueryType getQueryType() { } @Override - public String toDebugString(PARAMS params) { - return "find(" + params + ")"; + public Object toDebugString(PARAMS params) { + return lazyDebugMsg("find(%s)", params); } } diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/InsertYqlStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/InsertYqlStatement.java index fee20394..d69e2215 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/InsertYqlStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/InsertYqlStatement.java @@ -7,6 +7,8 @@ import java.util.Map; import java.util.function.Function; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; + public class InsertYqlStatement> extends MultipleVarsYqlStatement.Simple { public InsertYqlStatement(TableDescriptor tableDescriptor, EntitySchema schema) { super(tableDescriptor, schema); @@ -18,8 +20,8 @@ public QueryType getQueryType() { } @Override - public String toDebugString(PARAMS params) { - return "insert(" + toDebugParams(params) + ")"; + public Object toDebugString(PARAMS params) { + return lazyDebugMsg("insert(%s)", toDebugParams(params)); } @Override diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/MultipleVarsYqlStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/MultipleVarsYqlStatement.java index 81d132e6..77c9a947 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/MultipleVarsYqlStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/MultipleVarsYqlStatement.java @@ -18,6 +18,7 @@ import static java.util.stream.Collectors.joining; import static java.util.stream.Collectors.toList; import static tech.ydb.yoj.repository.db.EntityIdSchema.isIdField; +import static tech.ydb.yoj.util.lang.Strings.debugResult; public abstract class MultipleVarsYqlStatement, RESULT> extends YqlStatement { public static final String listName = "$Input"; @@ -90,15 +91,8 @@ public Map toQueryParameters(PARAMS params) { protected abstract Function> flattenInputVariables(); - protected String toDebugParams(PARAMS params) { - if (params instanceof Collection c) { - return switch (c.size()) { - case 0 -> "[]"; - case 1 -> "[" + c.iterator().next() + "]"; - default -> "[" + c.iterator().next() + ",...](" + c.size() + ")"; - }; - } - return String.valueOf(params); + protected Object toDebugParams(PARAMS params) { + return debugResult(params); } public abstract static class Simple> diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/Statement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/Statement.java index ee850be3..15430b47 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/Statement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/Statement.java @@ -39,13 +39,15 @@ default boolean isPreparable() { String getQuery(String tablespace); /** - * Returns debug representation of this query with the specified parameter values. + * Returns a debug representation (possibly a lazy one) of this query with the specified parameter values. + * Calling {@code toString()} on the debug representation will return a {@code String} with a textual representation + * of the statement and its parameters. * * @param params parameter values. * Might be {@code null} depending on the statement type, e.g. for DELETE statements. * @return debug representation of the query parameterized with {@code params} */ - String toDebugString(PARAMS params); + Object toDebugString(PARAMS params); // Parameters diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateByIdStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateByIdStatement.java index 543b38f5..43179f15 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateByIdStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateByIdStatement.java @@ -18,6 +18,7 @@ import static java.util.stream.Collectors.toMap; import static java.util.stream.Collectors.toUnmodifiableSet; import static java.util.stream.Stream.concat; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; /** * @deprecated Blindly setting entity fields is not recommended. Use {@code Table.modifyIfPresent()} instead, unless you @@ -70,8 +71,8 @@ public QueryType getQueryType() { } @Override - public String toDebugString(UpdateModel.ById idById) { - return "updateById(" + idById.getId() + ")"; + public Object toDebugString(UpdateModel.ById idById) { + return lazyDebugMsg("updateById(%s)", idById.getId()); } @Override diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateInStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateInStatement.java index 77b6c0d3..562b5c33 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateInStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpdateInStatement.java @@ -21,6 +21,7 @@ import static java.util.stream.Collectors.joining; import static java.util.stream.Collectors.toMap; import static java.util.stream.Collectors.toUnmodifiableSet; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; /** *

Creates statement for {@code UPDATE table SET values=values WHERE PK IN (PK1, PK2, ...)}.

@@ -172,8 +173,8 @@ private String getEscapedName(JavaField field) { } @Override - public String toDebugString(UpdateInStatementInput in) { - return String.format("updateIn(%s)", in); + public Object toDebugString(UpdateInStatementInput in) { + return lazyDebugMsg("updateIn(%s)", in); } private Set nonNullFieldNames(Entity.Id id) { diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpsertYqlStatement.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpsertYqlStatement.java index 66dd1ca4..7554befa 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpsertYqlStatement.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/statement/UpsertYqlStatement.java @@ -7,6 +7,8 @@ import java.util.Map; import java.util.function.Function; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; + public class UpsertYqlStatement> extends MultipleVarsYqlStatement.Simple { public UpsertYqlStatement(TableDescriptor tableDescriptor, EntitySchema schema) { super(tableDescriptor, schema); @@ -18,8 +20,8 @@ public QueryType getQueryType() { } @Override - public String toDebugString(IN in) { - return "upsert(" + toDebugParams(in) + ")"; + public Object toDebugString(IN in) { + return lazyDebugMsg("upsert(%s)", toDebugParams(in)); } @Override diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/table/YdbTable.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/table/YdbTable.java index b6c2d3ab..6b103ccf 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/table/YdbTable.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/table/YdbTable.java @@ -14,12 +14,12 @@ import tech.ydb.yoj.repository.db.Range; import tech.ydb.yoj.repository.db.Table; import tech.ydb.yoj.repository.db.TableDescriptor; -import tech.ydb.yoj.repository.db.TableQueryImpl; import tech.ydb.yoj.repository.db.Tx; import tech.ydb.yoj.repository.db.ViewSchema; import tech.ydb.yoj.repository.db.bulk.BulkParams; import tech.ydb.yoj.repository.db.cache.FirstLevelCache; import tech.ydb.yoj.repository.db.cache.TransactionLocal; +import tech.ydb.yoj.repository.db.internal.TableQueryImpl; import tech.ydb.yoj.repository.db.readtable.ReadTableParams; import tech.ydb.yoj.repository.db.statement.Changeset; import tech.ydb.yoj.repository.ydb.bulk.BulkMapper; diff --git a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/yql/YqlPredicate.java b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/yql/YqlPredicate.java index 5e4eb9f0..a1089ca3 100644 --- a/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/yql/YqlPredicate.java +++ b/repository-ydb-v2/src/main/java/tech/ydb/yoj/repository/ydb/yql/YqlPredicate.java @@ -1,6 +1,7 @@ package tech.ydb.yoj.repository.ydb.yql; import com.google.common.base.Preconditions; +import com.google.common.base.Strings; import com.google.common.collect.ImmutableList; import lombok.AllArgsConstructor; import lombok.NonNull; @@ -398,7 +399,7 @@ private String fieldToYql(EntitySchema.JavaField field) { @Override public String toString() { - return format("%s %s %s", fieldPath, rel, param.getValue()); + return Strings.lenientFormat("%s %s %s", fieldPath, rel, param.getValue()); } } @@ -457,7 +458,7 @@ public > String toYql(@NonNull EntitySchema schema) { @Override public String toString() { - return format("%s %s %s", fieldPath, rel, param.getValue()); + return Strings.lenientFormat("%s %s %s", fieldPath, rel, param.getValue()); } } @@ -564,7 +565,7 @@ public > String toYql(@NonNull EntitySchema schema) { @Override public String toString() { - return format("%s %s %s%s", fieldPath, type, param.getValue(), escape == null ? "" : " ESCAPE " + escape); + return Strings.lenientFormat("%s %s %s%s", fieldPath, type, param.getValue(), escape == null ? "" : " ESCAPE " + escape); } public enum Type { @@ -643,7 +644,7 @@ public List> paramList() { @Override public > String toYql(@NonNull EntitySchema schema) { if (isEmpty()) { - return alwaysFalse().toString(); + return alwaysFalse().toYql(schema); } EntitySchema.JavaField field = schema.getField(fieldPath); @@ -669,9 +670,8 @@ private boolean isEmpty() { @Override public String toString() { - return format("%s %s (%s)", fieldPath, inType, param.getValue()); + return Strings.lenientFormat("%s %s (%s)", fieldPath, inType, param.getValue()); } - } @AllArgsConstructor(access = PRIVATE) @@ -703,7 +703,7 @@ public List> paramList() { @Override public > String toYql(@NonNull EntitySchema schema) { if (isEmpty()) { - return alwaysFalse().toString(); + return alwaysFalse().toYql(schema); } EntitySchema.JavaField field = schema.getField(fieldPath); @@ -735,7 +735,7 @@ private boolean isEmpty() { @Override public String toString() { - return format("%s %s (%s)", fieldPath, inType, param.getValue()); + return Strings.lenientFormat("%s %s (%s)", fieldPath, inType, param.getValue()); } } @@ -760,19 +760,15 @@ public > String toYql(@NonNull EntitySchema schema) { @Override public YqlPredicate negate() { - switch (type) { - case IS_NULL: - return new IsNullPredicate(fieldPath, IS_NOT_NULL); - case IS_NOT_NULL: - return new IsNullPredicate(fieldPath, IS_NULL); - default: - throw new UnsupportedOperationException("This should never happen"); - } + return switch (type) { + case IS_NULL -> new IsNullPredicate(fieldPath, IS_NOT_NULL); + case IS_NOT_NULL -> new IsNullPredicate(fieldPath, IS_NULL); + }; } @Override public String toString() { - return format("%s %s", fieldPath, type); + return Strings.lenientFormat("%s %s", fieldPath, type); } /*package*/ enum IsNullType { @@ -834,7 +830,7 @@ public > String toYql(@NonNull EntitySchema schema) { @Override public String toString() { - return predicates.stream().map(p -> format("(%s)", p)).collect(joining(" && ")); + return predicates.stream().map(p -> "(" + p + ")").collect(joining(" && ")); } } @@ -879,7 +875,7 @@ public > String toYql(@NonNull EntitySchema schema) { @Override public String toString() { - return predicates.stream().map(p -> format("(%s)", p)).collect(joining(" || ")); + return predicates.stream().map(p -> "(" + p + ")").collect(joining(" || ")); } } @@ -912,7 +908,7 @@ public > String toYql(@NonNull EntitySchema schema) { @Override public String toString() { - return format("!(%s)", opposite); + return "!(" + opposite + ")"; } } diff --git a/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/YdbRepositoryIntegrationTest.java b/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/YdbRepositoryIntegrationTest.java index 817a1540..b04e04b1 100644 --- a/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/YdbRepositoryIntegrationTest.java +++ b/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/YdbRepositoryIntegrationTest.java @@ -216,7 +216,7 @@ public String getQuery(String tablespace) { @Override public String toDebugString(Object o) { - return null; + return "readYqlListAndMap"; } @Override diff --git a/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/statement/FindInStatementTest.java b/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/statement/FindInStatementTest.java index 89cc6499..604b74b1 100644 --- a/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/statement/FindInStatementTest.java +++ b/repository-ydb-v2/src/test/java/tech/ydb/yoj/repository/ydb/statement/FindInStatementTest.java @@ -92,7 +92,7 @@ public void testToDebugString() { ENTITY_SCHEMA, ENTITY_SCHEMA, IDS, null, null, null ); - assertThat(statement.toDebugString(IDS)).isNotBlank(); + assertThat(statement.toDebugString(IDS)).asString().isNotBlank(); } @Test @@ -101,7 +101,7 @@ public void testToDebugStringWithOrder() { ENTITY_SCHEMA, ENTITY_SCHEMA, IDS, null, DEFAULT_ORDER, null ); - assertThat(statement.toDebugString(IDS)).isNotBlank(); + assertThat(statement.toDebugString(IDS)).asString().isNotBlank(); } @Test diff --git a/repository/src/main/java/tech/ydb/yoj/repository/db/Table.java b/repository/src/main/java/tech/ydb/yoj/repository/db/Table.java index ae23b01d..9f705a60 100644 --- a/repository/src/main/java/tech/ydb/yoj/repository/db/Table.java +++ b/repository/src/main/java/tech/ydb/yoj/repository/db/Table.java @@ -5,6 +5,7 @@ import tech.ydb.yoj.databind.expression.FilterExpression; import tech.ydb.yoj.databind.expression.OrderExpression; import tech.ydb.yoj.repository.db.bulk.BulkParams; +import tech.ydb.yoj.repository.db.internal.TableQueryImpl; import tech.ydb.yoj.repository.db.list.ListRequest; import tech.ydb.yoj.repository.db.list.ListResult; import tech.ydb.yoj.repository.db.list.ViewListResult; diff --git a/repository/src/main/java/tech/ydb/yoj/repository/db/TxImpl.java b/repository/src/main/java/tech/ydb/yoj/repository/db/TxImpl.java index 19df3a37..0b0f6086 100644 --- a/repository/src/main/java/tech/ydb/yoj/repository/db/TxImpl.java +++ b/repository/src/main/java/tech/ydb/yoj/repository/db/TxImpl.java @@ -11,6 +11,8 @@ import java.util.List; import java.util.function.Supplier; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; + final class TxImpl implements Tx { private static final Logger log = LoggerFactory.getLogger(TxImpl.class); @@ -79,15 +81,15 @@ private R runImpl(Supplier supplier) { res = supplier.get(); deferredBeforeCommit.forEach(Runnable::run); } catch (Throwable t) { + var logLines = formatExecutionLogMultiline("! "); doRollback(isBusinessException(t), - String.format("[%s] runInTx(): Rollback as inconsistent with business exception %s%s", sw, t, formatExecutionLogMultiline("! "))); - log.debug("[{}] runInTx(): Rollback due to {}{}", sw, t, formatExecutionLogMultiline("! "), t); + lazyDebugMsg("[%s] runInTx(): Rollback as inconsistent with business exception %s%s", sw, t, logLines)); + log.debug("[{}] runInTx(): Rollback due to {}{}", sw, t, logLines, t); throw t; } if (dryRun) { - doRollback(true, - String.format("[%s]" + "runInTx(): Rollback because dry-run transaction read inconsistent data", sw)); + doRollback(true, lazyDebugMsg("[%s] runInTx(): Rollback because dry-run transaction read inconsistent data", sw)); log.debug("[{}] runInTx(): Rollback due to dry-run mode {}", sw, formatExecutionLogMultiline("# ")); return res; } @@ -104,7 +106,7 @@ private R runImpl(Supplier supplier) { return res; } - private void doRollback(boolean isBusinessException, String businessExceptionLogMessage) { + private void doRollback(boolean isBusinessException, Object businessExceptionLogMessage) { try { // Note that should we catch an InterruptedException from any place other than the transaction methods, // the transaction will remain in 'executed normally' state so the rollback call will go @@ -112,7 +114,7 @@ private void doRollback(boolean isBusinessException, String businessExceptionLog repositoryTransaction.rollback(); } catch (OptimisticLockException optimisticRollbackException) { if (isBusinessException) { - log.debug(businessExceptionLogMessage); + log.debug("{}", businessExceptionLogMessage); throw optimisticRollbackException; } } @@ -122,7 +124,7 @@ private boolean isBusinessException(Throwable th) { return !Interrupts.isInterruptException(th); } - private String formatExecutionLogMultiline(String prefix) { + private Object formatExecutionLogMultiline(String prefix) { return repositoryTransaction.getTransactionLocal().log().format(prefix); } } diff --git a/repository/src/main/java/tech/ydb/yoj/repository/db/cache/TransactionLog.java b/repository/src/main/java/tech/ydb/yoj/repository/db/cache/TransactionLog.java index 48ca43e3..4d5a71b1 100644 --- a/repository/src/main/java/tech/ydb/yoj/repository/db/cache/TransactionLog.java +++ b/repository/src/main/java/tech/ydb/yoj/repository/db/cache/TransactionLog.java @@ -3,6 +3,7 @@ import lombok.NonNull; import lombok.RequiredArgsConstructor; import tech.ydb.yoj.InternalApi; +import tech.ydb.yoj.util.function.LazyToString; import java.util.ArrayList; import java.util.List; @@ -11,6 +12,7 @@ import static java.util.stream.Collectors.joining; import static tech.ydb.yoj.repository.db.cache.TransactionLog.Level.DEBUG; import static tech.ydb.yoj.repository.db.cache.TransactionLog.Level.INFO; +import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg; @RequiredArgsConstructor public final class TransactionLog { @@ -46,7 +48,7 @@ public void info(@NonNull String message, Object... args) { private void log(@NonNull Level level, @NonNull String message, Object... args) { if (logLevel.acceptsMessageAt(level)) { - log0(args.length == 0 ? message : String.format(message, args)); + log0(args.length == 0 ? message : lazyDebugMsg(message, args)); } } @@ -71,8 +73,8 @@ private void log0(@NonNull List messages) { } @InternalApi - public String format(@NonNull String prefix) { - return messages.stream().map(l -> "\n " + prefix + l).collect(joining()); + public Object format(@NonNull String prefix) { + return LazyToString.of(() -> messages.stream().map(l -> "\n " + prefix + l).collect(joining())); } /** diff --git a/repository/src/main/java/tech/ydb/yoj/repository/db/internal/RepositoryTransactionImpl.java b/repository/src/main/java/tech/ydb/yoj/repository/db/internal/RepositoryTransactionImpl.java new file mode 100644 index 00000000..acf8155c --- /dev/null +++ b/repository/src/main/java/tech/ydb/yoj/repository/db/internal/RepositoryTransactionImpl.java @@ -0,0 +1,31 @@ +package tech.ydb.yoj.repository.db.internal; + +import com.google.common.base.Stopwatch; +import tech.ydb.yoj.repository.db.cache.TransactionLog; + +import static tech.ydb.yoj.util.lang.Strings.debugResult; + +/** + * Utility class for {@link tech.ydb.yoj.repository.db.RepositoryTransaction} implementation; + * for internal use only. + * This class is not part of the public API and should not + * be used directly by client code. + */ +public final class RepositoryTransactionImpl { + public static final Object EMPTY_RESULT = new Object(); + + private RepositoryTransactionImpl() { + } + + public static void logStatementResult(TransactionLog log, Stopwatch sw, Object action, Object result) { + if (result == EMPTY_RESULT) { + log.debug("[ %s ] %s", sw, action); + } else { + log.debug("[ %s ] %s -> %s", sw, action, debugResult(result)); + } + } + + public static void logStatementError(TransactionLog log, Stopwatch sw, Object action, Throwable t) { + log.debug("[ %s ] %s => %s", sw, action, t.getClass().getName()); + } +} diff --git a/repository/src/main/java/tech/ydb/yoj/repository/db/TableQueryImpl.java b/repository/src/main/java/tech/ydb/yoj/repository/db/internal/TableQueryImpl.java similarity index 91% rename from repository/src/main/java/tech/ydb/yoj/repository/db/TableQueryImpl.java rename to repository/src/main/java/tech/ydb/yoj/repository/db/internal/TableQueryImpl.java index 4f3ee950..63573dd5 100644 --- a/repository/src/main/java/tech/ydb/yoj/repository/db/TableQueryImpl.java +++ b/repository/src/main/java/tech/ydb/yoj/repository/db/internal/TableQueryImpl.java @@ -1,7 +1,11 @@ -package tech.ydb.yoj.repository.db; +package tech.ydb.yoj.repository.db.internal; import com.google.common.collect.Sets; -import tech.ydb.yoj.InternalApi; +import tech.ydb.yoj.repository.db.Entity; +import tech.ydb.yoj.repository.db.EntityExpressions; +import tech.ydb.yoj.repository.db.EntityIdSchema; +import tech.ydb.yoj.repository.db.Table; +import tech.ydb.yoj.repository.db.TableQueryBuilder; import tech.ydb.yoj.repository.db.cache.FirstLevelCache; import tech.ydb.yoj.repository.db.list.ListRequest; @@ -20,7 +24,6 @@ * This class is not part of the public API and should not * be used directly by client code. */ -@InternalApi public final class TableQueryImpl { private TableQueryImpl() { } diff --git a/repository/src/main/java/tech/ydb/yoj/repository/db/internal/package-info.java b/repository/src/main/java/tech/ydb/yoj/repository/db/internal/package-info.java new file mode 100644 index 00000000..14a4e25b --- /dev/null +++ b/repository/src/main/java/tech/ydb/yoj/repository/db/internal/package-info.java @@ -0,0 +1,4 @@ +@InternalApi +package tech.ydb.yoj.repository.db.internal; + +import tech.ydb.yoj.InternalApi; diff --git a/util/src/main/java/tech/ydb/yoj/util/function/LazyToString.java b/util/src/main/java/tech/ydb/yoj/util/function/LazyToString.java new file mode 100644 index 00000000..9ab154b8 --- /dev/null +++ b/util/src/main/java/tech/ydb/yoj/util/function/LazyToString.java @@ -0,0 +1,15 @@ +package tech.ydb.yoj.util.function; + +import lombok.RequiredArgsConstructor; + +import java.util.function.Supplier; + +@RequiredArgsConstructor(staticName = "of") +public final class LazyToString { + private final Supplier supplier; + + @Override + public String toString() { + return supplier.get(); + } +} diff --git a/util/src/main/java/tech/ydb/yoj/util/lang/Strings.java b/util/src/main/java/tech/ydb/yoj/util/lang/Strings.java index 78f3e325..7170aeeb 100644 --- a/util/src/main/java/tech/ydb/yoj/util/lang/Strings.java +++ b/util/src/main/java/tech/ydb/yoj/util/lang/Strings.java @@ -1,11 +1,14 @@ package tech.ydb.yoj.util.lang; +import com.google.common.collect.Iterables; import lombok.NonNull; +import tech.ydb.yoj.util.function.LazyToString; import javax.annotation.Nullable; import java.util.Objects; import java.util.stream.Stream; +import static com.google.common.base.Strings.lenientFormat; import static java.util.stream.Collectors.joining; public final class Strings { @@ -27,4 +30,23 @@ public static String removeSuffix(@Nullable String s, @NonNull String suffix) { public static String leftPad(@NonNull String s, int minLength, char padChar) { return s.length() >= minLength ? s : String.valueOf(padChar).repeat(minLength - s.length()) + s; } + + public static Object lazyDebugMsg(String format, Object... args) { + return LazyToString.of(() -> lenientFormat(format, args)); + } + + public static Object debugResult(Object result) { + return LazyToString.of(() -> { + if (result instanceof Iterable iterable) { + int size = Iterables.size(iterable); + return switch (size) { + case 0 -> "[]"; + case 1 -> String.valueOf(iterable.iterator().next()); + default -> "[" + iterable.iterator().next() + ",...](" + size + ")"; + }; + } else { + return String.valueOf(result); + } + }); + } }