【发布时间】：2013-05-03 05:46:14
【问题描述】：
我们可以就扩展/操作问题使用建议。
我们有一个在 Rails 3.2.12 上运行的简单移动应用程序，它使用 MongoMapper 而不是 ActiveRecord。有一个数据库调用偶尔表现不佳，导致用户写信抱怨。目前尚不清楚为什么。由于MongoMapper，我们无法安装NewRelic，Mongo返回的数据并不多（
随着用户数量的增加，问题似乎更加严重。服务器在 VPS 上运行，其中一个与 30 个节点共享。托管公司表示，平均 I/O 利用率为 12%，远低于临界阈值。
既然我们不能使用 NewRelic，那么解决问题的最佳方法是什么？
这是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"}
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 by 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
}
【问题讨论】：
-
你有没有在查询上使用
explain来查看查询在执行时是如何执行的？例如，它是否进行了大量扫描而不是使用索引？ -
用解释的输出更新了问题。谢谢，@WiredPrairie。
-
该查询耗时 3 毫秒。您能否访问 mongod 日志并查看那里记录了哪些查询 - 将记录所有耗时超过 100 毫秒的查询。
-
谢谢，@AsyaKamsky。最好的方法是什么？我应该将整个日志文件转储到某个地方吗？有没有只检索最慢查询的命令？
-
我说的是 mongod 进程写入的日志文件。它是磁盘上的文件。所以我会使用 grep 来查找慢查询 - 可能从 grep '[0-9][0-9][0-9]ms$' logfilepathandname 开始。
标签： ruby-on-rails ruby-on-rails-3 mongodb scalability mongomapper