[SERVER-38423] Prepared transaction stats should not go at end of slow transaction log message Created: 05/Dec/18  Updated: 29/Oct/23  Resolved: 22/Jan/19

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: None
Fix Version/s: 4.1.8

Type: Bug Priority: Minor - P4
Reporter: William Schultz (Inactive) Assignee: Judah Schvimer
Resolution: Fixed Votes: 1
Labels: prepare_diagnostics
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Repl 2019-01-28
Participants:

 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.



 Comments   
Comment by Githook User [ 22/Jan/19 ]

Author:

{'username': 'judahschvimer', 'email': 'judah@mongodb.com', 'name': 'Judah Schvimer'}

Message: SERVER-39083 SERVER-38423 improve transaction stats for slow transaction logs
Branch: master
https://github.com/mongodb/mongo/commit/38f7e69c879296f6b779bc4a3f80ba47ea6cbd9d

Comment by Bruce Lucas (Inactive) [ 10/Dec/18 ]

Would the most logical thing be to group it with other existing transaction-related fields, e.g. prepareReadConflicts, terminationCause, or parameters? (I'm not sure whether those are very logically grouped currently, but I think at least we shouldn't make it worse.)

Comment by Judah Schvimer [ 09/Dec/18 ]

bruce.lucas, do you have a preference for where in the log message wasPrepared should go? Does right before the 11ms above make sense?

Comment by Bruce Lucas (Inactive) [ 07/Dec/18 ]

I would like to raise this to P3 and 4.1 required. This is essential for tools that parse log files.

Generated at Thu Feb 08 04:48:55 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.