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 ?