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

Add execution details to slow transaction output

    XMLWordPrintable

Details

    • Improvement
    • Status: Closed
    • Major - P3
    • Resolution: Works as Designed
    • None
    • None
    • Logging, Querying
    • 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

            Unassigned Unassigned
            shakir.sadikali@mongodb.com Shakir Sadikali
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: