由提示可知 是读取消息时超时,因为我们项目配置的SocketTimeOut是5秒,也就是说,是在读取5秒后,还未返回响应,就报了这个异常。

怀疑两个原因:

1.因为锁的原因,比如说写锁阻塞,其他读锁都只能等待。

2.怀疑是查询慢的问题

排查步骤如下,首先进入Mongodb对应DB

执行db.currentOp()  查看目前正在执行的所有查询语句

##当前语句有没有在等待锁 false即为否
"waitingForLock" : false,
//当前整个服务器 整个库 整个表的读锁数和写锁数
"lockStats" : {
   "Global" : {
     "acquireCount" : {
        "r" : NumberLong(56),
        "w" : NumberLong(56)
        }
    },
    "Database" : {
        "acquireCount" : {
             "w" : NumberLong(56)
         }
    },
    "Collection" : {
         "acquireCount" : {
         "w" : NumberLong(56)
     }
   }
}

 看到几个语句的waitingForLock都是False,所以暂时排除锁的原因。

然后排查 查询慢的原因 1没有用到索引 2,有用到索引,但是索引符合到的数据量很多,导致也很慢

mongodb lock mongodb lock acquireconut_.net

通过查询日志 PlanSummay:IXSCAN{operUid:1} 表示它有用到operUid索引,通过keysExamined跟docsExamined可以知道,索引到的数据量很大,都是1万条多条。

因为当前索引是单索引,在多条件查询时,首先用operUid查到1万多条数据,然后再根据条件过滤掉记录。

因为常用的查询字段是operUid roomId type 所以我建了这三个字段的联合索引

然后用以下语句来实验下效果。

db.COLLECTION_NAME.explain("executionStats").find({operUid:70002431,type:1,endTime: { $exists:false },roomId:70228589})

尽管查询条件多了一个非索引字段endTime ,但执行毫秒数从6650,keysExamined28303 变成执行毫秒数11 totalKeysExamined 321 所以联合索引还是起到很大作用。

然后再看看应用的日志,从加了复合索引后,就没再报这个异常,即问题得以解决。

PS:.setProfilingLevel可以设值为0(不打开慢日志) 1 打开慢日志(默认执行超过100ms的才会记录) 2所有执行都会记录

setProfilingLevel(级别,毫秒数) setProfilingLevel(1,1000)就是只记录超过1秒的记录

在执行db.system.profile.drop() 前要关闭慢日志 setProfilingLevel(0)

PPS:打开慢日志记录,会影响CPU跟IO 如果CPU升高或者IO读写频繁可能跟这个原因有关,MYSQL也是。