[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] [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: {} } , 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 } 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. |