mongodb并发性能太低,如何优化?

高压东 发布于 2015/01/28 20:38
阅读 20K+
收藏 1
最近要上线一个系统,但是这两天做压力测试,发现并发性能很差(200用户),经过检查,发现瓶颈出现在mongodb,慢得不科学,我不能接受
使用的是spring-mongo

spring的配置文件如下
 <mongo:mongo host="#{conf['mongo.host']}" port="27017" write-concern="MAJORITY">
                <mongo:options connections-per-host="100"
                   threads-allowed-to-block-for-connection-multiplier="50"
                   connect-timeout="3000"
                   max-wait-time="5000"
                   auto-connect-retry="true"
                   socket-keep-alive="true"
                   socket-timeout="5000"
                   slave-ok="true"
                   write-number="1"
                   write-timeout="0"
                   write-fsync="true"/>
 </mongo:mongo>

mongodb现在还是单机,没有副本,没做分片

使用mongostat统计的结果,这并发并不算大啊
insert  query update delete getmore command flushes mapped  vsize    res faults      locked db idx miss %     qr|qw   ar|aw  netIn netOut  conn       time
    18     66      5     *0       0   103|0       0  26.2g  52.8g  3.22g     21  osci:1.3%          0       0|0     0|0     1m    95k   110   18:45:26
    16     58      4     *0       0    89|0       0  26.2g  52.8g  3.22g      1  osci:2.6%          0       0|0     3|0    24k    34k   110   18:45:27
    54     45      1     *0       0   134|0       0  26.2g  52.8g  3.21g    105  osci:3.7%          0       0|0     0|0     7m   158k   110   18:45:28
    25     59      2     *0       1   122|0       0  26.2g  52.8g  3.23g     42  osci:1.3%          0       0|0     0|0     2m   187k   110   18:45:29
    24     53      1     *0       1   111|0       0  26.2g  52.8g  3.24g     42  osci:4.1%          0       0|0     2|0     2m   142k   110   18:45:30
     8     59      2     *0       0   123|0       0  26.2g  52.8g  3.23g      0  osci:1.8%          0       0|0     1|0    27k    67k   110   18:45:31
    23     60      3     *0       0    97|0       0  26.2g  52.8g  3.23g     21  osci:1.8%          0       0|0     1|0     1m    79k   110   18:45:32
    16     54      3     *0       0    64|0       0  26.2g  52.8g  3.23g      0  osci:2.7%          0       0|0     1|0    20k    42k   110   18:45:33
    40     72      5     *0       0   139|0       0  26.2g  52.8g  3.23g     46  osci:4.5%          0       3|0     1|2     2m   113k   110   18:45:35
    34     47      1     *0       0   132|0       0  26.2g  52.8g  3.25g     60 osci:44.5%          0      10|0     1|0     4m   106k   110   18:45:36
    34     46      1     *0       1   128|0       0  26.2g  52.8g  3.24g     63 osci:12.0%          0       0|0     0|0     4m   170k   110   18:45:37
     3     27      2     *0       0    39|0       0  26.2g  52.8g  3.24g      0  osci:0.0%          0       0|0     0|4    13k     9k   110   18:45:38
    *0     19      3     *0       0    13|0       0  26.2g  52.8g  3.24g      0  osci:0.1%          0       0|0     0|7     6k    19k   110   18:45:39
    *0     37     11     *0       0    66|0       0  26.2g  52.8g  3.21g      0  osci:2.4%          0       0|0     1|0    14k    53k   110   18:45:40
    31     81     *0     *0       1   273|0       0  26.2g  52.8g  3.23g     63  osci:1.4%          0       0|0     0|0     4m   160k   110   18:45:41
    34     57     *0     *0       0   161|0       0  26.2g  52.8g  3.23g     21  osci:1.3%          0       0|0     1|0     1m    96k   110   18:45:42
     7     44      4     *0       0    53|0       0  26.2g  52.8g  3.23g      0  osci:0.1%          0       0|0     0|0    16k    63k   110   18:45:43
     8     78      3     *0       0   114|0       0  26.2g  52.8g  3.22g      0  osci:0.9%          0       0|0     0|0    27k    43k   110   18:45:44
    24     52     *0     *0       0   109|0       0  26.2g  52.8g  3.22g      0  osci:1.5%          0       0|0     1|4    27k    34k   110   18:45:45
    60     41      1     *0       1   152|0       0  26.2g  52.8g  3.25g    126  osci:5.1%          0       0|0     1|0     8m   227k   110   18:45:46
 

然后打开profier统计比较慢的操作,超过100ms的都会统计,发现一些很普通的query耗时几秒,没法接受
接着给一些查询条件字段加上了索引,然后就没有超过100ms的查询了,但是insert,update跟一些聚合查询仍然花了好几秒
从system.profile中查询了一些比较耗时的操作
看看这个insert
{
    "op" : "insert",
    "ns" : "osci.historyInfo",
    "ninserted" : 1,
    "keyUpdates" : 0,
    "numYield" : 0,
    "lockStats" : {
        "timeLockedMicros" : {
            "r" : NumberLong(0),
            "w" : NumberLong(209)
        },
        "timeAcquiringMicros" : {
            "r" : NumberLong(0),
            "w" : NumberLong(535)
        }
    },
    "millis" : 5078,
    "execStats" : {},
    "ts" : ISODate("2015-01-28T10:44:06.856Z"),
    "client" : "192.168.1.41",
    "allUsers" : [],
    "user" : ""
}
费时5秒
这个update 也不慌多让
{
    "op" : "update",
    "ns" : "osci.chatMessage",
    "query" : {
        "_id" : ObjectId("54c8bd69e4b092e7d3eb30f2")
    },
    "updateobj" : {
        "$set" : {
            "isRead" : 1
        }
    },
    "nscanned" : 1,
    "nscannedObjects" : 1,
    "nMatched" : 1,
    "nModified" : 1,
    "fastmod" : true,
    "keyUpdates" : 0,
    "numYield" : 0,
    "lockStats" : {
        "timeLockedMicros" : {
            "r" : NumberLong(0),
            "w" : NumberLong(381)
        },
        "timeAcquiringMicros" : {
            "r" : NumberLong(0),
            "w" : NumberLong(620)
        }
    },
    "millis" : 5042,
    "execStats" : {},
    "ts" : ISODate("2015-01-28T10:44:06.856Z"),
    "client" : "192.168.1.41",
    "allUsers" : [],
    "user" : ""
}
还有就是这种聚合查询
{
    "op" : "command",
    "ns" : "osci.$cmd",
    "command" : {
        "aggregate" : "searchHistory",
        "pipeline" : [
            {
                "$group" : {
                    "_id" : "$term",
                    "sum" : {
                        "$sum" : 1
                    }
                }
            },
            {
                "$sort" : {
                    "sum" : -1
                }
            },
            {
                "$limit" : 10
            }
        ]
    },
    "keyUpdates" : 0,
    "numYield" : 13,
    "lockStats" : {
        "timeLockedMicros" : {
            "r" : NumberLong(78909),
            "w" : NumberLong(0)
        },
        "timeAcquiringMicros" : {
            "r" : NumberLong(742900),
            "w" : NumberLong(190)
        }
    },
    "responseLength" : 350,
    "millis" : 857,
    "execStats" : {},
    "ts" : ISODate("2015-01-28T10:36:36.701Z"),
    "client" : "192.168.1.41",
    "allUsers" : [],
    "user" : ""
}

oplog部分日志
2015-01-28T18:43:02.981+0800 [conn2499] insert osci.searchHistory ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:50142 480ms
2015-01-28T18:43:02.981+0800 [conn2538] insert osci.searchHistory ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:149108 234ms
2015-01-28T18:43:04.534+0800 [conn2500] insert osci.searchHistory ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:132 123ms
2015-01-28T18:43:04.534+0800 [conn2519] insert osci.historyInfo ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:93 219ms
2015-01-28T18:43:04.534+0800 [conn2516] insert osci.loginLog ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:237 140ms
2015-01-28T18:43:04.533+0800 [conn2490] insert osci.historyInfo ninserted:1 keyUpdates:0 numYields:0 locks(micros) w:75 225ms
2015-01-28T18:42:51.673+0800 [conn2520] command osci.$cmd command: aggregate { aggregate: "searchHistory", pipeline: [ { $group: { _id: "$term", sum: { $sum: 1 } } }, { $sort: { sum: -1 } }, { $limit: 10 } ] } keyUpdates:0 numYields:9 locks(micros) r:84739 reslen:350 104ms
2015-01-28T18:42:51.676+0800 [conn2555] command osci.$cmd command: aggregate { aggregate: "searchHistory", pipeline: [ { $group: { _id: "$term", sum: { $sum: 1 } } }, { $sort: { sum: -1 } }, { $limit: 10 } ] } keyUpdates:0 numYields:10 locks(micros) r:88022 reslen:350 109ms
2015-01-28T18:42:51.699+0800 [conn2546] command osci.$cmd command: aggregate { aggregate: "searchHistory", pipeline: [ { $group: { _id: "$term", sum: { $sum: 1 } } }, { $sort: { sum: -1 } }, { $limit: 10 } ] } keyUpdates:0 numYields:15 locks(micros) r:161715 reslen:350 132ms
2015-01-28T18:42:51.730+0800 [conn2498] command osci.$cmd command: aggregate { aggregate: "searchHistory", pipeline: [ { $group: { _id: "$term", sum: { $sum: 1 } } }, { $sort: { sum: -1 } }, { $limit: 10 } ] } keyUpdates:0 numYields:8 locks(micros) r:85279 reslen:350 104ms
2015-01-28T18:42:52.042+0800 [conn2511] command osci.$cmd command: aggregate { aggregate: "searchHistory", pipeline: [ { $group: { _id: "$term", sum: { $sum: 1 } } }, { $sort: { sum: -1 } }, { $limit: 10 } ] } keyUpdates:0 numYields:13 locks(micros) r:124860 reslen:350 175ms
2015-01-28T18:42:52.094+0800 [conn2530] command osci.$cmd command: aggregate { aggregate: "searchHistory", pipeline: [ { $group: { _id: "$term", sum: { $sum: 1 } } }, { $sort: { sum: -1 } }, { $limit: 10 } ] } keyUpdates:0 numYields:12 locks(micros) r:196746 reslen:350 192ms


这个是serverStatus结果
> db.serverStatus();
{
    "host" : "oscitest-virtual-machine",
    "version" : "2.6.7",
    "process" : "mongod",
    "pid" : NumberLong(9486),
    "uptime" : 87730,
    "uptimeMillis" : NumberLong(87729330),
    "uptimeEstimate" : 72225,
    "localTime" : ISODate("2015-01-28T12:10:08.179Z"),
    "asserts" : {
        "regular" : 0,
        "warning" : 0,
        "msg" : 0,
        "user" : 0,
        "rollovers" : 0
    },
    "backgroundFlushing" : {
        "flushes" : 1462,
        "total_ms" : 321638,
        "average_ms" : 219.9986320109439,
        "last_ms" : 12,
        "last_finished" : ISODate("2015-01-28T12:10:01.978Z")
    },
    "connections" : {
        "current" : 115,
        "available" : 704,
        "totalCreated" : NumberLong(2584)
    },
    "cursors" : {
        "note" : "deprecated, use server status metrics",
        "clientCursors_size" : 0,
        "totalOpen" : 0,
        "pinned" : 0,
        "totalNoTimeout" : 0,
        "timedOut" : 224
    },
    "dur" : {
        "commits" : 29,
        "journaledMB" : 0,
        "writeToDataFilesMB" : 0,
        "compression" : 0,
        "commitsInWriteLock" : 0,
        "earlyCommits" : 0,
        "timeMs" : {
            "dt" : 3046,
            "prepLogBuffer" : 0,
            "writeToJournal" : 0,
            "writeToDataFiles" : 0,
            "remapPrivateView" : 0
        }
    },
    "extra_info" : {
        "note" : "fields vary by platform",
        "heap_usage_bytes" : 76989000,
        "page_faults" : 161806
    },
    "globalLock" : {
        "totalTime" : NumberLong("87729331000"),
        "lockTime" : NumberLong(143420999),
        "currentQueue" : {
            "total" : 0,
            "readers" : 0,
            "writers" : 0
        },
        "activeClients" : {
            "total" : 0,
            "readers" : 0,
            "writers" : 0
        }
    },
    "indexCounters" : {
        "accesses" : 1064282,
        "hits" : 1064282,
        "misses" : 0,
        "resets" : 0,
        "missRatio" : 0
    },
    "locks" : {
        "." : {
            "timeLockedMicros" : {
                "R" : NumberLong(83181765),
                "W" : NumberLong(143420999)
            },
            "timeAcquiringMicros" : {
                "R" : NumberLong(66418300),
                "W" : NumberLong(6067897)
            }
        },
        "admin" : {
            "timeLockedMicros" : {
                "r" : NumberLong(662513),
                "w" : NumberLong(0)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(49404),
                "w" : NumberLong(0)
            }
        },
        "local" : {
            "timeLockedMicros" : {
                "r" : NumberLong(764698),
                "w" : NumberLong(14)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(561198),
                "w" : NumberLong(0)
            }
        },
        "osci" : {
            "timeLockedMicros" : {
                "r" : NumberLong("45414224309"),
                "w" : NumberLong(376034735)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong("23345527775"),
                "w" : NumberLong("5348846639")
            }
        },
        "test" : {
            "timeLockedMicros" : {
                "r" : NumberLong(65479),
                "w" : NumberLong(1648254)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(44008),
                "w" : NumberLong(38)
            }
        },
        "mongo_test" : {
            "timeLockedMicros" : {
                "r" : NumberLong(373355),
                "w" : NumberLong(180)
            },
            "timeAcquiringMicros" : {
                "r" : NumberLong(241661),
                "w" : NumberLong(7)
            }
        }
    },
    "network" : {
        "bytesIn" : 11921473798,
        "bytesOut" : 659216698,
        "numRequests" : 1300602
    },
    "opcounters" : {
        "insert" : 139853,
        "query" : 329791,
        "update" : 21517,
        "delete" : 0,
        "getmore" : 313,
        "command" : 768435
    },
    "opcountersRepl" : {
        "insert" : 0,
        "query" : 0,
        "update" : 0,
        "delete" : 0,
        "getmore" : 0,
        "command" : 0
    },
    "recordStats" : {
        "accessesNotInMemory" : 28,
        "pageFaultExceptionsThrown" : 7,
        "admin" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        },
        "local" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        },
        "mongo_test" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        },
        "osci" : {
            "accessesNotInMemory" : 28,
            "pageFaultExceptionsThrown" : 7
        },
        "test" : {
            "accessesNotInMemory" : 0,
            "pageFaultExceptionsThrown" : 0
        }
    },
    "writeBacksQueued" : false,
    "mem" : {
        "bits" : 64,
        "resident" : 3074,
        "virtual" : 54089,
        "supported" : true,
        "mapped" : 26804,
        "mappedWithJournal" : 53608
    },
    "metrics" : {
        "cursor" : {
            "timedOut" : NumberLong(224),
            "open" : {
                "noTimeout" : NumberLong(0),
                "pinned" : NumberLong(0),
                "total" : NumberLong(0)
            }
        },
        "document" : {
            "deleted" : NumberLong(0),
            "inserted" : NumberLong(139853),
            "returned" : NumberLong(1273310),
            "updated" : NumberLong(21517)
        },
        "getLastError" : {
            "wtime" : {
                "num" : 0,
                "totalMillis" : 0
            },
            "wtimeouts" : NumberLong(0)
        },
        "operation" : {
            "fastmod" : NumberLong(17751),
            "idhack" : NumberLong(19188),
            "scanAndOrder" : NumberLong(17)
        },
        "queryExecutor" : {
            "scanned" : NumberLong("2448776088"),
            "scannedObjects" : NumberLong("2448776088")
        },
        "record" : {
            "moves" : NumberLong(0)
        },
        "repl" : {
            "apply" : {
                "batches" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "ops" : NumberLong(0)
            },
            "buffer" : {
                "count" : NumberLong(0),
                "maxSizeBytes" : 268435456,
                "sizeBytes" : NumberLong(0)
            },
            "network" : {
                "bytes" : NumberLong(0),
                "getmores" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "ops" : NumberLong(0),
                "readersCreated" : NumberLong(0)
            },
            "preload" : {
                "docs" : {
                    "num" : 0,
                    "totalMillis" : 0
                },
                "indexes" : {
                    "num" : 0,
                    "totalMillis" : 0
                }
            }
        },
        "storage" : {
            "freelist" : {
                "search" : {
                    "bucketExhausted" : NumberLong(0),
                    "requests" : NumberLong(142818),
                    "scanned" : NumberLong(272500)
                }
            }
        },
        "ttl" : {
            "deletedDocuments" : NumberLong(0),
            "passes" : NumberLong(1461)
        }
    },
    "ok" : 1
}

请大家指点一下,看下具体瓶颈在哪,如何优化
加载中
1
icanfly
icanfly
会不会是磁盘预分配问题引起的,windows建设预先分配,linux最好使用ext4,ext3及以下会导致数据文件分配很慢,导致假死现象。
0
Injection
Injection
是不是你电脑配置差了,200并发也太低了吧
Injection
Injection
回复 @高压东 : 你测试一下磁盘速度
高压东
高压东
机器没问题,4核8G内存,无论cpu跟内存都有不少空间
0
绝对是路过
使用mongodb 我个人不建议频繁使用复杂的查询,分组等,查询的字段必须建立索引,否则数据量一大,速度非常慢
绝对是路过
你MongoDB是那个版本 64位的吧?
高压东
高压东
现在数据量并不大,而且很多插入也耗时好几秒
0
e
eshujiushiwo

哈喽你好。

没有太仔细看,但是,你的lockstate状态如下:

  "lockStats" : {
        "timeLockedMicros" : {
            "r" : NumberLong(0),
            "w" : NumberLong(381)
        },
        "timeAcquiringMicros" : {
            "r" : NumberLong(0),
            "w" : NumberLong(620)
        }


但是mills居然是5000+

这很不科学啊。

但是我没用过spring。建议观察下io且调试程序让他返回插入与更新mongo的返回什么的。

简单的压测垃圾机器 insert 随便都可以1W5/s


aggregate的话 你没有match,就是说他得吧所有的数据按照你的pipeline来做,最后再sort和limit,当然慢了。

0
神州浪子
神州浪子
检查一下进行费时操作时候的磁盘IO
高压东
高压东
回复 @神州浪子 : 如果是io的问题,那如何解决呢,现在的并发量很小,而且操作的数据量也不大
神州浪子
神州浪子
回复 @高压东 : 我猜想这就是问题所在。IO影响实在太大,我们实际上使用mongo的经验,只要IO有瞬间飙升到100的情况,那么所有的操作都会变得极慢。
高压东
高压东
磁盘IO,用iostat看,util大部分时候都是10+,20+,有时也能到100,但是出现情况很少
0
各种打杂
各种打杂

我们用的4太服务器做的mongo集群,没有说你说的性能低下的问题。并发在1000-2000,服务器load值很低,op/s 比较高一点:平均 163, 服务器配置是: E5-26704核,16G内存

0
b
banei
内存有多少?mongo很吃内存的,如果内存小于数据和索引,可能会很慢
返回顶部
顶部