博客

由提示可知 是读取消息时超时，因为我们项目配置的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,有用到索引，但是索引符合到的数据量很多，导致也很慢

通过查询日志 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也是。

参考相关博文，感谢相关博主：

https://www.cnblogs.com/zhouqinxiong/p/5554779.html

https://www.jb51.net/article/123713.htm

https://www.cnblogs.com/duhuo/articles/4762933.html

https://www.jb51.net/article/137119.htm

https://blog.csdn.net/user_longling/article/details/83957085