[SERVER-19649] awaitData queries are logged to slow query log if maxTimeMS expires Created: 29/Jul/15  Updated: 19/Sep/15  Resolved: 04/Sep/15

Status: Closed
Project: Core Server
Component/s: Querying
Affects Version/s: 3.1.6
Fix Version/s: 3.1.8

Type: Bug Priority: Major - P3
Reporter: Kamran K. Assignee: YunHe Wang
Resolution: Done Votes: 0
Labels: 32qa, neweng
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
is related to SERVER-19307 Use find/getmore commands in bgsync t... Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

var rst = new ReplSetTest({nodes: 3});
rst.startSet();
rst.initiate();
 
// perform a dummy insert
rst.getPrimary().getDB('test').foo.insert({});
 
// sleep to allow time for the slow query messages to appear
sleep(30000);

Sprint: Quint 9 09/18/15
Participants:

 Description   

In recent versions of 3.1.x, an idle replica set will emit slow query messages for getMores on the primary:

m31000| 2015-07-29T13:26:11.359-0400 I COMMAND  [conn10] command local.oplog.rs command: getMore { getMore: 22205584705, collection: "oplog.rs", maxTimeMS: 2000 } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:1 reslen:86 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 2001ms
m31000| 2015-07-29T13:26:11.359-0400 I COMMAND  [conn11] command local.oplog.rs command: getMore { getMore: 21801738166, collection: "oplog.rs", maxTimeMS: 2000 } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:1 reslen:86 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 2001ms
m31000| 2015-07-29T13:26:13.361-0400 I COMMAND  [conn11] command local.oplog.rs command: getMore { getMore: 21801738166, collection: "oplog.rs", maxTimeMS: 2000 } ntoreturn:1 ntoskip:0 keyUpdates:0 writeConflicts:0 numYields:1 reslen:86 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 2000ms
...

Potential issues here:
1 - Idle replica sets shouldn't be so chatty (3.0.5 is much less verbose)
2 - awaitData information seems to be missing from the log messages



 Comments   
Comment by Githook User [ 04/Sep/15 ]

Author:

{u'name': u'Yunhe (John) Wang', u'email': u'yunhe.wang@mongodb.com'}

Message: SERVER-19649 don't log awaitData queries that exceed slowms while waiting

Closes #1015

Signed-off-by: David Storch <david.storch@10gen.com>
Branch: master
https://github.com/mongodb/mongo/commit/053154edfbdaa770f5c099cb2c16a24cb5d3a7e1

Comment by Eric Milkie [ 29/Jul/15 ]

Note that if the query returns any data, we should log the query if it exceeds the slowms level. However, if the query returns no data, we should not log it, even if it await-data'd longer than slowms. This is the behavior of OP_QUERY and OP_GETMORE.

Comment by Eric Milkie [ 29/Jul/15 ]

It's probably all awaitdata queries, for both the find and getMore commands.

Generated at Thu Feb 08 03:51:39 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.