[SERVER-39757] Add execution details to slow transaction output Created: 22/Feb/19  Updated: 27/Oct/23  Resolved: 22/Feb/19

Status: Closed
Project: Core Server
Component/s: Logging, Querying
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: Shakir Sadikali Assignee: Unassigned
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Participants:

 Description   

We currently track and log statistics for slow transactions

mongodb.log.2019-02-21T16-06-35:2019-02-21T12:54:34.271+0000 W NETWORK  [conn29896] no SSL certificate provided by peer
mongodb.log.2019-02-21T16-06-35:2019-02-21T12:54:34.273+0000 I NETWORK  [conn29896] received client metadata from xxx.xxx.x.x:58319 conn29896: { driver: { name: "mongo-java-driver", version: "3.8.2" }, os: { type: "Windows", name: "Windows 10", architecture: "amd64", version: "10.0" }, platform: "Java/Oracle Corporation/1.8.0_74-b02" }
mongodb.log.2019-02-21T16-06-35:2019-02-21T12:54:35.946+0000 I ACCESS   [conn29896] Successfully authenticated as principal coreapi-dev on admin
mongodb.log.2019-02-21T16-06-35:2019-02-21T12:55:21.453+0000 I TXN      [conn29896] transaction parameters:{ lsid: { id: UUID("a91391af-e6b8-4956-8cd7-8bdfda3f7f37"), uid: BinData(0, 335C52DA77A8915F0E136B9BAADC6B97D45222CB52E41FAAE098BDA85E98DE30) }, txnNumber: 4, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(1550753706, 1), keysExamined:8 docsExamined:8 ninserted:3 keysInserted:19 terminationCause:committed timeActiveMicros:14066 timeInactiveMicros:9719327 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 5 } } } 9733ms
mongodb.log.2019-02-21T16-06-35:2019-02-21T12:55:53.494+0000 I TXN      [conn29896] transaction parameters:{ lsid: { id: UUID("a91391af-e6b8-4956-8cd7-8bdfda3f7f37"), uid: BinData(0, 335C52DA77A8915F0E136B9BAADC6B97D45222CB52E41FAAE098BDA85E98DE30) }, txnNumber: 5, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(1550753746, 1), keysExamined:7 docsExamined:7 ninserted:3 keysInserted:17 terminationCause:committed timeActiveMicros:7906 timeInactiveMicros:5400186 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 5 } } } 5408ms
mongodb.log.2019-02-21T16-06-35:2019-02-21T13:11:37.795+0000 I TXN      [conn29896] transaction parameters:{ lsid: { id: UUID("448dc2f9-ed81-4ea6-acc6-761f7591d3c7"), uid: BinData(0, 335C52DA77A8915F0E136B9BAADC6B97D45222CB52E41FAAE098BDA85E98DE30) }, txnNumber: 64, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(1550754686, 1), keysExamined:18 docsExamined:15 ninserted:7 keysInserted:50 terminationCause:committed timeActiveMicros:10910 timeInactiveMicros:6050666 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 5 } } } 6061ms
mongodb.log.2019-02-21T16-06-35:2019-02-21T13:26:06.377+0000 I NETWORK  [conn29896] end connection xxx.xxx.x.x:58319 (89 connections now open)

However, this doesn't help us determine what queries might have been slow within these transactions. It would be helpful to interleave the individual statements (as we do with all other slow operations) that are executed in the transaction in the logs.



 Comments   
Comment by Bruce Lucas (Inactive) [ 22/Feb/19 ]

We log any slow individual operations, and that should include the transaction information that would allow associating the slow individual operations, if there were any, with the slow transaction. In this case we can tell that the transaction was slow because it was waiting for the client to send the next operation, not because any operations were slow, because the transaction was inactive for most of the time:

timeActiveMicros:14066 timeInactiveMicros:9719327 ... 9733ms

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