Я тестирую отработку отказа набора реплик MongoDB. Когда я вручную выхожу из строя один из экземпляров, я вижу прибл. Время ответа на мои PHP-запросы уменьшилось в 1000 раз (тысяча раз).
Я использую последнюю версию MongoDB (2.2.2) и последнюю версию драйвера php (1.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 (ниже, несколько сокращено и отредактировано, чтобы вместить все). Похоже, драйвер несколько раз пытается проверить все серверы ReplicaSet. Если сервер недоступен, время ожидания составляет 1000 мс. Похоже, это вероятные виновники значительного увеличения времени отклика. Я смотрю на ошибку в драйвере или "работает как задумано"? Если это по дизайну, то кажется, что replicaSets и php не очень хорошее сочетание? Мой сайт падает при попадании такого огромного увеличения количества запросов. Должен ли я не сообщать php обо всех серверах с набором реплик и просто дать конструктору MongoClient ПЕРВИЧНЫЙ? Это тоже не похоже на то, чтобы летать.
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 ...
Это из-за тайм-аутов соединения. Проблемы отслеживаются здесь
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