Php
MongoDB 副本集故障轉移導致 1000 倍的查詢響應時間增加
我正在測試生產 MongoDB 副本集故障轉移。當我手動使其中一個實例失敗時，我看到一個大約。我的 PHP 查詢的響應時間減少了 1000 倍（一千倍）。
我正在使用最新的 MongoDB (2.2.2) 和最新的 php 驅動程序 (1.3.3)。我有一個 3 伺服器副本集和一個 php 測試，它可以進行兩個相同的呼叫。
有沒有其他人看過這個？有人可以建議更改我的配置來修復它嗎？對我來說這是一個停船問題。
詳情如下… 注意：我沒有通過初級考試 我沒有通過二級考試，但軼事測試表明它沒有任何區別。
非常感謝您提供的任何見解。
-- ReplicaSet Config test:PRIMARY> rs.conf() { "_id" : "test", "version" : 10, "members" : [ { "_id" : 1, "host" : "10.0.1.1:27017", "priority" : 20 }, { "_id" : 2, "host" : "10.0.3.3:27017", "priority" : 10 }, { "_id" : 3, "host" : "10.0.2.2:27017" } ] } -- ReplicaSet status when everything is working (e.g. I don't firewall off a SECONDARY) test:PRIMARY> rs.status() { "set" : "test", "date" : ISODate("2013-01-24T16:32:14Z"), "myState" : 1, "members" : [ { "_id" : 1, "name" : "10.0.1.1:27017", "health" : 1, "state" : 1, "stateStr" : "PRIMARY", "uptime" : 1704, "optime" : Timestamp(1359045123000, 1), "optimeDate" : ISODate("2013-01-24T16:32:03Z"), "self" : true }, { "_id" : 2, "name" : "10.0.3.3:27017", "health" : 1, "state" : 2, "stateStr" : "SECONDARY", "uptime" : 14, "optime" : Timestamp(1359045123000, 1), "optimeDate" : ISODate("2013-01-24T16:32:03Z"), "lastHeartbeat" : ISODate("2013-01-24T16:32:14Z"), "pingMs" : 1511 }, { "_id" : 3, "name" : "10.0.2.2:27017", "health" : 1, "state" : 2, "stateStr" : "SECONDARY", "uptime" : 1698, "optime" : Timestamp(1359045123000, 1), "optimeDate" : ISODate("2013-01-24T16:32:03Z"), "lastHeartbeat" : ISODate("2013-01-24T16:32:14Z"), "pingMs" : 1 } ], "ok" : 1 } -- ReplicaSet status when I firewall off SECONDARY 10.0.3.3 test:PRIMARY> rs.status() { "set" : "test", "date" : ISODate("2013-01-24T16:27:30Z"), "myState" : 1, "members" : [ { "_id" : 1, "name" : "10.0.1.1:27017", "health" : 1, "state" : 1, "stateStr" : "PRIMARY", "uptime" : 1420, "optime" : Timestamp(1359044238000, 1), "optimeDate" : ISODate("2013-01-24T16:17:18Z"), "self" : true }, { "_id" : 2, "name" : "10.0.3.3:27017", "health" : 0, "state" : 8, "stateStr" : "(not reachable/healthy)", "uptime" : 0, "optime" : Timestamp(1359042361000, 1), "optimeDate" : ISODate("2013-01-24T15:46:01Z"), "lastHeartbeat" : ISODate("2013-01-24T16:15:47Z"), "pingMs" : 0, "errmsg" : "socket exception [CONNECT_ERROR] for 10.0.3.3:27017" }, { "_id" : 3, "name" : "10.0.2.2:27017", "health" : 1, "state" : 2, "stateStr" : "SECONDARY", "uptime" : 1414, "optime" : Timestamp(1359044238000, 1), "optimeDate" : ISODate("2013-01-24T16:17:18Z"), "lastHeartbeat" : ISODate("2013-01-24T16:27:30Z"), "pingMs" : 1 } ], "ok" : 1 } -- log snippet of activity between identical queries BEFORE manual failure of SECONDARY Thu Jan 24 08:12:42 [conn50] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:29 reslen:163 0ms Thu Jan 24 08:12:42 [initandlisten] connection accepted from 10.0.0.123:60710 #51 (13 connections now open) Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { getnonce: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { getnonce: 1 } ntoreturn:1 keyUpdates:0 reslen:65 0ms Thu Jan 24 08:12:42 [conn51] run command mydb.$cmd { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:12:42 [conn51] authenticate db: mydb { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:12:42 [conn51] command mydb.$cmd command: { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } ntoreturn:1 keyUpdates:0 locks(micros) r:48 reslen:91 0ms Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { ping: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { ping: 1 } ntoreturn:1 keyUpdates:0 reslen:37 0ms Thu Jan 24 08:12:42 [conn51] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:12:42 [conn51] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:12:42 [conn51] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:19 reslen:163 0ms -- log snippet of activity between identical queries AFTER manual failure of SECONDARY Thu Jan 24 08:17:12 [conn66] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:32 reslen:163 0ms Thu Jan 24 08:17:12 [initandlisten] connection accepted from 10.0.0.123:60719 #68 (13 connections now open) Thu Jan 24 08:17:12 [conn68] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:17:12 [conn68] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:17:12 [conn68] run command admin.$cmd { getnonce: 1 } Thu Jan 24 08:17:12 [conn68] command admin.$cmd command: { getnonce: 1 } ntoreturn:1 keyUpdates:0 reslen:65 0ms Thu Jan 24 08:17:12 [conn68] run command mydb.$cmd { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:17:12 [conn68] authenticate db: mydb { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } Thu Jan 24 08:17:12 [conn68] command mydb.$cmd command: { authenticate: 1, user: "polreadwrite", nonce: "redactedredacted", key: "redactedredactedredactedredacted" } ntoreturn:1 keyUpdates:0 locks(micros) r:87 reslen:91 0ms Thu Jan 24 08:17:12 [conn68] run command admin.$cmd { ping: 1 } Thu Jan 24 08:17:12 [conn68] command admin.$cmd command: { ping: 1 } ntoreturn:1 keyUpdates:0 reslen:37 0ms Thu Jan 24 08:17:13 BackgroundJob starting: ConnectBG Thu Jan 24 08:17:13 [conn68] run command admin.$cmd { isMaster: 1 } Thu Jan 24 08:17:13 [conn68] command admin.$cmd command: { isMaster: 1 } ntoreturn:1 keyUpdates:0 reslen:259 0ms Thu Jan 24 08:17:14 [conn67] run command admin.$cmd { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } Thu Jan 24 08:17:14 [conn67] command admin.$cmd command: { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } ntoreturn:1 keyUpdates:0 reslen:120 0ms Thu Jan 24 08:17:14 [conn5] getmore local.oplog.rs query: { ts: { $gte: new Date(5837042494373625857) } } cursorid:220712315271329417 ntoreturn:0 keyUpdates:0 locks(micros) r:114 nreturned:0 reslen:20 5010ms Thu Jan 24 08:17:16 [conn67] run command admin.$cmd { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } Thu Jan 24 08:17:16 [conn67] command admin.$cmd command: { replSetHeartbeat: "test", v: 10, pv: 1, checkEmpty: false, from: "10.0.2.2:27017", $auth: { local: { __system: 2 } } } ntoreturn:1 keyUpdates:0 reslen:120 0ms Thu Jan 24 08:17:16 [conn68] query mydb.mycollection query: { _id: ObjectId('41cdd148acf9092e1b000ca7') } ntoreturn:1 idhack:1 keyUpdates:0 locks(micros) r:33 reslen:163 0ms - Elapse time for PHP test BEFORE manual failure of SECONDARY - Note: ReadPreference = MongoClient::RP_PRIMARY, WriteConcern = 1 0.0052609444s - Elapse time for PHP test AFTER manual failure of SECONDARY - Note: ReadPreference = MongoClient::RP_PRIMARY, WriteConcern = 1 4.0203089714s更新…
我附上了一些來自 mongo-php 驅動程序的詳細日誌（下面，經過修剪和編輯以適應所有內容）。看起來驅動程序嘗試多次驗證所有副本集伺服器。如果伺服器不可用，它將達到 1000 毫秒超時。似乎這些是響應時間大幅增加的可能罪魁禍首。我是在查看驅動程序中的錯誤還是“按設計工作”？如果是設計使然，那麼replicaSets 和php 似乎不是一個很好的組合？我的網站在每次查詢都大幅增加時崩潰了。我是否應該避免告訴 php 所有副本集伺服器，而只為 MongoClient 建構子提供 PRIMARY？這似乎也不會飛。
8:14 Notice: CON INFO: mongo_get_read_write_connection: finding a REPLSET connection (read) in ... 8:14 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/r/redacted-id;23623 (looking for 10.0.1.1:27017;test;main/r/redacted-id;23623) in ... 8:14 Notice: CON FINE: is_ping: skipping: last ran at 1359076091, now: 1359076094, time left: 2 in ... 8:14 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/r/redacted-id;23623 (looking for 10.0.2.2:27017;test;main/r/redacted-id;23623) in ... 8:14 Notice: CON FINE: is_ping: skipping: last ran at 1359076091, now: 1359076094, time left: 2 in ... 8:14 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:15 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:15 Notice: CON WARN: Couldn't connect to '10.0.3.3:27017': Timed out after 1000 ms in ... 8:15 Notice: CON FINE: discover_topology: checking ismaster for 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/r/redacted-id;23623 (looking for 10.0.1.1:27017;test;main/r/redacted-id;23623) in ... 8:15 Notice: CON FINE: ismaster: skipping: last ran at 1359076092, now: 1359076095, time left: 12 in ... 8:15 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:15 Notice: CON FINE: discover_topology: checking ismaster for 10.0.2.2:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/r/redacted-id;23623 (looking for 10.0.2.2:27017;test;main/r/redacted-id;23623) in ... 8:15 Notice: CON FINE: ismaster: skipping: last ran at 1359076093, now: 1359076095, time left: 13 in ... 8:15 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:15 Notice: CON FINE: discover_topology: checking ismaster for 10.0.3.3:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: CON WARN: discover_topology: couldn't create a connection for 10.0.3.3:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: finding candidate servers in ... 8:15 Notice: REPLSET FINE: - all servers in ... 8:15 Notice: REPLSET FINE: filter_connections: adding connections: in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: filter_connections: done in ... 8:15 Notice: REPLSET FINE: limiting to servers with same replicaset name in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: limiting to servers with same replicaset name: done in ... 8:15 Notice: REPLSET FINE: limiting by credentials in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: limiting by credentials: done in ... 8:15 Notice: REPLSET FINE: sorting servers by priority and ping time in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: sorting servers: done in ... 8:15 Notice: REPLSET FINE: selecting near servers in ... 8:15 Notice: REPLSET FINE: selecting near servers: nearest is 0ms in ... 8:15 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: REPLSET FINE: selecting near server: done in ... 8:15 Notice: REPLSET INFO: pick server: random element 0 in ... 8:15 Notice: REPLSET INFO: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:15 Notice: IO FINE: getting reply in ... 8:15 Notice: IO FINE: getting cursor header in ... 8:15 Notice: IO FINE: getting cursor body in ... 8:15 Notice: PARSE INFO: Parsing mongodb://rw:thisisntreallytheacctpassword@10.0.1.1,10.0.3.3/main in ... 8:15 Notice: PARSE INFO: - Found user 'rw' and a password in ... 8:15 Notice: PARSE INFO: - Found node: 10.0.1.1:27017 in ... 8:15 Notice: PARSE INFO: - Found node: 10.0.3.3:27017 in ... 8:15 Notice: PARSE INFO: - Connection type: MULTIPLE in ... 8:15 Notice: PARSE INFO: - Found database name 'main' in ... 8:15 Notice: PARSE INFO: - Found option 'readPreference': 'primary' in ... 8:15 Notice: PARSE INFO: - Found option 'w': 1 in ... 8:15 Notice: PARSE INFO: - Found option 'replicaSet': 'test' in ... 8:15 Notice: PARSE INFO: - Switching connection type: REPLSET in ... 8:15 Notice: CON INFO: mongo_get_read_write_connection: finding a REPLSET connection (read) in ... 8:15 Notice: CON INFO: connection_create: creating new connection for 10.0.1.1:27017 in ... 8:15 Notice: CON INFO: get_server_flags: start in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 239 in ... 8:15 Notice: CON FINE: get_server_flags: setting maxBsonObjectSize to 16777216 in ... 8:15 Notice: CON INFO: get_connection_single: authenticating 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:15 Notice: CON INFO: getnonce: start in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 45 in ... 8:15 Notice: CON FINE: getnonce: found nonce 'd4017c7d0ebc1a9c' in ... 8:15 Notice: CON INFO: authenticate: start in ... 8:15 Notice: CON FINE: authenticate: hash=md5(rw:mongo:thisisntreallytheacctpassword) = 65917a6cb23196fc6ba826e6fdf4b5e7 in ... 8:15 Notice: CON FINE: authenticate: key=md5(d4017c7d0ebc1a9crw65917a6cb23196fc6ba826e6fdf4b5e7) = 775bf2c6a18a3375086b66a430daf89b in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 71 in ... 8:15 Notice: CON INFO: authentication successful in ... 8:15 Notice: CON INFO: is_ping: pinging 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:15 Notice: CON FINE: send_packet: read from header: 36 in ... 8:15 Notice: CON FINE: send_packet: data_size: 17 in ... 8:15 Notice: CON INFO: is_ping: last pinged at 1359076095; time: 0ms in ... 8:15 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:16 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:16 Notice: CON WARN: Couldn't connect to '10.0.3.3:27017': Timed out after 1000 ms in ... 8:16 Notice: CON FINE: discover_topology: checking ismaster for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:16 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:16 Notice: CON INFO: ismaster: start in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 239 in ... 8:16 Notice: CON FINE: ismaster: the server name matches what we thought it'd be (10.0.1.1:27017). in ... 8:16 Notice: CON FINE: ismaster: the found replicaset name matches the expected one (test). in ... 8:16 Notice: CON INFO: ismaster: set name: test, ismaster: 1, secondary: 0, is_arbiter: 0 in ... 8:16 Notice: CON INFO: found host: 10.0.1.1:27017 in ... 8:16 Notice: CON INFO: found host: 10.0.2.2:27017 in ... 8:16 Notice: CON INFO: found host: 10.0.3.3:27017 in ... 8:16 Notice: CON INFO: ismaster: last ran at 1359076096 in ... 8:16 Notice: CON FINE: discover_topology: ismaster worked in ... 8:16 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:16 Notice: CON INFO: discover_topology: found new host: 10.0.2.2:27017 in ... 8:16 Notice: CON INFO: connection_create: creating new connection for 10.0.2.2:27017 in ... 8:16 Notice: CON INFO: get_server_flags: start in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 239 in ... 8:16 Notice: CON FINE: get_server_flags: setting maxBsonObjectSize to 16777216 in ... 8:16 Notice: CON INFO: get_connection_single: authenticating 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:16 Notice: CON INFO: getnonce: start in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 45 in ... 8:16 Notice: CON FINE: getnonce: found nonce '19d9c5199e884edb' in ... 8:16 Notice: CON INFO: authenticate: start in ... 8:16 Notice: CON FINE: authenticate: hash=md5(rw:mongo:thisisntreallytheacctpassword) = 65917a6cb23196fc6ba826e6fdf4b5e7 in ... 8:16 Notice: CON FINE: authenticate: key=md5(19d9c5199e884edbrw65917a6cb23196fc6ba826e6fdf4b5e7) = 7fffb7f867a0e981952a45191fcab3f2 in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 71 in ... 8:16 Notice: CON INFO: authentication successful in ... 8:16 Notice: CON INFO: is_ping: pinging 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:16 Notice: CON FINE: send_packet: read from header: 36 in ... 8:16 Notice: CON FINE: send_packet: data_size: 17 in ... 8:16 Notice: CON INFO: is_ping: last pinged at 1359076096; time: 1ms in ... 8:16 Notice: CON INFO: discover_topology: found new host: 10.0.3.3:27017 in ... 8:16 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:17 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:17 Notice: CON WARN: discover_topology: could not connect to new host: 10.0.3.3:27017: Timed out after 1000 ms in ... 8:17 Notice: CON FINE: discover_topology: checking ismaster for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:17 Notice: CON WARN: discover_topology: couldn't create a connection for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:17 Notice: CON FINE: discover_topology: checking ismaster for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:17 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:17 Notice: CON INFO: ismaster: start in ... 8:17 Notice: CON FINE: send_packet: read from header: 36 in ... 8:17 Notice: CON FINE: send_packet: data_size: 239 in ... 8:17 Notice: CON FINE: ismaster: the server name matches what we thought it'd be (10.0.2.2:27017). in ... 8:17 Notice: CON FINE: ismaster: the found replicaset name matches the expected one (test). in ... 8:17 Notice: CON INFO: ismaster: set name: test, ismaster: 0, secondary: 1, is_arbiter: 0 in ... 8:17 Notice: CON INFO: found host: 10.0.2.2:27017 in ... 8:17 Notice: CON INFO: found host: 10.0.3.3:27017 in ... 8:17 Notice: CON INFO: found host: 10.0.1.1:27017 in ... 8:17 Notice: CON INFO: ismaster: last ran at 1359076097 in ... 8:17 Notice: CON FINE: discover_topology: ismaster worked in ... 8:17 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:17 Notice: CON INFO: discover_topology: found new host: 10.0.3.3:27017 in ... 8:17 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:18 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:18 Notice: CON WARN: discover_topology: could not connect to new host: 10.0.3.3:27017: Timed out after 1000 ms in ... 8:18 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:18 Notice: REPLSET FINE: finding candidate servers in ... 8:18 Notice: REPLSET FINE: - all servers in ... 8:18 Notice: REPLSET FINE: filter_connections: adding connections: in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: filter_connections: done in ... 8:18 Notice: REPLSET FINE: limiting to servers with same replicaset name in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: limiting to servers with same replicaset name: done in ... 8:18 Notice: REPLSET FINE: limiting by credentials in ... 8:18 Notice: REPLSET FINE: - skipping '10.0.1.1:27017;test;main/r/redacted-id;23623', username didn't match ('r' vs 'rw') in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: limiting by credentials: done in ... 8:18 Notice: REPLSET FINE: sorting servers by priority and ping time in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: sorting servers: done in ... 8:18 Notice: REPLSET FINE: selecting near servers in ... 8:18 Notice: REPLSET FINE: selecting near servers: nearest is 0ms in ... 8:18 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: REPLSET FINE: selecting near server: done in ... 8:18 Notice: REPLSET INFO: pick server: random element 0 in ... 8:18 Notice: REPLSET INFO: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:18 Notice: CON INFO: mongo_get_read_write_connection: finding a REPLSET connection (read) in ... 8:18 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:18 Notice: CON FINE: is_ping: skipping: last ran at 1359076095, now: 1359076098, time left: 2 in ... 8:18 Notice: CON INFO: connection_create: creating new connection for 10.0.3.3:27017 in ... 8:19 Notice: CON WARN: connection_create: error while creating connection for 10.0.3.3:27017: Timed out after 1000 ms in ... 8:19 Notice: CON WARN: Couldn't connect to '10.0.3.3:27017': Timed out after 1000 ms in ... 8:19 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:19 Notice: CON FINE: is_ping: skipping: last ran at 1359076096, now: 1359076099, time left: 2 in ... 8:19 Notice: CON FINE: discover_topology: checking ismaster for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON FINE: found connection 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.1.1:27017;test;main/rw/redacted-id-2;23623) in ... 8:19 Notice: CON FINE: ismaster: skipping: last ran at 1359076096, now: 1359076099, time left: 12 in ... 8:19 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:19 Notice: CON FINE: discover_topology: checking ismaster for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON WARN: discover_topology: couldn't create a connection for 10.0.3.3:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON FINE: discover_topology: checking ismaster for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: CON FINE: found connection 10.0.2.2:27017;test;main/rw/redacted-id-2;23623 (looking for 10.0.2.2:27017;test;main/rw/redacted-id-2;23623) in ... 8:19 Notice: CON FINE: ismaster: skipping: last ran at 1359076097, now: 1359076099, time left: 13 in ... 8:19 Notice: CON FINE: discover_topology: ismaster got skipped in ... 8:19 Notice: REPLSET FINE: finding candidate servers in ... 8:19 Notice: REPLSET FINE: - all servers in ... 8:19 Notice: REPLSET FINE: filter_connections: adding connections: in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: filter_connections: done in ... 8:19 Notice: REPLSET FINE: limiting to servers with same replicaset name in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 32, ping: 0, hash: 10.0.1.1:27017;test;main/r/redacted-id;23623 in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: limiting to servers with same replicaset name: done in ... 8:19 Notice: REPLSET FINE: limiting by credentials in ... 8:19 Notice: REPLSET FINE: - skipping '10.0.1.1:27017;test;main/r/redacted-id;23623', username didn't match ('r' vs 'rw') in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: limiting by credentials: done in ... 8:19 Notice: REPLSET FINE: sorting servers by priority and ping time in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: sorting servers: done in ... 8:19 Notice: REPLSET FINE: selecting near servers in ... 8:19 Notice: REPLSET FINE: selecting near servers: nearest is 0ms in ... 8:19 Notice: REPLSET FINE: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: REPLSET FINE: selecting near server: done in ... 8:19 Notice: REPLSET INFO: pick server: random element 0 in ... 8:19 Notice: REPLSET INFO: - connection: type: PRIMARY, socket: 35, ping: 0, hash: 10.0.1.1:27017;test;main/rw/redacted-id-2;23623 in ... 8:19 Notice: IO FINE: getting reply in ... 8:19 Notice: IO FINE: getting cursor header in ... 8:19 Notice: IO FINE: getting cursor body in ...
這是因為連接超時。正在跟踪問題here
https://jira.mongodb.org/browse/PHP-355
https://jira.mongodb.org/browse/PHP-613
https://jira.mongodb.org/browse/PHP-366
PHP Mongo Driver 1.4.0 修復了這個問題。
查看更改日誌：http ://pecl.php.net/package-info.php?package=mongo&version=1.4.0