Take the 2-minute tour ×
Server Fault is a question and answer site for professional system and network administrators. It's 100% free, no registration required.

I'm testing a production MongoDB replica set failover. When I manually fail one of the instances I see an approx. 1000x (one thousand x) decrease in response times of my PHP queries.

I'm on the latest MongoDB (2.2.2) and the latest php driver (1.3.3). I've got a 3 server replica set and a php test that makes two identical calls back to back.

Has anyone else seen this? Can someone suggest a change in my configuration to fix it? It's a stop-ship issue for me.

Details below... Note: I'm not failing the PRIMARY I'm failing a SECONDARY but anecdotal testing indicates it doesn't make any difference.

Many thanks for whatever insight you can provide.


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

I've attached some verbose logs from the mongo-php driver (below, pruned and redacted somewhat to fit it all in). Looks like the driver tries to verify all replicaSet servers multiple times. If a server is unavailable it hits a 1000ms timeout. Seems like these are the likely culprits in the large response time increase. Am I looking at a bug in the driver or "works as designed"? If it is by design then it seems like replicaSets and php are not a good mix? My site falls down when hit by such as huge increase to every query. Should I avoid telling php about all the replica set servers and just give the MongoClient constructor the PRIMARY? That doesn't seem like it will fly either.


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 ...
share|improve this question
    
what version of the php-mongo driver do you have? –  Mike Jan 24 '13 at 20:38
    
Hi Mike... mentioned it above, v1.3.3. –  John Jan 24 '13 at 20:59
    
what big is the database? –  Mike Jan 24 '13 at 21:48
    
Very small at this point, approx. 1 GB –  John Jan 24 '13 at 21:49
    
There are no slow queries being logged in the database in the second log output besides a getmore on the oplog (which is replication). That would suggest that the delay is on the PHP side rather than the DB, but you would need to add some debug to figure out where. Couple of quick checks - what happens if you just shut down the secondary rather than firewalling off and/or what if you actively reject (RST) rather than DROP - does the behavior change? I'm wondering if the detection of the new layout taking a long time might be an issue - failing more quickly would be a way to find out –  Adam C Jan 25 '13 at 0:57

2 Answers 2

up vote 1 down vote accepted

This is because of connection timeouts. The issues are being tracked here

https://jira.mongodb.org/browse/PHP-355

https://jira.mongodb.org/browse/PHP-613

https://jira.mongodb.org/browse/PHP-366

https://jira.mongodb.org/browse/PHP-348

https://jira.mongodb.org/browse/PHP-356

share|improve this answer
1  
Yep. The timeout flag being ignored was the root of my issue. Until the driver team comes out with a fix I've implemented my own failover detection by bypassing the drivers replicaSet settings and making direct connection attempts to the individual servers. That and some judicious use of memcache allows automatic failover with no ongoing delays beyond the failover transition period. Thanks for the jira list, Gregor. I should have found these myself. –  John Jan 27 '13 at 18:09
    
PHP driver 1.3.4 has been released. Can you check if it fixes this for you? –  gregor Jan 31 '13 at 16:03

PHP Mongo Driver 1.4.0 fixed this issue.

See change log: http://pecl.php.net/package-info.php?package=mongo&version=1.4.0

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.