1.查看mongodb进程 ps-ef | grep mongo 获取进程id为3267
2.查看进程的线程 top -p 3267 按shift+h 查看cpu高的线程,发现有线程点用cpu高且cpu时间很长,有线程的cpu时间有23分钟,说明一直有线程在消耗cpu,要找到执行这个线程在具体做什么操作
找到目前占用cpu最高的线程id为46265,该线程占用cpu 85.2%现在,如下图。
3.查看mongo进程3267的各线程系统调用情况
pstack 3267 >stack.log 导出到stack.log 见附件 stack.log 发现了290个线程如下图
从线程中找出上面的id为46265线程如下图,下图中红线画出的就是操作系统中给mongo的进程3267分配的线程id:46265,这个46265对应的mongo堆客栈中的线程id即为下图中白色的横线处的16进制的id:0x7f2311c18700
将16进程的0x7f2311c18700 转换为10进制
printf %d 0x7f230dad7700 结果
139788530054912
如下图红线中所示
上面红线中的数字非常重要,上面这个数字即为接下来要查找问题的关键
4.查看mongo当前有哪些操作,
执行命令:db.currentOp(true); 如下图所示,在结果中查找 139788530054912 找到如下图所示的查询操作,下面的这个threadId对就的操作即为刚才用cpu高的查更新操作,
到此就找出了占用cpu高的mongo的操作,此次为更新操作导致该线程占用cpu高。
本文结合操作系统的堆栈调用命令pstack 和mongodb的命令db.currentOp(true);快速定位cpu占用高的mongo操作。希望对大家有所帮助。
为了方便查看,可以开启mongo的慢日志记录,操作如下
1.查看mongodb慢日志是否开起
use BJ_Rack;
db.getProfilingStatus();
发现没有开户慢日志
2.开启慢日志,设置超过100毫秒的操作为慢操作
db.setProfilingLevel(1,100);
3.查看慢日志内容
db.system.profile.find().sort({$natural:-1})
得到50个比较慢的操作日志,
详情见附件 mongodb慢日志的操作
上面日志中最高的操作时间差不多2秒
慢日志对mongo性能分析很有用,建议在测试的时候都开启。