|
I took a more in-depth look at this today and here are my findings.
Timeline for a successful execution:
(1) Create a collection (with an _id index).
|
|
(2) Start a transaction, do an insert and prepare.
|
- WT_SESSION::begin_transaction()
|
- {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x5587763a6710","snapshotId":311}}
|
- insert {_id: 1}
|
- WT_SESSION::prepare_transaction()
|
- {"msg":"(1) WT_SESSION::prepare_transaction","attr":{"config":"prepare_timestamp=61F188A20000001B","session":"0x5587763a6710","snapshotId":311,"prepTS":{"$timestamp":{"t":1643219106,"i":27}}}}
|
- {"msg":"(2) WT_SESSION::prepare_transaction","attr":{"session":"0x5587763a6710"}}
|
|
(3) Try to insert {_id: 1} in another transaction.
|
- WT_SESSION::begin_transaction()
|
- {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x5587763a6af8","snapshotId":327}}
|
- insert {_id: 1} --> WT_ROLLBACK (write conflict)
|
- WT_SESSION::rollback_transaction()
|
- {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x5587763a6af8","snapshotId":327}}
|
- {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x5587763a6af8"}}
|
- User gets an error (expected)
|
- {"msg":"User assertion","attr":{"error":"WriteConflict: WiredTigerIdIndex::_insert: index: _id_; uri: table:index-41-531312270660082275 :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}
|
|
(4) Abort the prepared transaction from (2).
|
- {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x5587763a6710","snapshotId":311}}
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219106,"ts_usec":557843,"thread":"11558:0x7f26c928d700","session_dhandle_name":"file:index-41-531312270660082275.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 176and timestamp:(1643219106, 27)"}}}
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219106,"ts_usec":557874,"thread":"11558:0x7f26c928d700","session_dhandle_name":"file:collection-40-531312270660082275.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 176and timestamp:(1643219106, 27)"}}}
|
- {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x5587763a6710"}}
|
|
(5) Start a transaction, do an insert, and abort.
|
- WT_SESSION::begin_transaction()
|
- {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x5587763a6710","snapshotId":345}}
|
- insert {_id: 1}
|
- WT_SESSION::rollback_transaction()
|
- {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x5587763a6710","snapshotId":345}}
|
- {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x5587763a6710"}}
|
Timeline for a failed execution:
(1) Create a collection (with an _id index).
|
|
(2) Start a transaction, do an insert and prepare.
|
- WT_SESSION::begin_transaction()
|
- {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x55a07bd6e710","snapshotId":27179}}
|
- insert {_id: 1}
|
- WT_SESSION::prepare_transaction()
|
- {"msg":"(1) WT_SESSION::prepare_transaction","attr":{"config":"prepare_timestamp=61F189A800000091","session":"0x55a07bd6e710","snapshotId":27179,"prepTS":{"$timestamp":{"t":1643219368,"i":145}}}}
|
- {"msg":"(2) WT_SESSION::prepare_transaction","attr":{"session":"0x55a07bd6e710"}}
|
|
(3) Try to insert {_id: 1} in another transaction.
|
- WT_SESSION::begin_transaction()
|
- {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x55a07bd6eaf8","snapshotId":27199}}
|
- insert {_id: 1} --> WT_ROLLBACK (write conflict)
|
- WT_SESSION::rollback_transaction()
|
- {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x55a07bd6eaf8","snapshotId":27199}}
|
- {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x55a07bd6eaf8"}}
|
- User gets an error (expected)
|
- {"msg":"User assertion","attr":{"error":"WriteConflict: WiredTigerIdIndex::_insert: index: _id_; uri: table:index-41-5942478661676268792 :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}
|
|
(4) Abort the prepared transaction from (2).
|
- {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x55a07bd6e710","snapshotId":27179}}
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313459,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313538,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:collection-40-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
|
- {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x55a07bd6e710"}}
|
|
(5) Start a transaction, do an insert, hit an unexpected write conflict.
|
- WT_SESSION::begin_transaction()
|
- {"msg":"(1) WT_SESSION::begin_transaction","attr":{"readAtTimestamp":{"$timestamp":{"t":0,"i":0}},"session":"0x55a07bd6e710","snapshotId":27217}}
|
- insert {_id: 1} --> WT_ROLLBACK (write conflict, unexpected)
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315338,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Conflict with update 3236 at start timestamp: (1643219368, 145)"}}}
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315368,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"snapshot_min=3240, snapshot_max=3240, snapshot_count=0"}}}
|
- {"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315384,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Rollback reason: conflict between concurrent operations"}}}
|
- WT_SESSION::rollback_transaction()
|
- {"msg":"(1) WT_SESSION::rollback_transaction","attr":{"config":"","session":"0x55a07bd6e710","snapshotId":27217}}
|
- {"msg":"(2) WT_SESSION::rollback_transaction","attr":{"ret":0,"session":"0x55a07bd6e710"}}
|
- User gets an error (unexpected)
|
- {"msg":"User assertion","attr":{"error":"WriteConflict: WiredTigerIdIndex::_insert: index: _id_; uri: table:index-41-5942478661676268792 :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}
|
In the failed execution, on step (4), we see that the prepared transaction gets rolled back:
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313459,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
|
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":313538,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:collection-40-5942478661676268792.wt","session_name":"WT_SESSION.rollback_transaction","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"rollback resolving prepared transaction with txnid: 3236and timestamp:(1643219368, 145)"}}}
|
But in step (5), when trying to index the record, we run into a write conflict of what was already rolled back:
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315338,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Conflict with update 3236 at start timestamp: (1643219368, 145)"}}}
|
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315368,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"snapshot_min=3240, snapshot_max=3240, snapshot_count=0"}}}
|
{"msg":"WiredTiger message","attr":{"message":{"ts_sec":1643219368,"ts_usec":315384,"thread":"12480:0x7f125d901700","session_dhandle_name":"file:index-41-5942478661676268792.wt","session_name":"WT_CURSOR.insert","category":"WT_VERB_TRANSACTION","category_id":39,"verbose_level":"DEBUG","verbose_level_id":1,"msg":"Rollback reason: conflict between concurrent operations"}}}
|
This is what caused the test to fail. We begin a new transaction in step (5) after rolling back in step (4) and hit an unexpected prepare conflict. Could we be hitting some sort of race in WiredTiger? I've only been able to reproduce this on an optimized build while running WiredTiger in-memory mode after ~500-750 executions of the attached test.
I attached more verbose logging and a git diff with my debug logging. It can be run using this command:
python3 buildscripts/resmoke.py --storageEngine=inMemory --suites=core_txns jstests/core/txns/commit_prepared_transaction_errors.js
|
I should also point out that if step (3) is removed ("Block 2" in the attached jstest), this is no longer reproducible.
|