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

Missing component in slow query logs

    • Type: Icon: Bug Bug
    • Resolution: Fixed
    • Priority: Icon: Major - P3 Major - P3
    • 4.4.0-rc0, 4.7.0
    • Affects Version/s: None
    • Component/s: Logging
    • None
    • Fully Compatible
    • ALL
    • v4.4
    • Dev Tools 2020-03-23

      Some types of slow query logging statements are missing a component. Compare 4.2:

      2020-03-15T11:29:17.578-0400 I  COMMAND  [conn11] command test.c appName: "MongoDB Shell" command: insert { insert: "c", ordered: true, lsid: { id: UUID("ada91b37-fe1c-4990-8798-d9f3b9202c66") }, $clusterTime: { clusterTime: Timestamp(1584286156, 5), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, txnNumber: 0, autocommit: false, stmtId: 0, startTransaction: true, $db: "test" } ninserted:2 keysInserted:2 numYields:0 reslen:230 locks:{} storage:{} protocol:op_msg 0ms
      2020-03-15T11:29:17.581-0400 I  WRITE    [conn11] update test.c appName: "MongoDB Shell" command: { q: {}, u: { $set: { x: 1.0 } }, multi: true, upsert: false } planSummary: COLLSCAN keysExamined:0 docsExamined:2 nMatched:2 nModified:2 numYields:0 locks:{ Mutex: { acquireCount: { r: 1 } } } flowControl:{ acquireCount: 2 } storage:{} 0ms
      2020-03-15T11:29:17.581-0400 I  COMMAND  [conn11] command test.$cmd appName: "MongoDB Shell" command: update { update: "c", ordered: true, lsid: { id: UUID("ada91b37-fe1c-4990-8798-d9f3b9202c66") }, $clusterTime: { clusterTime: Timestamp(1584286157, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, txnNumber: 0, autocommit: false, stmtId: 2, $db: "test" } numYields:0 reslen:245 locks:{} storage:{} protocol:op_msg 0ms
      2020-03-15T11:29:17.583-0400 I  TXN      [conn11] transaction parameters:{ lsid: { id: UUID("ada91b37-fe1c-4990-8798-d9f3b9202c66"), uid: BinData(0, E3B0C44298FC1C149AFBF4C8996FB92427AE41E4649B934CA495991B7852B855) }, txnNumber: 0, autocommit: false, readConcern: { level: "snapshot" } }, readTimestamp:Timestamp(0, 0), ninserted:2 keysInserted:2 terminationCause:committed timeActiveMicros:1013 timeInactiveMicros:4412 numYields:0 locks:{ ReplicationStateTransition: { acquireCount: { w: 4 } }, Global: { acquireCount: { r: 1, w: 2 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 3 } }, Mutex: { acquireCount: { r: 8 } } } storage:{} wasPrepared:0, 5ms
      2020-03-15T11:29:17.583-0400 I  COMMAND  [conn11] command admin.$cmd appName: "MongoDB Shell" command: commitTransaction { commitTransaction: 1.0, txnNumber: 0, lsid: { id: UUID("ada91b37-fe1c-4990-8798-d9f3b9202c66") }, $clusterTime: { clusterTime: Timestamp(1584286157, 1), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, autocommit: false, stmtId: 3, $db: "admin" } numYields:0 reslen:163 locks:{ ReplicationStateTransition: { acquireCount: { w: 4 } }, Global: { acquireCount: { r: 1, w: 2 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 3 } }, Mutex: { acquireCount: { r: 8 } } } flowControl:{ acquireCount: 2 } protocol:op_msg 0ms
      

      with 4.4:

      {"t":{"$date":"2020-03-15T11:25:28.957-0400"},"s":"I", "c":"-",       "id":51803,"ctx":"conn12","msg":"slow query","attr":{"type":"command","ns":"test.c","appName":"MongoDB Shell","command":{"insert":"c","ordered":true,"lsid":{"id":{"$uuid":"0ed80567-f57e-492d-83f2-2ac4caedc004"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1584285927,"i":7}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"txnNumber":0,"autocommit":false,"stmtId":0,"startTransaction":true,"$db":"test"},"ninserted":2,"keysInserted":2,"numYields":0,"reslen":230,"locks":{},"storage":{},"protocol":"op_msg","durationMillis":0}}
      {"t":{"$date":"2020-03-15T11:25:28.958-0400"},"s":"I", "c":"-",       "id":51803,"ctx":"conn12","msg":"slow query","attr":{"type":"update","ns":"test.c","appName":"MongoDB Shell","command":{"q":{},"u":{"$set":{"x":1.0}},"multi":true,"upsert":false},"planSummary":"COLLSCAN","keysExamined":0,"docsExamined":2,"nMatched":2,"nModified":2,"numYields":0,"locks":{"Mutex":{"acquireCount":{"r":1}}},"flowControl":{"acquireCount":1},"storage":{},"durationMillis":0}}
      {"t":{"$date":"2020-03-15T11:25:28.958-0400"},"s":"I", "c":"-",       "id":51803,"ctx":"conn12","msg":"slow query","attr":{"type":"command","ns":"test.$cmd","appName":"MongoDB Shell","command":{"update":"c","ordered":true,"lsid":{"id":{"$uuid":"0ed80567-f57e-492d-83f2-2ac4caedc004"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1584285928,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"txnNumber":0,"autocommit":false,"stmtId":2,"$db":"test"},"numYields":0,"reslen":245,"locks":{},"storage":{},"protocol":"op_msg","durationMillis":0}}
      {"t":{"$date":"2020-03-15T11:25:28.959-0400"},"s":"I", "c":"TXN",     "id":51802,"ctx":"conn12","msg":"transaction","attr":{"parameters":{"lsid":{"id":{"$uuid":"0ed80567-f57e-492d-83f2-2ac4caedc004"},"uid":{"$binary":{"base64":"47DEQpj8HBSa+/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=","subType":"0"}}},"txnNumber":0,"autocommit":false,"readConcern":{"provenance":"implicitDefault"}},"readTimestamp":"Timestamp(0, 0)","ninserted":2,"keysInserted":2,"terminationCause":"committed","timeActiveMicros":492,"timeInactiveMicros":2373,"numYields":0,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":4}},"Global":{"acquireCount":{"r":1,"w":2}},"Database":{"acquireCount":{"w":3}},"Collection":{"acquireCount":{"w":3}},"Mutex":{"acquireCount":{"r":4}}},"storage":{},"wasPrepared":false,"durationMillis":2}}
      {"t":{"$date":"2020-03-15T11:25:28.959-0400"},"s":"I", "c":"-",       "id":51803,"ctx":"conn12","msg":"slow query","attr":{"type":"command","ns":"admin.$cmd","appName":"MongoDB Shell","command":{"commitTransaction":1.0,"txnNumber":0,"lsid":{"id":{"$uuid":"0ed80567-f57e-492d-83f2-2ac4caedc004"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1584285928,"i":1}},"signature":{"hash":{"$binary":{"base64":"AAAAAAAAAAAAAAAAAAAAAAAAAAA=","subType":"0"}},"keyId":0}},"autocommit":false,"stmtId":3,"$db":"admin"},"numYields":0,"reslen":163,"locks":{"ReplicationStateTransition":{"acquireCount":{"w":4}},"Global":{"acquireCount":{"r":1,"w":2}},"Database":{"acquireCount":{"w":3}},"Collection":{"acquireCount":{"w":3}},"Mutex":{"acquireCount":{"r":4}}},"flowControl":{"acquireCount":1},"protocol":"op_msg","durationMillis":0}}
      

            Assignee:
            henrik.edin@mongodb.com Henrik Edin
            Reporter:
            bruce.lucas@mongodb.com Bruce Lucas (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: