[SERVER-2602] Logging "query admin.$cmd ntoreturn:1 command:..." shows extremely high ms response times Created: 21/Feb/11  Updated: 12/Jul/16  Resolved: 02/Apr/12

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 1.7.5
Fix Version/s: 2.1.1

Type: Bug Priority: Minor - P4
Reporter: David Mytton Assignee: Eliot Horowitz (Inactive)
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Mon Feb 21 20:52:59 [initandlisten] db version v1.7.5, pdfile version 4.5
Mon Feb 21 20:52:59 [initandlisten] git version: 1978898d7a013657e5400133defdc996fb4c2c15
Mon Feb 21 20:52:59 [initandlisten] sys info: Linux domU-12-31-39-06-79-A1 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41


Issue Links:
Related
is related to SERVER-4527 Suppress long query messages for oplo... Closed
Operating System: ALL
Participants:

 Description   

Response times of e.g. 300028ms don't seem realistic

From mongod slave during initial replica set sync:

Mon Feb 21 21:04:47 [conn17] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5d5bb8c2504987772ec41b') }

reslen:60 300028ms
Mon Feb 21 21:04:49 [conn21] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5cf8b4b47bc4ea73aa83a1') }

reslen:60 300027ms
Mon Feb 21 21:05:20 [replica set sync] 1873579 objects cloned so far from collection sd.metrics
Mon Feb 21 21:05:29 [conn31] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5ba5a96ed04dfbd093cd97') }

reslen:60 300029ms
Mon Feb 21 21:06:21 [replica set sync] 2843732 objects cloned so far from collection sd.metrics
Mon Feb 21 21:06:21 [FileAllocator] allocating new datafile /mongodbdata/sd.4, filling with zeroes...
Mon Feb 21 21:06:22 [FileAllocator] done allocating datafile /mongodbdata/sd.4, size: 1024MB, took 1.145 secs
Mon Feb 21 21:07:22 [replica set sync] 3793311 objects cloned so far from collection sd.metrics
Mon Feb 21 21:07:45 [conn32] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5ba56021d7d00ef5bbe3b7') }

reslen:60 300031ms
Mon Feb 21 21:08:02 [conn33] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5a54108d4e400d241a4a83') }

reslen:60 300032ms
Mon Feb 21 21:08:24 [replica set sync] 4694503 objects cloned so far from collection sd.metrics
Mon Feb 21 21:09:25 [replica set sync] 5568644 objects cloned so far from collection sd.metrics
Mon Feb 21 21:09:46 [FileAllocator] allocating new datafile /mongodbdata/sd.5, filling with zeroes...
Mon Feb 21 21:09:47 [conn17] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5d5bb8c2504987772ec41b') }

reslen:60 300033ms
Mon Feb 21 21:09:49 [conn21] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5cf8b4b47bc4ea73aa83a1') }

reslen:60 300034ms
Mon Feb 21 21:09:50 [FileAllocator] done allocating datafile /mongodbdata/sd.5, size: 2047MB, took 4.153 secs
Mon Feb 21 21:10:27 [replica set sync] 6470217 objects cloned so far from collection sd.metrics
Mon Feb 21 21:10:29 [conn31] query admin.$cmd ntoreturn:1 command:

{ writebacklisten: ObjectId('4d5ba5a96ed04dfbd093cd97') }

reslen:60 300033ms



 Comments   
Comment by auto [ 02/Apr/12 ]

Author:

{u'login': u'erh', u'name': u'Eliot Horowitz', u'email': u'eliot@10gen.com'}

Message: SERVER-2602 supress writebacklist messages from log under normal verbosity
Branch: master
https://github.com/mongodb/mongo/commit/6c2bc1e8d3babd21ab49ec805b17a9c2e4c70fed

Comment by Eliot Horowitz (Inactive) [ 21/Feb/11 ]

For writebacks that's normal and correct.
We'll change the logging.

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