How to troubleshoot slow performance on URL with Rails + Mongo -
we use advice on scaling/ops issue.
we have simple mobile app runs on rails 3.2.12 , uses mongomapper instead of activerecord. there 1 database call sporadically performs poorly, causing users write in , complain. isn't clear why. can't install newrelic because of mongomapper, , data returned mongo isn't lot (< 200kb). there isn't logic being executed in controller, either.
the problem seems exacerbated more users. server runs on vps, 1 shared 30 nodes. hosting company says average i/o utilization @ 12%, below critical threshold.
since can't use newrelic, what's best approach troubleshooting problem?
here's output explain:
user.collection.find({:username_downcase => 'banana2006'}).explain => {"cursor"=>"btreecursor username_downcase", "ismultikey"=>false, "n"=>1, "nscannedobjects"=>1, "nscanned"=>1, "nscannedobjectsallplans"=>1, "nscannedallplans"=>1, "scanandorder"=>false, "indexonly"=>false, "nyields"=>0, "nchunkskips"=>0, "millis"=>3, "indexbounds"=>{"username_downcase"=>[["banana2006", "banana2006"]]}, "allplans"=>[{"cursor"=>"btreecursor username_downcase", "n"=>1, "nscannedobjects"=>1, "nscanned"=>1, "indexbounds"=>{"username_downcase"=>[["banana2006", "banana2006"]]}}], "oldplan"=>{"cursor"=>"btreecursor username_downcase", "indexbounds"=>{"username_downcase"=>[["banana2006", "banana2006"]]}}, "server"=>"x.com"} output db.serverstatus:
> db.serverstatus() { "host" : "mongo.x.com", "version" : "2.2.0", "process" : "mongod", "pid" : 15957, "uptime" : 5232267, "uptimemillis" : numberlong("5232267460"), "uptimeestimate" : 5178261, "localtime" : isodate("2013-05-19t19:32:14.561z"), "locks" : { "." : { "timelockedmicros" : { "r" : numberlong(131563265), "w" : numberlong("2824934127") }, "timeacquiringmicros" : { "r" : numberlong(536751143), "w" : numberlong(644540368) } }, "admin" : { "timelockedmicros" : { "r" : numberlong(11906), "w" : numberlong(0) }, "timeacquiringmicros" : { "r" : numberlong(424), "w" : numberlong(0) } }, "local" : { "timelockedmicros" : { "r" : numberlong(13829064), "w" : numberlong(0) }, "timeacquiringmicros" : { "r" : numberlong(96863334), "w" : numberlong(0) } }, "x-development" : { "timelockedmicros" : { "r" : numberlong(22074626), "w" : numberlong(645528) }, "timeacquiringmicros" : { "r" : numberlong(2876041), "w" : numberlong(3693) } }, "x-production" : { "timelockedmicros" : { "r" : numberlong("39251850394"), "w" : numberlong(1466862624) }, "timeacquiringmicros" : { "r" : numberlong("17410130690"), "w" : numberlong(858232658) } }, "z-development" : { "timelockedmicros" : { "r" : numberlong(1897461), "w" : numberlong(0) }, "timeacquiringmicros" : { "r" : numberlong(134836), "w" : numberlong(0) } } }, "globallock" : { "totaltime" : numberlong("5232267461000"), "locktime" : numberlong("2824934127"), "currentqueue" : { "total" : 0, "readers" : 0, "writers" : 0 }, "activeclients" : { "total" : 0, "readers" : 0, "writers" : 0 } }, "mem" : { "bits" : 64, "resident" : 87, "virtual" : 9071, "supported" : true, "mapped" : 4207, "mappedwithjournal" : 8414 }, "connections" : { "current" : 3, "available" : 9597 }, "extra_info" : { "note" : "fields vary platform", "heap_usage_bytes" : 198457056, "page_faults" : 3176777 }, "indexcounters" : { "btree" : { "accesses" : 18208995, "hits" : 18208994, "misses" : 0, "resets" : 0, "missratio" : 0 } }, "backgroundflushing" : { "flushes" : 87204, "total_ms" : 563603, "average_ms" : 6.463040686207055, "last_ms" : 1, "last_finished" : isodate("2013-05-19t19:31:55.201z") }, "cursors" : { "totalopen" : 0, "clientcursors_size" : 0, "timedout" : 0 }, "network" : { "bytesin" : 9286320357, "bytesout" : 148669944094, "numrequests" : 5102457 }, "opcounters" : { "insert" : 0, "query" : 3213569, "update" : 1989197, "delete" : 0, "getmore" : 30944, "command" : 216139 }, "asserts" : { "regular" : 0, "warning" : 0, "msg" : 0, "user" : 0, "rollovers" : 0 }, "writebacksqueued" : false, "dur" : { "commits" : 30, "journaledmb" : 0.04096, "writetodatafilesmb" : 0.043131, "compression" : 0.9447148096039855, "commitsinwritelock" : 0, "earlycommits" : 0, "timems" : { "dt" : 3069, "preplogbuffer" : 0, "writetojournal" : 0, "writetodatafiles" : 0, "remapprivateview" : 0 } }, "recordstats" : { "accessesnotinmemory" : 1102532, "pagefaultexceptionsthrown" : 657056, "admin" : { "accessesnotinmemory" : 0, "pagefaultexceptionsthrown" : 0 }, "local" : { "accessesnotinmemory" : 0, "pagefaultexceptionsthrown" : 0 }, "x-development" : { "accessesnotinmemory" : 1555, "pagefaultexceptionsthrown" : 1304 }, "x-production" : { "accessesnotinmemory" : 1074115, "pagefaultexceptionsthrown" : 639842 }, "z-development" : { "accessesnotinmemory" : 0, "pagefaultexceptionsthrown" : 0 } }, "ok" : 1 }
you can set mongodb profiling although default 100ms should enough.
still, can't tell how optimize mongo queries if don't know are. "one database call sporadically performs poorly"?
in comments reference long query using snapshot option. can cause lock contention, if can remove snapshot option safely see improvement.
i don't know why can't use new relic. might not give automatic timing of database queries since know 1 problem can use method tracers isolate problem , make sure database rather other part of code.
Comments
Post a Comment