Skip to content

Commit 90142e0

Browse files
nvamelichevnvamelichev
committed
#143: Lazy and lenient logging of statements and statement parameters
1 parent 982cbc5 commit 90142e0

File tree

33 files changed

+367
-159
lines changed

33 files changed

+367
-159
lines changed

‎repository-inmemory/pom.xml‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -60,6 +60,11 @@
6060
<artifactId>log4j-core</artifactId>
6161
<scope>test</scope>
6262
</dependency>
63+
<dependency>
64+
<groupId>org.apache.logging.log4j</groupId>
65+
<artifactId>log4j-jul</artifactId>
66+
<scope>test</scope>
67+
</dependency>
6368
<!-- for log4j2.yaml parsing -->
6469
<dependency>
6570
<groupId>com.fasterxml.jackson.core</groupId>
@@ -79,6 +84,15 @@
7984
<groupId>org.apache.maven.plugins</groupId>
8085
<artifactId>maven-jar-plugin</artifactId>
8186
</plugin>
87+
<plugin>
88+
<groupId>org.apache.maven.plugins</groupId>
89+
<artifactId>maven-surefire-plugin</artifactId>
90+
<configuration>
91+
<systemPropertyVariables>
92+
<java.util.logging.manager>org.apache.logging.log4j.jul.LogManager</java.util.logging.manager>
93+
</systemPropertyVariables>
94+
</configuration>
95+
</plugin>
8296
</plugins>
8397
</build>
8498
</project>

‎repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryRepositoryTransaction.java‎

Lines changed: 14 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
package tech.ydb.yoj.repository.test.inmemory;
22

33
import com.google.common.base.Stopwatch;
4-
import com.google.common.collect.Iterables;
54
import lombok.Getter;
65
import tech.ydb.yoj.DeprecationWarnings;
76
import tech.ydb.yoj.repository.BaseDb;
@@ -22,8 +21,12 @@
2221
import java.util.function.Function;
2322
import java.util.function.Supplier;
2423

24+
import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.EMPTY_RESULT;
25+
import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.logStatementError;
26+
import static tech.ydb.yoj.repository.db.internal.RepositoryTransactionImpl.logStatementResult;
27+
2528
public class InMemoryRepositoryTransaction implements BaseDb, RepositoryTransaction {
26-
private final static AtomicLong txIdGenerator = new AtomicLong();
29+
private static final AtomicLong txIdGenerator = new AtomicLong();
2730

2831
private final long txId = txIdGenerator.incrementAndGet();
2932
private final Stopwatch txStopwatch = Stopwatch.createStarted();
@@ -115,7 +118,7 @@ private void endTransaction(String action, Runnable runnable) {
115118
}
116119
} finally {
117120
closeAction = action;
118-
transactionLocal.log().info("[[%s]] TOTAL (since tx start)", txStopwatch);
121+
transactionLocal.log().info("[[%s]] TOTAL (since tx start)", txStopwatch.stop());
119122
}
120123
}
121124

@@ -132,7 +135,7 @@ private boolean isFinalActionNeeded(String action) {
132135
}
133136

134137
final <T extends Entity<T>> void doInWriteTransaction(
135-
String log, TableDescriptor<T> tableDescriptor, Consumer<WriteTxDataShard<T>> consumer
138+
Object action, TableDescriptor<T> tableDescriptor, Consumer<WriteTxDataShard<T>> consumer
136139
) {
137140
if (options.isScan()) {
138141
throw new IllegalTransactionScanException("Mutable operations");
@@ -141,7 +144,7 @@ final <T extends Entity<T>> void doInWriteTransaction(
141144
throw new IllegalTransactionIsolationLevelException("Mutable operations", options.getIsolationLevel());
142145
}
143146

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

@@ -156,7 +159,7 @@ final <T extends Entity<T>> void doInWriteTransaction(
156159
}
157160

158161
final <T extends Entity<T>, R> R doInTransaction(
159-
String action, TableDescriptor<T> tableDescriptor, Function<ReadOnlyTxDataShard<T>, R> func
162+
Object action, TableDescriptor<T> tableDescriptor, Function<ReadOnlyTxDataShard<T>, R> func
160163
) {
161164
return logTransaction(action, () -> {
162165
InMemoryTxLockWatcher findWatcher = hasWrites ? watcher : InMemoryTxLockWatcher.NO_LOCKS;
@@ -172,37 +175,26 @@ tableDescriptor, txId, getVersion(), findWatcher
172175
});
173176
}
174177

175-
private void logTransaction(String action, Runnable runnable) {
178+
private void logTransaction(Object action, Runnable runnable) {
176179
logTransaction(action, () -> {
177180
runnable.run();
178-
return null;
181+
return EMPTY_RESULT;
179182
});
180183
}
181184

182-
private <R> R logTransaction(String action, Supplier<R> supplier) {
185+
private <R> R logTransaction(Object action, Supplier<R> supplier) {
183186
if (closeAction != null) {
184187
throw new IllegalStateException("Transaction already closed by " + closeAction);
185188
}
186189

187190
Stopwatch sw = Stopwatch.createStarted();
188191
try {
189192
R result = supplier.get();
190-
transactionLocal.log().debug("[ %s ] %s -> %s", sw, action, printResult(result));
193+
logStatementResult(transactionLocal.log(), sw.stop(), action, result);
191194
return result;
192195
} catch (Throwable t) {
193-
transactionLocal.log().debug("[ %s ] %s => %s", sw, action, t);
196+
logStatementError(transactionLocal.log(), sw.stop(), action, t);
194197
throw t;
195198
}
196199
}
197-
198-
private String printResult(Object result) {
199-
if (result instanceof Iterable<?>) {
200-
long size = Iterables.size((Iterable<?>) result);
201-
return size == 1
202-
? String.valueOf(Iterables.getOnlyElement((Iterable<?>) result))
203-
: "[" + size + "]";
204-
} else {
205-
return String.valueOf(result);
206-
}
207-
}
208200
}

‎repository-inmemory/src/main/java/tech/ydb/yoj/repository/test/inmemory/InMemoryTable.java‎

Lines changed: 7 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -15,10 +15,10 @@
1515
import tech.ydb.yoj.repository.db.Range;
1616
import tech.ydb.yoj.repository.db.Table;
1717
import tech.ydb.yoj.repository.db.TableDescriptor;
18-
import tech.ydb.yoj.repository.db.TableQueryImpl;
1918
import tech.ydb.yoj.repository.db.ViewSchema;
2019
import tech.ydb.yoj.repository.db.cache.FirstLevelCache;
2120
import tech.ydb.yoj.repository.db.exception.IllegalTransactionIsolationLevelException;
21+
import tech.ydb.yoj.repository.db.internal.TableQueryImpl;
2222
import tech.ydb.yoj.repository.db.list.InMemoryQueries;
2323
import tech.ydb.yoj.repository.db.readtable.ReadTableParams;
2424
import tech.ydb.yoj.repository.db.statement.Changeset;
@@ -33,6 +33,7 @@
3333
import static java.util.stream.Collectors.toList;
3434
import static java.util.stream.Collectors.toUnmodifiableMap;
3535
import static java.util.stream.Collectors.toUnmodifiableSet;
36+
import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg;
3637

3738
public class InMemoryTable<T extends Entity<T>> implements Table<T> {
3839
private final EntitySchema<T> schema;
@@ -180,7 +181,7 @@ public T find(Entity.Id<T> id) {
180181
}
181182
return transaction.getTransactionLocal().firstLevelCache(tableDescriptor).get(id, __ -> {
182183
markKeyRead(id);
183-
T entity = transaction.doInTransaction("find(" + id + ")", tableDescriptor, shard -> shard.find(id));
184+
T entity = transaction.doInTransaction(lazyDebugMsg("find(%s)", id), tableDescriptor, shard -> shard.find(id));
184185
return postLoad(entity);
185186
});
186187
}
@@ -204,7 +205,7 @@ public <V extends View> V find(Class<V> viewType, Entity.Id<T> id) {
204205
}
205206

206207
markKeyRead(id);
207-
return transaction.doInTransaction("find(" + id + ")", tableDescriptor, shard -> shard.find(id, viewType));
208+
return transaction.doInTransaction(lazyDebugMsg("find(%s)", id), tableDescriptor, shard -> shard.find(id, viewType));
208209
}
209210

210211
@Override
@@ -427,7 +428,7 @@ public <ID extends Entity.Id<T>> List<ID> findIds(Set<ID> ids) {
427428
public T insert(T tt) {
428429
T t = tt.preSave();
429430
transaction.getWatcher().markRowRead(tableDescriptor, t.getId());
430-
transaction.doInWriteTransaction("insert(" + t + ")", tableDescriptor, shard -> shard.insert(t));
431+
transaction.doInWriteTransaction(lazyDebugMsg("insert(%s)", t), tableDescriptor, shard -> shard.insert(t));
431432
transaction.getTransactionLocal().firstLevelCache(tableDescriptor).put(t);
432433
transaction.getTransactionLocal().projectionCache().save(t);
433434
return t;
@@ -436,15 +437,15 @@ public T insert(T tt) {
436437
@Override
437438
public T save(T tt) {
438439
T t = tt.preSave();
439-
transaction.doInWriteTransaction("save(" + t + ")", tableDescriptor, shard -> shard.save(t));
440+
transaction.doInWriteTransaction(lazyDebugMsg("save(%s)", t), tableDescriptor, shard -> shard.save(t));
440441
transaction.getTransactionLocal().firstLevelCache(tableDescriptor).put(t);
441442
transaction.getTransactionLocal().projectionCache().save(t);
442443
return t;
443444
}
444445

445446
@Override
446447
public void delete(Entity.Id<T> id) {
447-
transaction.doInWriteTransaction("delete(" + id + ")", tableDescriptor, shard -> shard.delete(id));
448+
transaction.doInWriteTransaction(lazyDebugMsg("delete(%s)", id), tableDescriptor, shard -> shard.delete(id));
448449
transaction.getTransactionLocal().firstLevelCache(tableDescriptor).putEmpty(id);
449450
transaction.getTransactionLocal().projectionCache().delete(id);
450451
}

‎repository-test/pom.xml‎

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,10 @@
4545
<groupId>org.eclipse.collections</groupId>
4646
<artifactId>eclipse-collections</artifactId>
4747
</dependency>
48+
<dependency>
49+
<groupId>org.apache.logging.log4j</groupId>
50+
<artifactId>log4j-core</artifactId>
51+
</dependency>
4852

4953
<dependency>
5054
<groupId>com.fasterxml.jackson.core</groupId>

‎repository-test/src/main/java/tech/ydb/yoj/repository/test/RepositoryTest.java‎

Lines changed: 73 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,9 @@
44
import com.google.common.collect.Iterables;
55
import com.google.common.collect.Iterators;
66
import lombok.SneakyThrows;
7+
import org.apache.logging.log4j.Level;
8+
import org.apache.logging.log4j.core.LoggerContext;
9+
import org.apache.logging.log4j.core.config.Configurator;
710
import org.assertj.core.api.Assertions;
811
import org.junit.Assert;
912
import org.junit.Test;
@@ -39,6 +42,7 @@
3942
import tech.ydb.yoj.repository.test.sample.TestDb;
4043
import tech.ydb.yoj.repository.test.sample.TestDbImpl;
4144
import tech.ydb.yoj.repository.test.sample.TestEntityOperations;
45+
import tech.ydb.yoj.repository.test.sample.model.BadToStringEntity;
4246
import tech.ydb.yoj.repository.test.sample.model.Book;
4347
import tech.ydb.yoj.repository.test.sample.model.Bubble;
4448
import tech.ydb.yoj.repository.test.sample.model.BytePkEntity;
@@ -73,6 +77,7 @@
7377
import tech.ydb.yoj.repository.test.sample.model.annotations.UniqueEntity;
7478
import tech.ydb.yoj.repository.test.sample.model.annotations.UniqueEntityNative;
7579

80+
import java.time.Duration;
7681
import java.time.Instant;
7782
import java.util.ArrayList;
7883
import java.util.Arrays;
@@ -1660,24 +1665,22 @@ public void optimisticLockRead() {
16601665
RepositoryTransaction tx1 = startTransaction();
16611666
tx1.table(Project.class).insert(new Project(new Project.Id("3"), "p3"));
16621667
tx1.table(Project.class).find(new Project.Id("1"));
1663-
{
1664-
RepositoryTransaction tx2 = startTransaction();
1665-
tx2.table(Project.class).save(new Project(new Project.Id("1"), "p1-1"));
1666-
tx2.commit();
1667-
}
1668+
1669+
RepositoryTransaction tx2 = startTransaction();
1670+
tx2.table(Project.class).save(new Project(new Project.Id("1"), "p1-1"));
1671+
tx2.commit();
1672+
16681673
// read object was touched -> rollback on any operation
1669-
//не prepare запросы валятся при обращении
1670-
//prepare запросы валятся на комите
16711674
assertThatExceptionOfType(OptimisticLockException.class)
16721675
.isThrownBy(() -> {
1673-
//не prepare запросы валятся при обращении
1676+
// non-prepared statements fail on statement execution
16741677
try {
16751678
tx1.table(Project.class).find(new Project.Id("1"));
16761679
} catch (Exception e) {
16771680
tx1.rollback();
16781681
throw e;
16791682
}
1680-
//prepare запросы валятся на комите
1683+
// prepared statements fail on tx commit
16811684
tx1.commit();
16821685
});
16831686
}
@@ -2469,14 +2472,14 @@ public void noOptimisticLockOnScan() {
24692472
tx2.commit();
24702473
}
24712474

2472-
//не prepare запросы не валятся при обращении
2475+
// non-prepared statements should not fail on statement execution, because scan reads from a database snapshot
24732476
try {
24742477
tx1.table(Project.class).find(new Project.Id("1"));
24752478
} catch (Exception e) {
24762479
tx1.rollback();
24772480
throw e;
24782481
}
2479-
//prepare запросы не валятся на комите
2482+
// prepared statements should not fail on commit, because scan reads from a database snapshot
24802483
tx1.commit();
24812484
}
24822485

@@ -3039,8 +3042,66 @@ private void strictEnumBehaviorTestImpl() {
30393042
});
30403043
}
30413044

3045+
@Test
3046+
public void toStringThrows() {
3047+
var entity = new BadToStringEntity(new BadToStringEntity.Id("id"), null);
3048+
db.tx(() -> db.table(BadToStringEntity.class).save(entity));
3049+
assertThatExceptionOfType(EntityAlreadyExistsException.class)
3050+
.isThrownBy(() -> db.withMaxRetries(0).tx(() -> db.table(BadToStringEntity.class).insert(entity)));
3051+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(entity.getId()))).isEqualTo(entity);
3052+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(Set.of(entity.getId()))))
3053+
.singleElement().isEqualTo(entity);
3054+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3055+
.ids(Set.of(entity.getId()))
3056+
.findOne())
3057+
).isEqualTo(entity);
3058+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3059+
.where("id").in(entity.getId())
3060+
.findOne())
3061+
).isEqualTo(entity);
3062+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3063+
.where("id").eq(entity.getId())
3064+
.and("toStringDuration").isNull()
3065+
.findOne())
3066+
).isEqualTo(entity);
3067+
}
3068+
3069+
@Test(timeout = 30_000L)
3070+
public void toStringSlow() {
3071+
var loggerName = "tech.ydb.yoj.repository.db";
3072+
var config = LoggerContext.getContext().getConfiguration();
3073+
var prevLoggerLevel = config.getLoggerConfig(loggerName).getLevel();
3074+
try {
3075+
Configurator.setLevel(loggerName, Level.ERROR);
3076+
3077+
var entity = new BadToStringEntity(new BadToStringEntity.Id("id"), Duration.ofMinutes(5));
3078+
db.tx(() -> db.table(BadToStringEntity.class).save(entity));
3079+
assertThatExceptionOfType(EntityAlreadyExistsException.class)
3080+
.isThrownBy(() -> db.withMaxRetries(0).tx(() -> db.table(BadToStringEntity.class).insert(entity)));
3081+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(entity.getId()))).isEqualTo(entity);
3082+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(Set.of(entity.getId()))))
3083+
.singleElement().isEqualTo(entity);
3084+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3085+
.ids(Set.of(entity.getId()))
3086+
.findOne())
3087+
).isEqualTo(entity);
3088+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3089+
.where("id").in(entity.getId())
3090+
.findOne())
3091+
).isEqualTo(entity);
3092+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3093+
.where("id").eq(entity.getId())
3094+
.and("toStringDuration").isNotNull()
3095+
.findOne())
3096+
).isEqualTo(entity);
3097+
} finally {
3098+
Configurator.setLevel(loggerName, prevLoggerLevel);
3099+
}
3100+
}
3101+
30423102
protected void runInTx(Consumer<RepositoryTransaction> action) {
3043-
// We do not retry transactions, because we do not expect conflicts in our test scenarios.
3103+
// We do *not* retry low-level transactions (`RepositoryTransaction`s) because we don't expect to get conflicts
3104+
// in our test scenarios
30443105
RepositoryTransaction transaction = startTransaction();
30453106
try {
30463107
action.accept(transaction);

‎repository-test/src/main/java/tech/ydb/yoj/repository/test/entity/TestEntities.java‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
import tech.ydb.yoj.repository.db.Entity;
55
import tech.ydb.yoj.repository.db.Repository;
66
import tech.ydb.yoj.repository.db.TableDescriptor;
7+
import tech.ydb.yoj.repository.test.sample.model.BadToStringEntity;
78
import tech.ydb.yoj.repository.test.sample.model.Book;
89
import tech.ydb.yoj.repository.test.sample.model.Bubble;
910
import tech.ydb.yoj.repository.test.sample.model.BytePkEntity;
@@ -64,7 +65,8 @@ private TestEntities() {
6465
MultiWrappedEntity2.class,
6566
UniqueEntity.class,
6667
UniqueEntityNative.class,
67-
EnumEntity.class
68+
EnumEntity.class,
69+
BadToStringEntity.class
6870
);
6971

7072
public static final List<TableDescriptor<?>> ALL_TABLE_DESCRIPTORS = List.of(

0 commit comments

Comments
 (0)