Details
-
Bug
-
Resolution: Fixed
-
Minor - P4
-
None
-
Fully Compatible
-
ALL
-
Repl 2019-01-28
Description
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.