[SERVER-37927] Print readConcern and writeConcern for slow queries Created: 05/Nov/18  Updated: 27/Oct/23  Resolved: 07/Nov/18

Status: Closed
Project: Core Server
Component/s: Logging
Affects Version/s: 4.0.3
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: Henrik Ingo (Inactive) Assignee: Backlog - Service Architecture
Resolution: Works as Designed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to PYTHON-1668 Expand transaction documentation for ... Backlog
Assigned Teams:
Service Arch
Participants:

 Description   

In PYTHON-1668 I would have wanted to verify readConcern and writeConcern for queries logged to mongod.log. I couldn't see those, even if readPreference is logged. I also am not aware of another way to log readConcern or writeConcern, but admittedly didn't try the debug log levels.

I don't know if we can add more info to slow query logging, bur readConcern and writeConcern seem like a big deal, for example compared to readPreference.



 Comments   
Comment by Henrik Ingo (Inactive) [ 07/Nov/18 ]

Ok, I reran and looking closer. The readConcern is in the first operation of a transaction, right next to startTransaction:

2018-11-07T07:46:45.411+0200 I COMMAND  [conn50] command test.hltest command: find { find: "hltest", filter: { _id: 1 }, limit: 1, singleBatch: true, lsid: { id: UUID("a2d9e096-02a3-41ee-88f2-a8af76f5ee00") }, startTransaction: true, readConcern: { level: "snapshot" }, txnNumber: 100, autocommit: false, $clusterTime: { clusterTime: Timestamp(1541569605, 59), signature: { keyId: 0, hash: BinData(0, 0000000000000000000000000000000000000000) } }, $db: "test", $readPreference: { mode: "primaryPreferred" } } planSummary: IDHACK keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:249 locks:{} protocol:op_msg 0ms

...but doesn't re-appear in the additional reads nor writes.

And the writeConcern is in the commitTransaction, but not in the individual writes, which makes sense, as the writeConcern applies to the commit (and this is when the driver sends it too).

2018-11-07T07:46:45.419+0200 I COMMAND  [conn50] command admin.$cmd command: commitTransaction { commitTransaction: 1, txnNumber: 100, autocommit: false, writeConcern: { w: "majority" }, lsid: { id: UUID("a2d9e096-02a3-41ee-88f2-a8af76f5ee00") }, $clusterTime: { clusterTime: Timestamp(1541569605, 59), signature: { keyId: 0, hash: BinData(0, 0000000000000000000000000000000000000000) } }, $db: "admin", $readPreference: { mode: "primary" } } numYields:0 reslen:163 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 3 } }, Collection: { acquireCount: { w: 2 } }, oplog: { acquireCount: { w: 1 } } } protocol:op_msg 4ms

The reason I didn't see them at first is that in Case 3 in PYTHON-1668 the client doesn't send any read or write concern, server default is used and nothing is logged about that. (Essentially, what is logged is what the client sent.)

I will close this ticket, but thanks for telling me where to look.

Comment by Henrik Ingo (Inactive) [ 06/Nov/18 ]

Unfortunately I seem to have neglected to keep the mongod.log and it's lost in the cloud now. But I did set slowms to -1 and did see my queries. I saw readPreference but no readConcern on queries. Maybe it was there for the transaction line?

I guess for PYTHON-1668 I'm really more worried about write concern.

I think I need to rerun test for PYTHON-1668 with more verbose (or attention to...) logging. I will double check your statement as well. You can assign this to me while waiting, if that is correct process wise.

Comment by Bruce Lucas (Inactive) [ 06/Nov/18 ]

I believe we do log readConcern for the transaction, and since slow transaction logging follows the same slowms setting as the individual operations, if those were logged the transaction should have been logged. Would that have been sufficient for PYTHON-1668?

Generated at Thu Feb 08 04:47:26 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.