[SERVER-36461] Add 'transaction' identifier to slow transaction log output Created: 06/Aug/18  Updated: 29/Oct/23  Resolved: 08/Aug/18

Status: Closed
Project: Core Server
Component/s: Diagnostics, Replication
Affects Version/s: None
Fix Version/s: 4.0.2, 4.1.2

Type: Bug Priority: Major - P3
Reporter: William Schultz (Inactive) Assignee: Nathan Louie
Resolution: Fixed Votes: 0
Labels: per-txn-metrics
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Related
is related to SERVER-35433 Log slow transactions when they finish Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.0
Sprint: Repl 2018-08-13
Participants:

 Description   

We should add an identifier to the log message for slow transactions so that we know the information logged corresponds to a transaction. This could be as simple as prefixing the log message with 'transaction'. Currently, slow transaction log messages look like the following:

I COMMAND  [main] parameters:{ lsid: { id: UUID("1d7db5e4-e684-482e-b903-eb23203d14d8"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) }, txnNumber: 1, 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:committed timeActiveMicros:11142 timeInactiveMicros:3 numYields:0 locks:{ Global: { acquireCount: { r: 6, w: 4 } }, Database: { acquireCount: { r: 1, w: 1, W: 2 } }, Collection: { acquireCount: { R: 1 } }, oplog: { acquireCount: { W: 1 } } } 11ms

We could change them to look to something like:

I COMMAND  [main] transaction parameters:{ lsid: { id: UUID("1d7db5e4-e684-482e-b903-eb23203d14d8"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) }, txnNumber: 1, 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:committed timeActiveMicros:11142 timeInactiveMicros:3 numYields:0 locks:{ Global: { acquireCount: { r: 6, w: 4 } }, Database: { acquireCount: { r: 1, w: 1, W: 2 } }, Collection: { acquireCount: { R: 1 } }, oplog: { acquireCount: { W: 1 } } } 11ms



 Comments   
Comment by Githook User [ 16/Aug/18 ]

Author:

{'username': 'nxlouie', 'email': 'nathan.louie@10gen.com', 'name': 'Nathan Louie'}

Message: SERVER-36461 Add 'transaction' identifier to slow transaction log output

(cherry picked from commit 4b6a5591cf912f6cadaf2f1ede5d58ad2bb694c6)
Branch: v4.0
https://github.com/mongodb/mongo/commit/199963de3d57ffcb1db7acd75911d547a4cd6f31

Comment by Githook User [ 08/Aug/18 ]

Author:

{'name': 'Nathan Louie', 'email': 'nathan.louie@10gen.com', 'username': 'nxlouie'}

Message: SERVER-36461 Add 'transaction' identifier to slow transaction log output
Branch: master
https://github.com/mongodb/mongo/commit/4b6a5591cf912f6cadaf2f1ede5d58ad2bb694c6

Comment by William Schultz (Inactive) [ 07/Aug/18 ]

Ok, we will go ahead and add a kTransaction logging component.

Comment by Esha Maharishi (Inactive) [ 07/Aug/18 ]

I would just like to be careful not to log anything not related to transactions under kTransaction (e.g., we should not log anything for a retryable write under kTransaction).

Comment by Esha Maharishi (Inactive) [ 07/Aug/18 ]

Yeah, sounds fine to me. I realize kSession is probably too general since sessions encompass so many different features (causal consistency, retryable writes, transactions).

Comment by Judah Schvimer [ 07/Aug/18 ]

I think with renctan's refactor, the boundary between retryable writes and transactions will become a lot clearer as well which should reduce the chance that we introduce a new kTransaction log message that gets logged for retryable writes as well.

Comment by Tess Avitabile (Inactive) [ 07/Aug/18 ]

I think it is fine to just create the kTransaction log component. I don't believe we have any logging at the moment about retryable writes, and that logging could go in the kWrite component anyway. And I don't believe we have any logging around session killing or expiration unrelated to transactions.

I'm not aware of other transaction log messages, except for this one, which Randolph is removing because it is out of date.

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

On the face of it I think it sounds like a good idea to log all transaction-related messages under a new TXN component. However I don't have a broad enough view of what those messages are to know whether that stands up to scrutiny. How much effort is it to identify all such messages to a) assess whether it makes sense and b) make the change if so?

Comment by William Schultz (Inactive) [ 07/Aug/18 ]

Also, tess.avitabile judah.schvimer esha.maharishi are we OK with adding this as an isolated kTransaction log component to start, or do we think we should first add a kSession component and make this a child component of that?

Comment by William Schultz (Inactive) [ 07/Aug/18 ]

spencer Are you implying we need to answer that question before we commit this change?

Comment by Spencer Brody (Inactive) [ 06/Aug/18 ]

If we're adding a new TXN log component, do we need a separate ticket to switch existing txn-related log messages (if there are any) to use the new component?

CC judah.schvimer

Comment by William Schultz (Inactive) [ 06/Aug/18 ]

Sounds good. We will add that.

Comment by Bruce Lucas (Inactive) [ 06/Aug/18 ]

Yes I think both would be useful: TXN component to show that this relates to transactions generally, "transaction" to indicate this is reporting on a transaction per se (vs some other logging that might relate to transactions but not be reporting on the transaction as such, if that makes sense...)

Comment by William Schultz (Inactive) [ 06/Aug/18 ]

For sake of time, we omitted adding the new logging component as part of the original ticket. If you think both would be useful, we can do both as part of this ticket.

Comment by Bruce Lucas (Inactive) [ 06/Aug/18 ]

I think that's fine, but I think we also had decided to log them under a new component TXN since COMMAND isn't right as this is not a command as such. Can we make both changes as part of this ticket?

Comment by William Schultz (Inactive) [ 06/Aug/18 ]

bruce.lucas Do you think this is a reasonable way to identify "slow" transactions in the log? My thought was that we should add something analogous to the "command: find" string that we would see in the logs for slow commands. If we don't add any identifier it is a bit difficult in my opinion to immediately identify that the log line actually represents information about a transaction.

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