[SERVER-46875] Missing component in slow query logs Created: 15/Mar/20  Updated: 29/Oct/23  Resolved: 19/Mar/20

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: None
Fix Version/s: 4.4.0-rc0, 4.7.0

Type: Bug Priority: Major - P3
Reporter: Bruce Lucas (Inactive) Assignee: Henrik Edin
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4
Sprint: Dev Tools 2020-03-23
Participants:

 Description   

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}}



 Comments   
Comment by Githook User [ 26/Mar/20 ]

Author:

{'name': 'Henrik Edin', 'username': 'henrikedin', 'email': 'henrik.edin@mongodb.com'}

Message: SERVER-46875 Fix log component of slow query log

(cherry picked from commit 9fa3c10ac7517877066702e777582083d6322e1c)
Branch: v4.4
https://github.com/mongodb/mongo/commit/eb1b98df6b43071d57a2ff4d9ed69120c8f458e3

Comment by Githook User [ 19/Mar/20 ]

Author:

{'name': 'Henrik Edin', 'username': 'henrikedin', 'email': 'henrik.edin@mongodb.com'}

Message: SERVER-46875 Fix log component of slow query log
Branch: master
https://github.com/mongodb/mongo/commit/9fa3c10ac7517877066702e777582083d6322e1c

Comment by Henrik Edin [ 19/Mar/20 ]

bruce.lucas Yep, I'll take care of it.

Comment by Bruce Lucas (Inactive) [ 18/Mar/20 ]

Thanks henrik.edin. While you're touching that code would it also be possible to update the msg from "slow query" to "Slow query"?

Comment by Henrik Edin [ 18/Mar/20 ]

The component is not passed to the log statement in CurOp::completeAndLogOperation(). It was a regression during the conversion. I'll take this ticket and fix it tomorrow.

Comment by Kelsey Schubert [ 18/Mar/20 ]

This should be included in 4.4.0, flagging for re-triage by query team.

It's not clear to me whether this regression was the result of structuring logging or something else.

cc henrik.edin, gabriel.russell

Comment by Bruce Lucas (Inactive) [ 16/Mar/20 ]

The COMMAND and WRITE components are missing; the TXN component is not.

Generated at Thu Feb 08 05:12:41 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.