Skip to content

#143: Lazy and lenient logging of statements and statement parameters #144

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 1 commit into
base: main
Choose a base branch
from
Open

#143: Lazy and lenient logging of statements and statement parameters #144

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 14 additions & 0 deletions repository-inmemory/pom.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,11 @@
<artifactId>log4j-core</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-jul</artifactId>
<scope>test</scope>
</dependency>
<!-- for log4j2.yaml parsing -->
<dependency>
<groupId>com.fasterxml.jackson.core</groupId>
Expand All @@ -79,6 +84,15 @@
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-jar-plugin</artifactId>
</plugin>
<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-surefire-plugin</artifactId>
<configuration>
<systemPropertyVariables>
<java.util.logging.manager>org.apache.logging.log4j.jul.LogManager</java.util.logging.manager>
</systemPropertyVariables>
</configuration>
</plugin>
</plugins>
</build>
</project>
36 changes: 14 additions & 22 deletions ...ry/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryRepositoryTransaction.java
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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;
Expand All @@ -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();
Expand Down Expand Up @@ -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());
}
}

Expand All @@ -126,7 +129,7 @@ private boolean isFinalActionNeeded(String action) {
}

final <T extends Entity<T>> void doInWriteTransaction(
String log, TableDescriptor<T> tableDescriptor, Consumer<WriteTxDataShard<T>> consumer
Object action, TableDescriptor<T> tableDescriptor, Consumer<WriteTxDataShard<T>> consumer
) {
if (options.isScan()) {
throw new IllegalTransactionScanException("Mutable operations");
Expand All @@ -135,7 +138,7 @@ final <T extends Entity<T>> void doInWriteTransaction(
throw new IllegalTransactionIsolationLevelException("Mutable operations", options.getIsolationLevel());
}

Runnable query = () -> logTransaction(log, () -> {
Runnable query = () -> logTransaction(action, () -> {
WriteTxDataShard<T> shard = storage.getWriteTxDataShard(tableDescriptor, txId, getVersion());
consumer.accept(shard);

Expand All @@ -150,7 +153,7 @@ final <T extends Entity<T>> void doInWriteTransaction(
}

final <T extends Entity<T>, R> R doInTransaction(
String action, TableDescriptor<T> tableDescriptor, Function<ReadOnlyTxDataShard<T>, R> func
Object action, TableDescriptor<T> tableDescriptor, Function<ReadOnlyTxDataShard<T>, R> func
) {
return logTransaction(action, () -> {
InMemoryTxLockWatcher findWatcher = hasWrites ? watcher : InMemoryTxLockWatcher.NO_LOCKS;
Expand All @@ -166,37 +169,26 @@ 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> R logTransaction(String action, Supplier<R> supplier) {
private <R> R logTransaction(Object action, Supplier<R> supplier) {
if (closeAction != null) {
throw new IllegalStateException("Transaction already closed by " + closeAction);
}

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);
}
}
}
13 changes: 7 additions & 6 deletions repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryTable.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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<T extends Entity<T>> implements Table<T> {
private final EntitySchema<T> schema;
Expand Down Expand Up @@ -178,7 +179,7 @@ public T find(Entity.Id<T> 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);
});
}
Expand All @@ -202,7 +203,7 @@ public <V extends View> V find(Class<V> viewType, Entity.Id<T> 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
Expand Down Expand Up @@ -425,7 +426,7 @@ public <ID extends Entity.Id<T>> List<ID> findIds(Set<ID> 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;
Expand All @@ -434,15 +435,15 @@ 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;
}

@Override
public void delete(Entity.Id<T> 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);
}
Expand Down
4 changes: 4 additions & 0 deletions repository-test/pom.xml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,6 +45,10 @@
<groupId>org.eclipse.collections</groupId>
<artifactId>eclipse-collections</artifactId>
</dependency>
<dependency>
<groupId>org.apache.logging.log4j</groupId>
<artifactId>log4j-core</artifactId>
</dependency>

<dependency>
<groupId>com.fasterxml.jackson.core</groupId>
Expand Down
85 changes: 73 additions & 12 deletions repository-test/src/main/java/tech/ydb/yoj/repository/test/RepositoryTest.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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();
});
}
Expand Down Expand Up @@ -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();
}

Expand Down Expand Up @@ -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<RepositoryTransaction> 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);
Expand Down
4 changes: 3 additions & 1 deletion repository-test/src/main/java/tech/ydb/yoj/repository/test/entity/TestEntities.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -62,7 +63,8 @@ private TestEntities() {
MultiWrappedEntity.class,
MultiWrappedEntity2.class,
UniqueEntity.class,
UniqueEntityNative.class
UniqueEntityNative.class,
BadToStringEntity.class
);

public static final List<TableDescriptor<?>> ALL_TABLE_DESCRIPTORS = List.of(
Expand Down
Loading