我正在测试生产 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 毫秒。似乎这些是响应时间大幅增加的罪魁祸首。我看到的是驱动程序中的错误还是“按设计运行”？如果是设计使然，那么似乎副本集和 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:[email protected],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 ...
答案1
答案2
PHP Mongo Driver 1.4.0 修复了此问题。
查看变更日志：http://pecl.php.net/package-info.php?package=mongo&version=1.4.0