Hello,
I have a Write Conflict that I hardly understand.
I’m using spring boot 3.3.1, I think the mongo client version is 5.0.1.
I’m trying to run a simple test to understand how operations with and without transactions behave together.
I wrote this test :
@Test
public void documentLockingTestOneSession() {
// Create a document
DummyDocument doc = new DummyDocument("test");
mongoTemplate.save(doc);
// A query to find the doc
Query findDoc = new Query().addCriteria(Criteria.where("uuid").is("test"));
// An update to change the lock value in the doc
Update lock = new Update().set("lock", "locked");
// An update of the doc
Update updateCollection = new Update().addToSet("simpleCollection", "something");
try (ClientSession session = client.startSession(ClientSessionOptions.builder()
.defaultTransactionOptions(TransactionOptions.builder().maxCommitTime(10L, TimeUnit.SECONDS).build())
.build())) {
session.startTransaction();
// Acquire lock on doc by writing on it
UpdateResult lockResult = mongoTemplate.withSession(session).updateFirst(findDoc, lock,
DummyDocument.class);
assertThat(lockResult.getModifiedCount()).isOne();
// Try to update the collection out of the transaction
UpdateResult changeResult = mongoTemplate.updateFirst(findDoc, updateCollection, DummyDocument.class);
assertThat(changeResult.getModifiedCount()).isOne();
session.commitTransaction();
} catch (MongoCommandException e) {
e.printStackTrace();
}
DummyDocument updatedDoc = mongoTemplate.findOne(findDoc, DummyDocument.class);
assertThat(updatedDoc.getLock()).isNull();
assertThat(updatedDoc.getSimpleCollection()).contains("something");
}
where the dummy document is
@Setter
class DummyDocument {
@MongoId
private String uuid;
private String lock;
private List simpleCollection = new ArrayList<>();public DummyDocument(String uuid) { this.uuid = uuid; }}
When I look at the logs in the DB I have something very curious :
{“t”:{“$date”:“2024-07-03T19:56:08.729+00:00”},“s”:“D4”, “c”:“TXN”, “id”:23984, “ctx”:“conn241”,“msg”:“New transaction started”,“attr”:{“txnNumberAndRetryCounter”:{“txnNumber”:1,“txnRetryCounter”:-1},“lsid”:{“id”:{“$uuid”:“30100543-2405-4ebc-81e4-06b44f5267f1”},“uid”:{“$binary”:{“base64”:“KtjD81gJ73AHqlcRRanM2JqDfWSolKhKcOzLN+hNjCM=”,“subType”:“0”}}},“apiParameters”:{}}}
{“t”:{“$date”:“2024-07-03T19:56:08.730+00:00”},“s”:“I”, “c”:“WRITE”, “id”:51803, “ctx”:“conn241”,“msg”:“Slow query”,“attr”:{“type”:“update”,“ns”:“test.dummyDocument”,“command”:{“q”:{“_id”:“test”},“u”:{“_id”:“test”,“simpleCollection”:,“_class”:“com.test.concurrency.DummyDocument”},“multi”:false,“upsert”:true},“planSummary”:“IDHACK”,“totalOplogSlotDurationMicros”:143,“keysExamined”:1,“docsExamined”:1,“nMatched”:1,“nModified”:1,“nUpserted”:0,“keysInserted”:0,“keysDeleted”:0,“numYields”:0,“locks”:{“ParallelBatchWriterMode”:{“acquireCount”:{“r”:2}},“FeatureCompatibilityVersion”:{“acquireCount”:{“w”:2}},“ReplicationStateTransition”:{“acquireCount”:{“w”:2}},“Global”:{“acquireCount”:{“w”:2}},“Database”:{“acquireCount”:{“w”:2}},“Collection”:{“acquireCount”:{“w”:2}}},“flowControl”:{“acquireCount”:1},“readConcern”:{“provenance”:“implicitDefault”},“storage”:{},“cpuNanos”:336086,“remote”:“172.18.0.1:37946”,“durationMillis”:0}}
{“t”:{“$date”:“2024-07-03T19:56:08.833+00:00”},“s”:“D4”, “c”:“TXN”, “id”:23984, “ctx”:“conn241”,“msg”:“New transaction started”,“attr”:{“txnNumberAndRetryCounter”:{“txnNumber”:2,“txnRetryCounter”:0},“lsid”:{“id”:{“$uuid”:“30100543-2405-4ebc-81e4-06b44f5267f1”},“uid”:{“$binary”:{“base64”:“KtjD81gJ73AHqlcRRanM2JqDfWSolKhKcOzLN+hNjCM=”,“subType”:“0”}}},“apiParameters”:{}}}
{“t”:{“$date”:“2024-07-03T19:56:08.834+00:00”},“s”:“I”, “c”:“WRITE”, “id”:51803, “ctx”:“conn241”,“msg”:“Slow query”,“attr”:{“type”:“update”,“ns”:“test.dummyDocument”,“command”:{“q”:{“_id”:“test”},“u”:{“$set”:{“lock”:“locked”}},“multi”:false,“upsert”:false},“planSummary”:“IDHACK”,“keysExamined”:1,“docsExamined”:1,“nMatched”:1,“nModified”:1,“nUpserted”:0,“keysInserted”:0,“keysDeleted”:0,“numYields”:0,“locks”:{“Database”:{“acquireCount”:{“w”:1}},“Collection”:{“acquireCount”:{“w”:1}}},“flowControl”:{“acquireCount”:1},“readConcern”:{“level”:“local”,“provenance”:“implicitDefault”},“storage”:{},“cpuNanos”:225979,“remote”:“172.18.0.1:37946”,“durationMillis”:0}}
{“t”:{“$date”:“2024-07-03T19:56:08.899+00:00”},“s”:“D4”, “c”:“TXN”, “id”:23984, “ctx”:“conn241”,“msg”:“New transaction started”,“attr”:{“txnNumberAndRetryCounter”:{“txnNumber”:1,“txnRetryCounter”:-1},“lsid”:{“id”:{“$uuid”:“dfc1c83c-0fad-4881-9315-978d9db11442”},“uid”:{“$binary”:{“base64”:“KtjD81gJ73AHqlcRRanM2JqDfWSolKhKcOzLN+hNjCM=”,“subType”:“0”}}},“apiParameters”:{}}}
{“t”:{“$date”:“2024-07-03T19:56:08.899+00:00”},“s”:“D1”, “c”:“WRITE”, “id”:4640401, “ctx”:“conn241”,“msg”:“Caught WriteConflictException”,“attr”:{“operation”:“plan execution”,“namespace”:“test.dummyDocument”,“attempts”:1}}
{“t”:{“$date”:“2024-07-03T19:56:08.899+00:00”},“s”:“D1”, “c”:“WRITE”, “id”:4640401, “ctx”:“conn241”,“msg”:“Caught WriteConflictException”,“attr”:{“operation”:“plan execution”,“namespace”:“test.dummyDocument”,“attempts”:2}}
HUNDREDS OF CONFLICTS
{“t”:{“$date”:“2024-07-03T19:57:15.934+00:00”},“s”:“D1”, “c”:“WRITE”, “id”:4640401, “ctx”:“conn241”,“msg”:“Caught WriteConflictException”,“attr”:{“operation”:“plan execution”,“namespace”:“test.dummyDocument”,“attempts”:853}}
{“t”:{“$date”:“2024-07-03T19:57:15.954+00:00”},“s”:“I”, “c”:“COMMAND”, “id”:20707, “ctx”:“abortExpiredTransactions”,“msg”:“Aborting transaction because it has been running for longer than ‘transactionLifetimeLimitSeconds’”,“attr”:{“sessionId”:{“uuid”:{“$uuid”:“30100543-2405-4ebc-81e4-06b44f5267f1”}},“txnNumberAndRetryCounter”:{“txnNumber”:2,“txnRetryCounter”:0}}}
{“t”:{“$date”:“2024-07-03T19:57:15.954+00:00”},“s”:“I”, “c”:“TXN”, “id”:51802, “ctx”:“abortExpiredTransactions”,“msg”:“transaction”,“attr”:{“parameters”:{“lsid”:{“id”:{“$uuid”:“30100543-2405-4ebc-81e4-06b44f5267f1”},“uid”:{“$binary”:{“base64”:“KtjD81gJ73AHqlcRRanM2JqDfWSolKhKcOzLN+hNjCM=”,“subType”:“0”}}},“txnNumber”:2,“txnRetryCounter”:0,“autocommit”:false,“readConcern”:{“level”:“local”,“provenance”:“implicitDefault”}},“readTimestamp”:“Timestamp(0, 0)”,“terminationCause”:“aborted”,“timeActiveMicros”:355,“timeInactiveMicros”:67119971,“numYields”:0,“locks”:{“FeatureCompatibilityVersion”:{“acquireCount”:{“w”:1}},“ReplicationStateTransition”:{“acquireCount”:{“w”:3}},“Global”:{“acquireCount”:{“w”:1}},“Database”:{“acquireCount”:{“w”:1}},“Collection”:{“acquireCount”:{“w”:1}}},“storage”:{},“wasPrepared”:false,“durationMillis”:67120}}
{“t”:{“$date”:“2024-07-03T19:57:16.035+00:00”},“s”:“I”, “c”:“WRITE”, “id”:51803, “ctx”:“conn241”,“msg”:“Slow query”,“attr”:{“type”:“update”,“ns”:“test.dummyDocument”,“command”:{“q”:{“_id”:“test”},“u”:{“$addToSet”:{“simpleCollection”:“something”}},“multi”:false,“upsert”:false},“planSummary”:“IDHACK”,“totalOplogSlotDurationMicros”:110,“keysExamined”:1,“docsExamined”:1,“nMatched”:1,“nModified”:1,“nUpserted”:0,“keysInserted”:0,“keysDeleted”:0,“writeConflicts”:853,“numYields”:853,“locks”:{“ParallelBatchWriterMode”:{“acquireCount”:{“r”:855}},“FeatureCompatibilityVersion”:{“acquireCount”:{“w”:855}},“ReplicationStateTransition”:{“acquireCount”:{“w”:855}},“Global”:{“acquireCount”:{“w”:855}},“Database”:{“acquireCount”:{“w”:855}},“Collection”:{“acquireCount”:{“w”:855}}},“flowControl”:{“acquireCount”:854},“readConcern”:{“provenance”:“implicitDefault”},“storage”:{},“cpuNanos”:209168296,“remote”:“172.18.0.1:37946”,“durationMillis”:67135}}
{“t”:{“$date”:“2024-07-03T19:57:16.040+00:00”},“s”:“I”, “c”:“COMMAND”, “id”:51803, “ctx”:“conn241”,“msg”:“Slow query”,“attr”:{“type”:“command”,“ns”:“test.$cmd”,“command”:{“update”:“dummyDocument”,“ordered”:true,“txnNumber”:1,“$db”:“test”,“$clusterTime”:{“clusterTime”:{“$timestamp”:{“t”:1720036568,“i”:1}},“signature”:{“hash”:{“$binary”:{“base64”:“5Jr32heYSlT0lvNbpu67i5wrtYs=”,“subType”:“0”}},“keyId”:7323334146405695495}},“lsid”:{“id”:{“$uuid”:“dfc1c83c-0fad-4881-9315-978d9db11442”}}},“numYields”:853,“reslen”:245,“locks”:{“ParallelBatchWriterMode”:{“acquireCount”:{“r”:856}},“FeatureCompatibilityVersion”:{“acquireCount”:{“r”:6,“w”:855}},“ReplicationStateTransition”:{“acquireCount”:{“w”:860}},“Global”:{“acquireCount”:{“r”:6,“w”:855}},“Database”:{“acquireCount”:{“r”:2,“w”:855}},“Collection”:{“acquireCount”:{“r”:2,“w”:855}}},“flowControl”:{“acquireCount”:854},“readConcern”:{“provenance”:“implicitDefault”},“writeConcern”:{“w”:“majority”,“wtimeout”:0,“provenance”:“implicitDefault”},“waitForWriteConcernDurationMillis”:5,“storage”:{},“cpuNanos”:209812093,“remote”:“172.18.0.1:37946”,“protocol”:“op_msg”,“durationMillis”:67141}}
{“t”:{“$date”:“2024-07-03T19:57:16.126+00:00”},“s”:“D4”, “c”:“TXN”, “id”:23984, “ctx”:“conn241”,“msg”:“New transaction started”,“attr”:{“txnNumberAndRetryCounter”:{“txnNumber”:3,“txnRetryCounter”:-1},“lsid”:{“id”:{“$uuid”:“30100543-2405-4ebc-81e4-06b44f5267f1”},“uid”:{“$binary”:{“base64”:“KtjD81gJ73AHqlcRRanM2JqDfWSolKhKcOzLN+hNjCM=”,“subType”:“0”}}},“apiParameters”:{}}}
{“t”:{“$date”:“2024-07-03T19:57:16.126+00:00”},“s”:“I”, “c”:“WRITE”, “id”:51803, “ctx”:“conn241”,“msg”:“Slow query”,“attr”:{“type”:“remove”,“ns”:“test.dummyDocument”,“command”:{“q”:{“_id”:“test”},“limit”:1},“planSummary”:“IDHACK”,“totalOplogSlotDurationMicros”:129,“keysExamined”:1,“docsExamined”:1,“ndeleted”:1,“keysDeleted”:1,“numYields”:0,“locks”:{“ParallelBatchWriterMode”:{“acquireCount”:{“r”:2}},“FeatureCompatibilityVersion”:{“acquireCount”:{“w”:2}},“ReplicationStateTransition”:{“acquireCount”:{“w”:2}},“Global”:{“acquireCount”:{“w”:2}},“Database”:{“acquireCount”:{“w”:2}},“Collection”:{“acquireCount”:{“w”:2}}},“flowControl”:{“acquireCount”:1},“readConcern”:{“level”:“local”,“provenance”:“implicitDefault”},“storage”:{},“cpuNanos”:313218,“remote”:“172.18.0.1:37946”,“durationMillis”:0}}
{“t”:{“$date”:“2024-07-03T19:57:16.146+00:00”},“s”:“I”, “c”:“NETWORK”, “id”:22944, “ctx”:“conn241”,“msg”:“Connection ended”,“attr”:{“remote”:“172.18.0.1:37946”,“uuid”:{“uuid”:{“$uuid”:“22dcc2d5-3f5d-455b-bfe2-7f780f32faa5”}},“connectionId”:241,“connectionCount”:39}}
{“t”:{“$date”:“2024-07-03T19:57:16.148+00:00”},“s”:“I”, “c”:“-”, “id”:20883, “ctx”:“conn240”,“msg”:“Interrupted operation as its client disconnected”,“attr”:{“opId”:549230}}
{“t”:{“$date”:“2024-07-03T19:57:16.148+00:00”},“s”:“I”, “c”:“NETWORK”, “id”:22944, “ctx”:“conn239”,“msg”:“Connection ended”,“attr”:{“remote”:“172.18.0.1:37930”,“uuid”:{“uuid”:{“$uuid”:“ef856df8-a6a0-4e95-9716-bbb0d6eef84d”}},“connectionId”:239,“connectionCount”:38}}
{“t”:{“$date”:“2024-07-03T19:57:16.149+00:00”},“s”:“I”, “c”:“NETWORK”, “id”:22944, “ctx”:“conn240”,“msg”:“Connection ended”,“attr”:{“remote”:“172.18.0.1:37934”,“uuid”:{“uuid”:{“$uuid”:“81df3c05-0f92-432f-ae72-2e6beefc4f23”}},“connectionId”:240,“connectionCount”:37}}
How can I prevent these hundreds of write conflict ? I expect to have at most a single one.
Thanks in advance if you find the time to help