|
For example on a single NoSuchTransaction error it is incremented 5 times:
{"t":{"$date":"2021-05-05T14:30:00.793Z"},"s":"D1","c":"-","id":23074,"ctx":"conn540","msg":"User assertion","attr":{"error":"NoSuchTransaction: Transaction 1147 has been aborted.","file":"src/mongo/db/transaction_participant.cpp","line":1722}}
|
{"t":{"$date":"2021-05-05T14:30:00.798Z"},"s":"D1","c":"-","id":23074,"ctx":"conn540","msg":"User assertion","attr":{"error":"NoSuchTransaction: Transaction 1147 has been aborted.","file":"src/mongo/util/future_impl.h","line":1087}}
|
{"t":{"$date":"2021-05-05T14:30:00.798Z"},"s":"D1","c":"-","id":23074,"ctx":"conn540","msg":"User assertion","attr":{"error":"NoSuchTransaction: Transaction 1147 has been aborted.","file":"src/mongo/util/future_impl.h","line":1087}}
|
{"t":{"$date":"2021-05-05T14:30:00.798Z"},"s":"D1","c":"-","id":23074,"ctx":"conn540","msg":"User assertion","attr":{"error":"NoSuchTransaction: Transaction 1147 has been aborted.","file":"src/mongo/util/future_impl.h","line":1104}}
|
{"t":{"$date":"2021-05-05T14:30:00.798Z"},"s":"D1","c":"-","id":23074,"ctx":"conn540","msg":"User assertion","attr":{"error":"NoSuchTransaction: Transaction 1147 has been aborted.","file":"src/mongo/util/future_impl.h","line":1087}}
|
{"t":{"$date":"2021-05-05T14:30:00.798Z"},"s":"D1","c":"COMMAND","id":21962,"ctx":"conn540","msg":"Assertion while executing command","attr":{"command":"abortTransaction","db":"admin","commandArgs":{"abortTransaction":1,"writeConcern":{"w":1},"lsid":{"id":{"_uuid":"25b9bff7-546a-4867-8a24-0972ae04a827"}},"txnNumber":1147,"autocommit":false,"_clusterTime":{"clusterTime":{"_timestamp":{"t":1620225000,"i":9124}},"signature":{"hash":{"_binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"_db":"admin","_readPreference":{"mode":"primary"}},"error":"NoSuchTransaction: Transaction 1147 has been aborted."}}
|
{"t":{"$date":"2021-05-05T14:30:00.798Z"},"s":"I","c":"COMMAND","id":51803,"ctx":"conn540","msg":"Slow query","attr":{"type":"command","ns":"admin.$cmd","command":{"abortTransaction":1,"writeConcern":{"w":1},"lsid":{"id":{"_uuid":"25b9bff7-546a-4867-8a24-0972ae04a827"}},"txnNumber":1147,"autocommit":false,"_clusterTime":{"clusterTime":{"_timestamp":{"t":1620225000,"i":9124}},"signature":{"hash":{"_binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"_db":"admin","_readPreference":{"mode":"primary"}},"numYields":0,"ok":0,"errMsg":"Transaction 1147 has been aborted.","errName":"NoSuchTransaction","errCode":251,"reslen":303,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":2}},"Global":{"acquireCount":{"w":1}}},"flowControl":{"acquireCount":1,"timeAcquiringMicros":3},"writeConcern":{"w":1,"wtimeout":0,"provenance":"clientSupplied"},"storage":{},"remote":"10.2.0.10:38578","protocol":"op_msg","durationMillis":4}}
|
and on single WriteConflict error it is incremented 4 times:
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"W","c":"COMMAND","id":23802,"ctx":"conn478","msg":"Plan executor error during findAndModify","attr":{"error":{"code":112,"codeName":"WriteConflict","errmsg":"WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."},"stats":{"stage":"PROJECTION_DEFAULT","nReturned":0,"executionTimeMillisEstimate":0,"works":1,"advanced":0,"needTime":0,"needYield":1,"saveState":0,"restoreState":0,"isEOF":0,"transformBy":{},"inputStage":{"stage":"UPDATE","nReturned":0,"executionTimeMillisEstimate":0,"works":1,"advanced":0,"needTime":0,"needYield":1,"saveState":0,"restoreState":0,"isEOF":0,"nMatched":0,"nWouldModify":0,"nWouldUpsert":0,"inputStage":{"stage":"FETCH","nReturned":1,"executionTimeMillisEstimate":0,"works":1,"advanced":1,"needTime":0,"needYield":0,"saveState":1,"restoreState":0,"isEOF":0,"docsExamined":1,"alreadyHasObj":0,"inputStage":{"stage":"IXSCAN","nReturned":1,"executionTimeMillisEstimate":0,"works":1,"advanced":1,"needTime":0,"needYield":0,"saveState":1,"restoreState":0,"isEOF":0,"keyPattern":{"W_ID":1,"W_TAX":1},"indexName":"W_ID_1_W_TAX_1","isMultiKey":false,"multiKeyPaths":{"W_ID":[],"W_TAX":[]},"isUnique":true,"isSparse":false,"isPartial":false,"indexVersion":2,"direction":"forward","indexBounds":{"W_ID":["[25, 25]"],"W_TAX":["[MinKey, MaxKey]"]},"keysExamined":1,"seeks":1,"dupsTested":0,"dupsDropped":0}}}},"cmd":{"findAndModify":"WAREHOUSE","query":{"W_ID":25,"_comment":"PAYMENT"},"fields":{"W_NAME":1,"W_STREET_1":1,"W_STREET_2":1,"W_CITY":1,"W_STATE":1,"W_ZIP":1},"update":{"_inc":{"W_YTD":3359.84}},"upsert":false,"new":false}}}
|
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"D1","c":"-","id":23074,"ctx":"conn478","msg":"User assertion","attr":{"error":"WriteConflict: Plan executor error during findAndModify :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.","file":"src/mongo/util/future_impl.h","line":1087}}
|
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"D1","c":"-","id":23074,"ctx":"conn478","msg":"User assertion","attr":{"error":"WriteConflict: Plan executor error during findAndModify :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.","file":"src/mongo/util/future_impl.h","line":1087}}
|
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"D1","c":"-","id":23074,"ctx":"conn478","msg":"User assertion","attr":{"error":"WriteConflict: Plan executor error during findAndModify :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.","file":"src/mongo/util/future_impl.h","line":1104}}
|
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"D1","c":"-","id":23074,"ctx":"conn478","msg":"User assertion","attr":{"error":"WriteConflict: Plan executor error during findAndModify :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.","file":"src/mongo/util/future_impl.h","line":1087}}
|
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"D1","c":"COMMAND","id":21962,"ctx":"conn478","msg":"Assertion while executing command","attr":{"command":"findAndModify","db":"tpcc","commandArgs":{"findAndModify":"WAREHOUSE","query":{"W_ID":25,"_comment":"PAYMENT"},"new":false,"update":{"_inc":{"W_YTD":3359.84}},"fields":{"W_NAME":1,"W_STREET_1":1,"W_STREET_2":1,"W_CITY":1,"W_STATE":1,"W_ZIP":1},"upsert":false,"lsid":{"id":{"_uuid":"98df1da3-6b20-4a7c-9080-e9e3cf2e88ce"}},"txnNumber":1030,"autocommit":false,"_clusterTime":{"clusterTime":{"_timestamp":{"t":1620225000,"i":3360}},"signature":{"hash":{"_binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"_db":"tpcc","_readPreference":{"mode":"primary"}},"error":"WriteConflict: Plan executor error during findAndModify :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction."}}
|
{"t":{"$date":"2021-05-05T14:30:00.300Z"},"s":"I","c":"COMMAND","id":51803,"ctx":"conn478","msg":"Slow query","attr":{"type":"command","ns":"tpcc.WAREHOUSE","command":{"findAndModify":"WAREHOUSE","query":{"W_ID":25,"_comment":"PAYMENT"},"new":false,"update":{"_inc":{"W_YTD":3359.84}},"fields":{"W_NAME":1,"W_STREET_1":1,"W_STREET_2":1,"W_CITY":1,"W_STATE":1,"W_ZIP":1},"upsert":false,"lsid":{"id":{"_uuid":"98df1da3-6b20-4a7c-9080-e9e3cf2e88ce"}},"txnNumber":1030,"autocommit":false,"_clusterTime":{"clusterTime":{"_timestamp":{"t":1620225000,"i":3360}},"signature":{"hash":{"_binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"_db":"tpcc","_readPreference":{"mode":"primary"}},"planSummary":"IXSCAN { W_ID: 1, W_TAX: 1 }","numYields":0,"queryHash":"34051C0B","planCacheKey":"9B875C35","ok":0,"errMsg":"Plan executor error during findAndModify :: caused by :: WriteConflict error: this operation conflicted with another operation. Please retry your operation or multi-document transaction.","errName":"WriteConflict","errCode":112,"reslen":451,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":3}},"Global":{"acquireCount":{"r":1,"w":1}},"Database":{"acquireCount":{"w":1}},"Collection":{"acquireCount":{"w":2}},"Mutex":{"acquireCount":{"r":2}}},"flowControl":{"acquireCount":1,"timeAcquiringMicros":5},"readConcern":{"level":"majority","afterClusterTime":{"_timestamp":{"t":1620225000,"i":2308}},"provenance":"clientSupplied"},"storage":{},"remote":"10.2.0.10:38314","protocol":"op_msg","durationMillis":0}}
|
This makes the actual asserts.user count fairly meaningless for diagnostic purposes. The debug log messages show that extra uasserts are coming from utility code in future_impl.h, which suggests that a) the problem may be pervasive but 2) maybe it is easily fixed.
|