[SERVER-37756] add logging for the amount of time spent blocked on a prepare conflict Created: 25/Oct/18  Updated: 29/Oct/23  Resolved: 16/Sep/19

Status: Closed
Project: Core Server
Component/s: Diagnostics, Replication
Affects Version/s: None
Fix Version/s: 4.3.1

Type: Improvement Priority: Major - P3
Reporter: Pavithra Vetriselvan Assignee: Haley Connelly
Resolution: Fixed Votes: 0
Labels: SWDI, prepare_diagnostics, prepare_optional
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Backwards Compatibility: Fully Compatible
Sprint: Execution Team 2019-09-23
Participants:

 Description   

Currently, long running operations show up in currentOp along with the locks that they held here

We would like to do something similar for long running reads that were blocked on a prepare conflict.



 Comments   
Comment by Haley Connelly [ 16/Sep/19 ]

Added prepareConflictDuration to log the total time spent blocked on prepare conflicts when it is nonzero.
Snipped from log output when prepare_conflict.js is run.

[ReplicaSetFixture:job0:primary] 2019-09-16T13:08:32.145-0400 I  COMMAND  [conn15] command test.prepare_conflict appName: "MongoDB Shell" command: find { find: "prepare_conflict", filter: { _id: 1.0 }, readConcern: { afterClusterTime: Timestamp(1568653707, 4) }, maxTimeMS: 5000.0, lsid: { id: UUID("f1483faa-da4b-4b8b-b0b1-298c6960e550") }, $clusterTime: { clusterTime: Timestamp(1568653707, 4), signature: { hash: BinData(0, 0000000000000000000000000000000000000000), keyId: 0 } }, $db: "test" } planSummary: IDHACK prepareConflictDuration: 5015ms prepareReadConflicts:2 numYields:0 ok:0 errMsg:"operation exceeded time limit" errName:MaxTimeMSExpired errCode:50 reslen:246 locks:{ ParallelBatchWriterMode: { acquireCount: { r: 3 } }, ReplicationStateTransition: { acquireCount: { w: 4 } }, Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 3 } }, Collection: { acquireCount: { r: 1 } }, Mutex: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 2 } } } protocol:op_msg 5016ms 

Comment by Githook User [ 16/Sep/19 ]

Author:

{'name': 'Haley Connelly', 'username': 'haleyConnelly', 'email': 'haley.connelly@10gen.com'}

Message: SERVER-37756 add logging for the amount of time spent blocked on a prepare conflict
Branch: master
https://github.com/mongodb/mongo/commit/911acee4d9f06ee33416b80bf4e65fa966fdd31a

Comment by Bruce Lucas (Inactive) [ 29/Oct/18 ]

I'm not sure what exactly is missing and what is to be added. In general, every running operation should show up in currentOp in some form. If the reads mentioned are not showing up at all, then in my view it's required to fix that. If they are showing up but have missing information relating to what they're blocked on, then it's highly desirable that that should be added.

 

So short answer is yes, required or highly desirable depending on the details.

Comment by Gregory McKeon (Inactive) [ 29/Oct/18 ]

kelsey.schubert bruce.lucas@mongodb.com how helpful do you think this would be for diagnostics?

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