文章目录
  1. 1. 异常日志
  2. 2. MongoDB的慢查询
    1. 2.1. 开启Profiling功能
    2. 2.2. 查询Profiling等级
    3. 2.3. 查询Profiling记录
  3. 3. 出现原因及解决方案

最近公司曲库接入新曲库上线,昨晚高峰期的时候应用报警,上去发现很多MongoTimeoutException异常,该异常最近一直有遇到,原因更是如出一辙,所以这里就记录一下。

异常日志

com.mongodb.MongoTimeoutException: Timeout waiting for a pooled item after 3000 MILLISECONDS
    at com.mongodb.ConcurrentPool.get(ConcurrentPool.java:113)
    at com.mongodb.PooledConnectionProvider.get(PooledConnectionProvider.java:75)
    at com.mongodb.DefaultServer.getConnection(DefaultServer.java:60)
    at com.mongodb.BaseCluster$WrappedServer.getConnection(BaseCluster.java:216)
    at com.mongodb.DBTCPConnector$MyPort.getConnection(DBTCPConnector.java:503)
    at com.mongodb.DBTCPConnector$MyPort.get(DBTCPConnector.java:451)
    at com.mongodb.DBTCPConnector.innerCall(DBTCPConnector.java:286)
    at com.mongodb.DBTCPConnector.call(DBTCPConnector.java:271)
    at com.mongodb.DBCollectionImpl.find(DBCollectionImpl.java:84)
    at com.mongodb.DBCollectionImpl.find(DBCollectionImpl.java:66)
    at com.mongodb.DBCursor._check(DBCursor.java:458)
    at com.mongodb.DBCursor._hasNext(DBCursor.java:546)
    at com.mongodb.DBCursor.hasNext(DBCursor.java:571)
    at org.jongo.MongoCursor.hasNext(MongoCursor.java:38)
    at com.ttpod.common.mongo.CursorListHelper.convert(CursorListHelper.java:14)

MongoDB默认的连接超时时间是3s,这里并不能通过简单设置超时时间来解决该问题,而是应该去数据库查看数据库的状态,最后发现是库中存在很多慢查询,一直占用连接不释放,导致其他连接超时。

MongoDB的慢查询

慢查询是数据库查询优化的一部分内容,通过查看慢查询日志,可以找到数据库查询问题在哪里。

开启Profiling功能

  1. 客户端

    db.setProfilingLevel(1);  
    

    Level共有三个等级:

    0 – 不开启
    1 – 记录慢命令 (默认为>100ms)
    2 – 记录所有命令
    

    Level 1 的超时时间默认为100ms,可以通过

    db.setProfilingLevel( level , slowms ) 设置
    
  2. 启动时

    启动MongoDB时加上–profile 和 –slowms 参数
               
    

查询Profiling等级

db.setProfilingLevel();                 

查询Profiling记录

Mongo Profile 记录是直接存在系统db里的,记录位置 system.profile ,所以,我们只要查询这个Collection的记录就可以获取到我们的 Profile 记录了

ttrs_quku:SECONDARY> db.system.profile.find()

{ "op" : "getmore", "ns" : "ttpod_songs.songsFile", "cursorid" : 653122545872, "ntoreturn" : 0, "keyUpdates" : 0, "numYield" : 214, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(152153), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(328), "w" : NumberLong(3) } }, "nreturned" : 22676, "responseLength" : 4194310, "millis" : 132, "execStats" : {  }, "ts" : ISODate("2015-10-25T16:23:36.189Z"), "client" : "10.147.238.83", "allUsers" : [ ], "user" : "" }
{ "op" : "getmore", "ns" : "ttpod_songs.songsFile", "cursorid" : 653122545872, "ntoreturn" : 0, "keyUpdates" : 0, "numYield" : 156, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(139827), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(231), "w" : NumberLong(2) } }, "nreturned" : 23193, "responseLength" : 4194446, "millis" : 107, "execStats" : {  }, "ts" : ISODate("2015-10-25T16:23:37.058Z"), "client" : "10.147.238.83", "allUsers" : [ ], "user" : "" }
{ "op" : "getmore", "ns" : "ttpod_songs.songsFile", "cursorid" : 653122545872, "ntoreturn" : 0, "keyUpdates" : 0, "numYield" : 232, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(146159), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(333), "w" : NumberLong(4) } }, "nreturned" : 22450, "responseLength" : 4194397, "millis" : 120, "execStats" : {  }, "ts" : ISODate("2015-10-25T16:23:38.820Z"), "client" : "10.147.238.83", "allUsers" : [ ], "user" : "" }
{ "op" : "getmore", "ns" : "ttpod_songs.songsFile", "cursorid" : 653122545872, "ntoreturn" : 0, "keyUpdates" : 0, "numYield" : 162, "lockStats" : { "timeLockedMicros" : { "r" : NumberLong(135602), "w" : NumberLong(0) }, "timeAcquiringMicros" : { "r" : NumberLong(253), "w" : NumberLong(4) } }, "nreturned" : 23162, "responseLength" : 4194302, "millis" : 101, "execStats" : {  }, "ts" : ISODate("2015-10-25T16:23:39.680Z"), "client" : "10.147.238.83", "allUsers" : [ ], "user" : "" }

其中:

  1. ts-该命令在何时执行.
  2. millis Time-该命令执行耗时,以毫秒记.
  3. info-本命令的详细信息.
  4. query-表明这是一个query查询操作.
  5. ntoreturn-本次查询客户端要求返回的记录数.比如, findOne()命令执行时 ntoreturn 为 1.有limit(n) 条件时ntoreturn为n.
  6. query-具体的查询条件(如x>3).
  7. nscanned-本次查询扫描的记录数.
  8. reslen-返回结果集的大小.
  9. nreturned-本次查询实际返回的结果集.
  10. update-表明这是一个update更新操作.
  11. fastmod-Indicates a fast modify operation. See Updates. These operations are normally quite fast.
  12. fastmodinsert – indicates a fast modify operation that performed an upsert.
  13. upsert-表明update的upsert参数为true.此参数的功能是如果update的记录不存在,则用update的条件insert一条记录.
  14. moved-表明本次update是否移动了硬盘上的数据,如果新记录比原记录短,通常不会移动当前记录,如果新记录比原记录长,那么可能会移动记录到其它位置,这时候会导致相关索引的更新.磁盘操作更多,加上索引更新,会使得这样的操作比较慢.
  15. insert-这是一个insert插入操作.
  16. getmore-这是一个getmore 操作,getmore通常发生在结果集比较大的查询时,第一个query返回了部分结果,后续的结果是通过getmore来获取的。
    注:查询慢查询需要连接到具体的数据库才能查询出来。

出现原因及解决方案

最终排查出来慢查询主要出现在一个同事最近才加的一张记录调用服务出错日志的表中,没有预料到数据在短短一天增长到400W,查询时并没有添加索引。

最终添加索引之后程序恢复正常。

文章目录
  1. 1. 异常日志
  2. 2. MongoDB的慢查询
    1. 2.1. 开启Profiling功能
    2. 2.2. 查询Profiling等级
    3. 2.3. 查询Profiling记录
  3. 3. 出现原因及解决方案