Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-39757

Add execution details to slow transaction output

    XMLWordPrintable

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Works as Designed
    • Affects Version/s: None
    • Fix Version/s: None
    • Component/s: Logging, Querying
    • Labels:
      None

      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.

        Attachments

          Activity

            People

            Assignee:
            Unassigned Unassigned
            Reporter:
            shakir.sadikali Shakir Sadikali
            Participants:
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: