-
Type:
Bug
-
Resolution: Fixed
-
Priority:
Minor - P4
-
Affects Version/s: None
-
Component/s: Replication
-
Fully Compatible
-
ALL
-
Repl 2019-01-28
Currently, when we log a slow transaction that was prepared, the log message looks like the following:
2018-12-05T15:41:19.094-0500 I TXN [main] transaction parameters:{ lsid: { id: UUID("d0b94b7f-b11c-455a-a276-588b2c4a866f"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB924
27AE41E4649B934CA495991B7852B855) }, txnNumber: 20, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(0, 0), keysExamined:1 docsExamined:1 nMatched
:1 nModified:1 ninserted:1 ndeleted:1 nmoved:1 keysInserted:1 keysDeleted:1 prepareReadConflicts:1 writeConflicts:1 terminationCause:aborted timeActiveMicros:0 timeInactiveMicros
:11000 numYields:0 locks:{ Global: { acquireCount: { r: 7, w: 9 } }, Database: { acquireCount: { r: 1, w: 1, W: 2 } }, Collection: { acquireCount: { R: 1 } }, oplog: { acquireCou
nt: { W: 1 } } } 11ms wasPrepared:0
The total transaction duration is no longer the final metric that is printed, and this breaks with the convention of matching the traditional slow operation logging format. The extra "prepare" info should go in the middle of the log message, and we should leave the total duration at the end.