O failover replicaSet do MongoDB aumenta o tempo de resposta da consulta em 1.000x

2

Estou testando um failover do conjunto de réplicas do MongoDB de produção. Quando falho manualmente em uma das instâncias, vejo um aprox. Diminuição de 1000x (mil x) em tempos de resposta de minhas consultas PHP.

Estou no mais recente MongoDB (2.2.2) e no driver mais recente do php (1.3.3). Eu tenho um conjunto de réplica de 3 servidores e um teste de php que faz duas chamadas idênticas de volta para trás.

Alguém mais viu isso? Alguém pode sugerir uma alteração na minha configuração para corrigi-lo? É um problema de parada para mim.

Detalhes abaixo ... Nota: Eu não estou falhando o PRIMÁRIO Estou com um teste SECUNDÁRIO mas anedótico indica que não faz nenhuma diferença.

Muito obrigado por qualquer informação que você possa fornecer.

-- 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

UPDATE ...

Eu anexei alguns logs detalhados do driver mongo-php (abaixo, podado e redigido um pouco para encaixar tudo). Parece que o driver tenta verificar todos os servidores replicaSet várias vezes. Se um servidor não estiver disponível, ele atingirá um tempo limite de 1000 ms. Parece que esses são os prováveis culpados pelo grande aumento no tempo de resposta. Eu estou olhando para um bug no driver ou "funciona como projetado"? Se é por design, então parece que replicaSets e php não são uma boa mistura? Meu site cai quando atingido por um aumento tão grande para cada consulta. Devo evitar dizer ao php sobre todos os servidores de conjuntos de réplicas e apenas dar ao construtor MongoClient o PRIMARY? Isso não parece que vai voar também.

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 ...
    
por John 24.01.2013 / 18:40

2 respostas

2

Isso ocorre devido a tempos limite de conexão. Os problemas estão sendo rastreados aqui

link

link

link

link

link

    
por 25.01.2013 / 15:32
0

O PHP Mongo Driver 1.4.0 corrigiu esse problema.

Veja o log de alterações: link

    
por 17.12.2013 / 18:49