[SERVER-9935] occasionally timeout when use mongos Created: 14/Jun/13  Updated: 10/Dec/14  Resolved: 17/Oct/13

Status: Closed
Project: Core Server
Component/s: Performance, Querying, Sharding
Affects Version/s: 2.2.3
Fix Version/s: None

Type: Question Priority: Major - P3
Reporter: peanutgyz Assignee: Randolph Tan
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

linux, mongo php 1.3.5 mongod 2.2


Participants:

 Description   

when use mongos , 2 shard (each has 2 mongod , 1 arbiter),

we set timeout 300ms , use php mongo 1.3.5

somtimes timeout , 5000 times one day with 1,000,000 queries.

I set loglevel 5 on mongos , then get log

Fri Jun 14 12:43:05 [conn131878] Request::process begin ns: database.collection msg id: 288 op: 2004 attempt: 0
Fri Jun 14 12:43:05 [conn131878] shard query: database.collection

{ _id: "the_key_to_be_found" }

Fri Jun 14 12:43:05 [conn131878] [pcursor] creating pcursor over QSpec { ns: "database.collection", n2skip: 0, n2return: -1, options: 0, query:

{ _id: "the_key_to_be_found" }

, fields: {} } and CInfo { v_ns: "", filter: {} }
Fri Jun 14 12:43:05 [conn131878] [pcursor] initializing over 1 shards required by [database.collection @ 604|27||512470419a06f4a9452a082e]Fri Jun 14 12:43:05 [conn131878] [pcursor] initializing on shard shard0001:shard0001/mongod_server1,mongod_server2, current connection state is { state: {}, retryNext: false, init: false, finish: false, errored: false }Fri Jun 14 12:43:05 [conn131878] [pcursor] initialized query (lazily) on shard shard0001:shard0001/mongod_server1,mongod_server2, current connection state is { state:

{ conn: "shard0001/mongod_server1,mongod_server2", vinfo: "database.collection @ 604|27||512470419a06f4a9452a082e", cursor: "(empty)", count: 0, done: false }

, retryNext: false, init: true, finish: false, errored: false }Fri Jun 14 12:43:05 [conn131878] [pcursor] finishing over 1 shardsFri Jun 14 12:43:05 [conn131878] [pcursor] finishing on shard shard0001:shard0001/mongod_server1,mongod_server2, current connection state is { state:

{ conn: "shard0001/mongod_server1,mongod_server2", vinfo: "database.collection @ 604|27||512470419a06f4a9452a082e", cursor: "(empty)", count: 0, done: false }

, retryNext: false, init: true, finish: false, errored: false }Fri Jun 14 12:43:06 [conn131878] [pcursor] finished on shard shard0001:shard0001/mongod_server1,mongod_server2, current connection state is { state:

{ conn: "(done)", vinfo: "database.collection @ 604|27||512470419a06f4a9452a082e", cursor: "(empty)", count: 0, done: false }

, retryNext: false, init: true, finish: true, errored: false }
Fri Jun 14 12:43:06 [conn131878] cursor type: ParallelSort
Fri Jun 14 12:43:06 [conn131878] hasMore: 0 sendMore: 0 cursorMore: 0 ntoreturn: 1 num: 0 wouldSendMoreIfHad: 0 id:4637175563515114743 totalSent: 0
Fri Jun 14 12:43:06 [conn131878] Request::process end ns: database.collection msg id: 288 op: 2004 attempt: 0 903ms

query used 903ms on mongos, but on mongod

Fri Jun 14 12:43:05 [conn42608] runQuery called onebox_storage_main.onebox_data

{ _id: "the_key_to_be_found" }

Fri Jun 14 12:43:06 [conn42608] query onebox_storage_main.onebox_data query:

{ _id: "the_key_to_be_found" }

ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:58 reslen:20 0ms

it took 0ms.

why mongos slow ?



 Comments   
Comment by Randolph Tan [ 11/Jul/13 ]

The time displayed in the logs is the time when the thread becomes active and started processing the message. This means that it does not include the time between the message sitting in the network buffer and the time the thread gets its time slice and consumes the message from the buffer. How many concurrent connections do you have on the mongod?

Comment by peanutgyz [ 17/Jun/13 ]

tcpdump show that

mongod receive packet, then send ack packet.

and after 700ms, mongod send the first response packet out.

but , in mongod log , show that the query only took 0ms.

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