Skip to content

Commit d9923f4

Browse files
nvamelichevnvamelichev
committed
#143: Lazy and lenient logging of statements and statement parameters
1 parent 272310d commit d9923f4

File tree

33 files changed

+380
-174
lines changed

33 files changed

+380
-174
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.repository.BaseDb;
76
import tech.ydb.yoj.repository.db.Entity;
@@ -21,8 +20,12 @@
2120
import java.util.function.Function;
2221
import java.util.function.Supplier;
2322

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

2730
private final long txId = txIdGenerator.incrementAndGet();
2831
private final Stopwatch txStopwatch = Stopwatch.createStarted();
@@ -109,7 +112,7 @@ private void endTransaction(String action, Runnable runnable) {
109112
}
110113
} finally {
111114
closeAction = action;
112-
transactionLocal.log().info("[[%s]] TOTAL (since tx start)", txStopwatch);
115+
transactionLocal.log().info("[[%s]] TOTAL (since tx start)", txStopwatch.stop());
113116
}
114117
}
115118

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

128131
final <T extends Entity<T>> void doInWriteTransaction(
129-
String log, TableDescriptor<T> tableDescriptor, Consumer<WriteTxDataShard<T>> consumer
132+
Object action, TableDescriptor<T> tableDescriptor, Consumer<WriteTxDataShard<T>> consumer
130133
) {
131134
if (options.isScan()) {
132135
throw new IllegalTransactionScanException("Mutable operations");
@@ -135,7 +138,7 @@ final <T extends Entity<T>> void doInWriteTransaction(
135138
throw new IllegalTransactionIsolationLevelException("Mutable operations", options.getIsolationLevel());
136139
}
137140

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

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

152155
final <T extends Entity<T>, R> R doInTransaction(
153-
String action, TableDescriptor<T> tableDescriptor, Function<ReadOnlyTxDataShard<T>, R> func
156+
Object action, TableDescriptor<T> tableDescriptor, Function<ReadOnlyTxDataShard<T>, R> func
154157
) {
155158
return logTransaction(action, () -> {
156159
InMemoryTxLockWatcher findWatcher = hasWrites ? watcher : InMemoryTxLockWatcher.NO_LOCKS;
@@ -166,37 +169,26 @@ tableDescriptor, txId, getVersion(), findWatcher
166169
});
167170
}
168171

169-
private void logTransaction(String action, Runnable runnable) {
172+
private void logTransaction(Object action, Runnable runnable) {
170173
logTransaction(action, () -> {
171174
runnable.run();
172-
return null;
175+
return EMPTY_RESULT;
173176
});
174177
}
175178

176-
private <R> R logTransaction(String action, Supplier<R> supplier) {
179+
private <R> R logTransaction(Object action, Supplier<R> supplier) {
177180
if (closeAction != null) {
178181
throw new IllegalStateException("Transaction already closed by " + closeAction);
179182
}
180183

181184
Stopwatch sw = Stopwatch.createStarted();
182185
try {
183186
R result = supplier.get();
184-
transactionLocal.log().debug("[ %s ] %s -> %s", sw, action, printResult(result));
187+
logStatementResult(transactionLocal.log(), sw.stop(), action, result);
185188
return result;
186189
} catch (Throwable t) {
187-
transactionLocal.log().debug("[ %s ] %s => %s", sw, action, t);
190+
logStatementError(transactionLocal.log(), sw.stop(), action, t);
188191
throw t;
189192
}
190193
}
191-
192-
private String printResult(Object result) {
193-
if (result instanceof Iterable<?>) {
194-
long size = Iterables.size((Iterable<?>) result);
195-
return size == 1
196-
? String.valueOf(Iterables.getOnlyElement((Iterable<?>) result))
197-
: "[" + size + "]";
198-
} else {
199-
return String.valueOf(result);
200-
}
201-
}
202194
}

‎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
@@ -14,10 +14,10 @@
1414
import tech.ydb.yoj.repository.db.Range;
1515
import tech.ydb.yoj.repository.db.Table;
1616
import tech.ydb.yoj.repository.db.TableDescriptor;
17-
import tech.ydb.yoj.repository.db.TableQueryImpl;
1817
import tech.ydb.yoj.repository.db.ViewSchema;
1918
import tech.ydb.yoj.repository.db.cache.FirstLevelCache;
2019
import tech.ydb.yoj.repository.db.exception.IllegalTransactionIsolationLevelException;
20+
import tech.ydb.yoj.repository.db.internal.TableQueryImpl;
2121
import tech.ydb.yoj.repository.db.list.InMemoryQueries;
2222
import tech.ydb.yoj.repository.db.readtable.ReadTableParams;
2323
import tech.ydb.yoj.repository.db.statement.Changeset;
@@ -32,6 +32,7 @@
3232
import static java.util.stream.Collectors.toList;
3333
import static java.util.stream.Collectors.toUnmodifiableMap;
3434
import static java.util.stream.Collectors.toUnmodifiableSet;
35+
import static tech.ydb.yoj.util.lang.Strings.lazyDebugMsg;
3536

3637
public class InMemoryTable<T extends Entity<T>> implements Table<T> {
3738
private final EntitySchema<T> schema;
@@ -178,7 +179,7 @@ public T find(Entity.Id<T> id) {
178179
}
179180
return transaction.getTransactionLocal().firstLevelCache(tableDescriptor).get(id, __ -> {
180181
markKeyRead(id);
181-
T entity = transaction.doInTransaction("find(" + id + ")", tableDescriptor, shard -> shard.find(id));
182+
T entity = transaction.doInTransaction(lazyDebugMsg("find(%s)", id), tableDescriptor, shard -> shard.find(id));
182183
return postLoad(entity);
183184
});
184185
}
@@ -202,7 +203,7 @@ public <V extends View> V find(Class<V> viewType, Entity.Id<T> id) {
202203
}
203204

204205
markKeyRead(id);
205-
return transaction.doInTransaction("find(" + id + ")", tableDescriptor, shard -> shard.find(id, viewType));
206+
return transaction.doInTransaction(lazyDebugMsg("find(%s)", id), tableDescriptor, shard -> shard.find(id, viewType));
206207
}
207208

208209
@Override
@@ -425,7 +426,7 @@ public <ID extends Entity.Id<T>> List<ID> findIds(Set<ID> ids) {
425426
public T insert(T tt) {
426427
T t = tt.preSave();
427428
transaction.getWatcher().markRowRead(tableDescriptor, t.getId());
428-
transaction.doInWriteTransaction("insert(" + t + ")", tableDescriptor, shard -> shard.insert(t));
429+
transaction.doInWriteTransaction(lazyDebugMsg("insert(%s)", t), tableDescriptor, shard -> shard.insert(t));
429430
transaction.getTransactionLocal().firstLevelCache(tableDescriptor).put(t);
430431
transaction.getTransactionLocal().projectionCache().save(t);
431432
return t;
@@ -434,15 +435,15 @@ public T insert(T tt) {
434435
@Override
435436
public T save(T tt) {
436437
T t = tt.preSave();
437-
transaction.doInWriteTransaction("save(" + t + ")", tableDescriptor, shard -> shard.save(t));
438+
transaction.doInWriteTransaction(lazyDebugMsg("save(%s)", t), tableDescriptor, shard -> shard.save(t));
438439
transaction.getTransactionLocal().firstLevelCache(tableDescriptor).put(t);
439440
transaction.getTransactionLocal().projectionCache().save(t);
440441
return t;
441442
}
442443

443444
@Override
444445
public void delete(Entity.Id<T> id) {
445-
transaction.doInWriteTransaction("delete(" + id + ")", tableDescriptor, shard -> shard.delete(id));
446+
transaction.doInWriteTransaction(lazyDebugMsg("delete(%s)", id), tableDescriptor, shard -> shard.delete(id));
446447
transaction.getTransactionLocal().firstLevelCache(tableDescriptor).putEmpty(id);
447448
transaction.getTransactionLocal().projectionCache().delete(id);
448449
}

‎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;
@@ -36,6 +39,7 @@
3639
import tech.ydb.yoj.repository.test.sample.TestDb;
3740
import tech.ydb.yoj.repository.test.sample.TestDbImpl;
3841
import tech.ydb.yoj.repository.test.sample.TestEntityOperations;
42+
import tech.ydb.yoj.repository.test.sample.model.BadToStringEntity;
3943
import tech.ydb.yoj.repository.test.sample.model.Book;
4044
import tech.ydb.yoj.repository.test.sample.model.Bubble;
4145
import tech.ydb.yoj.repository.test.sample.model.BytePkEntity;
@@ -69,6 +73,7 @@
6973
import tech.ydb.yoj.repository.test.sample.model.annotations.UniqueEntity;
7074
import tech.ydb.yoj.repository.test.sample.model.annotations.UniqueEntityNative;
7175

76+
import java.time.Duration;
7277
import java.time.Instant;
7378
import java.util.ArrayList;
7479
import java.util.Arrays;
@@ -1655,24 +1660,22 @@ public void optimisticLockRead() {
16551660
RepositoryTransaction tx1 = startTransaction();
16561661
tx1.table(Project.class).insert(new Project(new Project.Id("3"), "p3"));
16571662
tx1.table(Project.class).find(new Project.Id("1"));
1658-
{
1659-
RepositoryTransaction tx2 = startTransaction();
1660-
tx2.table(Project.class).save(new Project(new Project.Id("1"), "p1-1"));
1661-
tx2.commit();
1662-
}
1663+
1664+
RepositoryTransaction tx2 = startTransaction();
1665+
tx2.table(Project.class).save(new Project(new Project.Id("1"), "p1-1"));
1666+
tx2.commit();
1667+
16631668
// read object was touched -> rollback on any operation
1664-
//не prepare запросы валятся при обращении
1665-
//prepare запросы валятся на комите
16661669
assertThatExceptionOfType(OptimisticLockException.class)
16671670
.isThrownBy(() -> {
1668-
//не prepare запросы валятся при обращении
1671+
// non-prepared statements fail on statement execution
16691672
try {
16701673
tx1.table(Project.class).find(new Project.Id("1"));
16711674
} catch (Exception e) {
16721675
tx1.rollback();
16731676
throw e;
16741677
}
1675-
//prepare запросы валятся на комите
1678+
// prepared statements fail on tx commit
16761679
tx1.commit();
16771680
});
16781681
}
@@ -2464,14 +2467,14 @@ public void noOptimisticLockOnScan() {
24642467
tx2.commit();
24652468
}
24662469

2467-
//не prepare запросы не валятся при обращении
2470+
// non-prepared statements should not fail on statement execution, because scan reads from a database snapshot
24682471
try {
24692472
tx1.table(Project.class).find(new Project.Id("1"));
24702473
} catch (Exception e) {
24712474
tx1.rollback();
24722475
throw e;
24732476
}
2474-
//prepare запросы не валятся на комите
2477+
// prepared statements should not fail on commit, because scan reads from a database snapshot
24752478
tx1.commit();
24762479
}
24772480

@@ -2953,8 +2956,66 @@ public void multiWrapperEntity2WithCustomConverterFullyWrapped() {
29532956
)).isEmpty();
29542957
}
29552958

2959+
@Test
2960+
public void toStringThrows() {
2961+
var entity = new BadToStringEntity(new BadToStringEntity.Id("id"), null);
2962+
db.tx(() -> db.table(BadToStringEntity.class).save(entity));
2963+
assertThatExceptionOfType(EntityAlreadyExistsException.class)
2964+
.isThrownBy(() -> db.withMaxRetries(0).tx(() -> db.table(BadToStringEntity.class).insert(entity)));
2965+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(entity.getId()))).isEqualTo(entity);
2966+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(Set.of(entity.getId()))))
2967+
.singleElement().isEqualTo(entity);
2968+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
2969+
.ids(Set.of(entity.getId()))
2970+
.findOne())
2971+
).isEqualTo(entity);
2972+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
2973+
.where("id").in(entity.getId())
2974+
.findOne())
2975+
).isEqualTo(entity);
2976+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
2977+
.where("id").eq(entity.getId())
2978+
.and("toStringDuration").isNull()
2979+
.findOne())
2980+
).isEqualTo(entity);
2981+
}
2982+
2983+
@Test(timeout = 30_000L)
2984+
public void toStringSlow() {
2985+
var loggerName = "tech.ydb.yoj.repository.db";
2986+
var config = LoggerContext.getContext().getConfiguration();
2987+
var prevLoggerLevel = config.getLoggerConfig(loggerName).getLevel();
2988+
try {
2989+
Configurator.setLevel(loggerName, Level.ERROR);
2990+
2991+
var entity = new BadToStringEntity(new BadToStringEntity.Id("id"), Duration.ofMinutes(5));
2992+
db.tx(() -> db.table(BadToStringEntity.class).save(entity));
2993+
assertThatExceptionOfType(EntityAlreadyExistsException.class)
2994+
.isThrownBy(() -> db.withMaxRetries(0).tx(() -> db.table(BadToStringEntity.class).insert(entity)));
2995+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(entity.getId()))).isEqualTo(entity);
2996+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).find(Set.of(entity.getId()))))
2997+
.singleElement().isEqualTo(entity);
2998+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
2999+
.ids(Set.of(entity.getId()))
3000+
.findOne())
3001+
).isEqualTo(entity);
3002+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3003+
.where("id").in(entity.getId())
3004+
.findOne())
3005+
).isEqualTo(entity);
3006+
assertThat(db.tx(() -> db.table(BadToStringEntity.class).query()
3007+
.where("id").eq(entity.getId())
3008+
.and("toStringDuration").isNotNull()
3009+
.findOne())
3010+
).isEqualTo(entity);
3011+
} finally {
3012+
Configurator.setLevel(loggerName, prevLoggerLevel);
3013+
}
3014+
}
3015+
29563016
protected void runInTx(Consumer<RepositoryTransaction> action) {
2957-
// We do not retry transactions, because we do not expect conflicts in our test scenarios.
3017+
// We do *not* retry low-level transactions (`RepositoryTransaction`s) because we don't expect to get conflicts
3018+
// in our test scenarios
29583019
RepositoryTransaction transaction = startTransaction();
29593020
try {
29603021
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;
@@ -62,7 +63,8 @@ private TestEntities() {
6263
MultiWrappedEntity.class,
6364
MultiWrappedEntity2.class,
6465
UniqueEntity.class,
65-
UniqueEntityNative.class
66+
UniqueEntityNative.class,
67+
BadToStringEntity.class
6668
);
6769

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

0 commit comments

Comments
 (0)