Major - P3 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.