Why does the same Moped query sometimes take longer?

Question

When a ruby on rails web page is requested, sometimes the database query takes 2-4x as long. I've enabled debug logging for Moped and saw lines like this:

D, [2013-11-21T23:11:10.889418 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY        database=db collection=col selector={"emailCount"=>{"$gt"=>9}} flags=[:slave_ok] limit=0 skip=0 batch_size=nil fields=nil (42.4671ms)
D, [2013-11-21T23:11:13.403011 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY        database=db collection=col selector={"emailCount"=>{"$gt"=>9}} flags=[:slave_ok] limit=0 skip=0 batch_size=nil fields=nil (127.4977ms)

Redacting the query and flags, here's the difference in timing:

D, [2013-11-21T22:28:16.268263 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (163.0192ms)
D, [2013-11-21T22:28:17.872661 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (89.7279ms)
D, [2013-11-21T22:30:26.645921 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY [...redacted...] (38.0206ms)
D, [2013-11-21T22:37:47.464478 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY [...redacted...] (42.1586ms)
D, [2013-11-21T22:39:53.393541 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (154.6400ms)
D, [2013-11-21T22:41:16.217997 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY [...redacted...] (38.3251ms)
D, [2013-11-21T22:41:29.540417 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (124.6662ms)
D, [2013-11-21T22:41:36.281601 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY [...redacted...] (37.7121ms)
D, [2013-11-21T23:11:07.696951 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY [...redacted...] (41.8334ms)
D, [2013-11-21T23:11:10.889418 #7690] DEBUG -- :   MOPED: 127.0.0.1:17203 QUERY [...redacted...] (42.4671ms)
D, [2013-11-21T23:11:13.403011 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (127.4977ms)
D, [2013-11-21T23:11:16.796217 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (166.5795ms)
D, [2013-11-21T23:11:22.210991 #7690] DEBUG -- :   MOPED: 54.213.xxx.xx:17203 QUERY [...redacted...] (195.2744ms)

I'm wondering why Moped sometimes uses IP 127.0.0.1 and other times 54.213.xxx.xx? And why when querying 54.213.xxx.xx it takes 2-4x as long? To generate these log entries I'm just refreshing a web page.

Ideally I'd like all the queries to take ~40ms instead of occasionally taking ~160ms.

Here's my mongoid.yml if it's relevant:

development:
  sessions:
    default:
  database: db
  hosts:
    - localhost:17203
    - xxx.no-ip.biz:27017
  options:
    consistency: :eventual
  username: user
  password: pass

There are two mongos in a replica set. The one on localhost:17203 (or 54.213.xxx.xx) is a secondary member. xxx.no-ip-.biz resolves to 174.21.xxx.xxx so I know that my primary member is not being used for reads (as I'd expect).

Can you share your `mongoid.yml`? – davogones Nov 22 '13 at 06:03 — davogones, Nov 22 '13 at 06:03
I've edited the question to include my mongoid.yml. Thanks! – Stephen Nov 22 '13 at 18:33 — Stephen, Nov 22 '13 at 18:33

score 0 · Answer 1 · answered Nov 22 '13 at 21:30

When Moped connects to your mongoDB server, it resolves the hostname of the server to an IP address. Your web app server is probably handling each request in a different worker process, and each process resolved the hostname differently.

I'm not an expert in networking, but it's likely your DNS settings are messed up somehow. Sometimes localhost resolves to the external IP address of the box instead of the expected 127.0.0.1 loopback address. So instead of communicating within the local network, your request has to go out to your ISP's DNS server, get resolved there, and come right back to the same box.

Why does the same Moped query sometimes take longer?

1 Answers1