mongodb 使用 profile + mtools 来分析慢查询

os：centos 7.4
mongdbo：3.2
mtools：1.4.1

mongodb 是一款优秀的nosql数据库，高灵活性和高性能。所以有必要监控mongodb的慢查询，以便进一步缩短响应时间。
mtools是一组用来解析和过滤MongoDB日志文件的脚本。

profile 设置

由于是初次设置，定义慢查询为 1000ms。

db.getProfilingLevel()
db.getProfilingStatus()

db.setProfilingLevel(1)
db.setProfilingLevel(1,1000)

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

mtools 简介

mtools 是非官方公司维护，仅由个人做开源维护，可以用来分析mongod, mongos产生的日志。在github可以自由获取。
下载
https://github.com/rueckstiess/mtools/tree/master

mlogfilter
日志过滤组件，支持按时间检索慢查询、全表扫描操作，支持通过多个属性进行信息过滤，支持输出为JSON格式。

mloginfo
返回一些日志文件信息，比如开始、结束时间，版本，二进制，还有重启，连接，去重视图等一些特殊部分。

mplotqueries
支持将日志分析结果转换为图表形式，依赖于tkinter(python图形模块)、和matplotlib模块。

mlogvis
支持将日志分析结果转换为一个独立的HTML页面，实现与mplotqueries同样的功能。

mlaunch
支持快速搭建本地测试环境，可以是单机、副本集、分片集群。

mtools需要 python2.7 或者 3.6。

mtools 下载

https://github.com/rueckstiess/mtools/tree/master

mtools 安装

参考
http://blog.rueckstiess.com/mtools/install.html

依赖的组件
https://github.com/rueckstiess/mtools/blob/develop/requirements.txt

ordereddict==1.1
python-dateutil==2.2
matplotlib==1.3.1
numpy==1.8.0
pymongo>=3.3.0
psutil>=5.4.2

# cd /tmp
# yum install python python-devel python-tools

# curl https://bootstrap.pypa.io/get-pip.py -o get-pip.py
# python get-pip.py

# pip install psutil
# pip install pymongo
# pip install matplotlib
# pip install numpy
# pip install python-dateutil
# pip install ordereddict

模块名称 作用
psutil 用于管理进程的工具
pymongo mongodb python驱动
matplotlib python的2D图表渲染模块
numpy 支持科学计算的工具

# cd /tmp
# git clone https://github.com/rueckstiess/mtools.git
# cd mtools
# git status
# git branch -a
# git checkout master
# more INSTALL.md
# python setup.py install

# which mloginfo
/usr/local/bin/mloginfo
# ls -lt /usr/local/bin |more
total 6216
-rwxr-xr-x 1 root root     384 May 31 19:57 mlaunch
-rwxr-xr-x 1 root root     390 May 31 19:57 mlogfilter
-rwxr-xr-x 1 root root     386 May 31 19:57 mloginfo
-rwxr-xr-x 1 root root     384 May 31 19:57 mlogvis
-rwxr-xr-x 1 root root     394 May 31 19:57 mplotqueries
-rwxr-xr-x 1 root root     388 May 31 19:57 mgenerate

# mloginfo --help
usage: mloginfo [-h] [--version] [--no-progressbar] [--verbose]
                [--connections] [--connstats] [--distinct] [--queries]
                [--sort {namespace,pattern,count,min,max,mean,95%,sum}]
                [--restarts] [--rsinfo] [--rsstate]
                [logfile [logfile ...]]

Extracts general information from logfile and prints it to stdout.

positional arguments:
  logfile               logfile(s) to parse

optional arguments:
  -h, --help            show this help message and exit
  --version             show program's version number and exit
  --no-progressbar      disables progress bar
  --verbose             show more verbose output (depends on info section)

info sections:
  Below commands activate additional info sections for the log file.

  --connections         outputs information about opened and closed
                        connections
  --connstats           outputs helpful statistics for connection duration
                        (min/max/avg)
  --distinct            outputs distinct list of all log line by message type
                        (slow)
  --queries             outputs statistics about query patterns
  --sort {namespace,pattern,count,min,max,mean,95%,sum}
  --restarts            outputs information about every detected restart
  --rsinfo              outputs replica set config information
  --rsstate             outputs information about every detected RS state
                        change

出现错误 UnicodeDecodeError: ‘utf8’ codec can’t decode byte 0xe5 in position

# mloginfo /tmp/mongodb/mongod.log-20180531-2.211 --connections
     source: /tmp/mongodb/mongod.log-20180531-2.211
Traceback (most recent call last):
  File "/usr/local/bin/mloginfo", line 11, in <module>
    load_entry_point('mtools==1.4.1', 'console_scripts', 'mloginfo')()
  File "/usr/local/lib/python2.7/site-packages/mtools-1.4.1-py2.7.egg/mtools/mloginfo/mloginfo.py", line 95, in main
    tool.run()
  File "/usr/local/lib/python2.7/site-packages/mtools-1.4.1-py2.7.egg/mtools/mloginfo/mloginfo.py", line 58, in run
    if self.logfile.hostname else "unknown"))
  File "/usr/local/lib/python2.7/site-packages/mtools-1.4.1-py2.7.egg/mtools/util/logfile.py", line 154, in hostname
    self._iterate_lines()
  File "/usr/local/lib/python2.7/site-packages/mtools-1.4.1-py2.7.egg/mtools/util/logfile.py", line 275, in _iterate_lines
    line = line.decode("utf-8")
  File "/usr/local/lib/python2.7/encodings/utf_8.py", line 16, in decode
    return codecs.utf_8_decode(input, errors, True)
UnicodeDecodeError: 'utf8' codec can't decode byte 0xe5 in position 1169: invalid continuation byte

查看charset

# file -bi /tmp/mongodb/mongod.log-20180531-2.211
text/plain; charset=us-ascii

修改 logfile.py ，添加print，观察输出

# vi /usr/local/lib/python2.7/site-packages/mtools-1.4.1-py2.7.egg/mtools/util/logfile.py +275

for ln, line in enumerate(self.filehandle):
            print('>>>>>>>>>>>',line)
            line = line.decode("utf-8")

观察到只要碰到中文立即报错。

iconv转换charset

# iconv -f ascii -t gbk -c /tmp/mongodb/mongod.log-20180531-2.211 > /tmp/mongodb/mongod.log-20180531-2.211-gbk

然后然后就一切顺利

# mloginfo /tmp/mongodb/mongod.log-20180531-2.211-gbk --connections
     source: /tmp/mongodb/mongod.log-20180531-2.211-gbk
       host: unknown
      start: 2018 May 30 02:30:04.504
        end: 2018 May 31 02:30:03.918
date format: iso8601-local
     length: 215377
     binary: unknown
    version: >= 3.0 (iso8601 format, level, component)
    storage: unknown

CONNECTIONS
     total opened: 81238
     total closed: 81419
    no unique IPs: 25
socket exceptions: 0

192.168.56.101       opened: 4         closed: 4       
192.168.56.102       opened: 4         closed: 4       
192.168.56.103       opened: 2         closed: 2       
192.168.56.104       opened: 1         closed: 0       

mloginfo

mloginfo令是一个用于做日志信息统计的工具。

连接数

# mloginfo mongod.log-20180531-2.211-gbk --connections

事件统计

# mloginfo mongod.log-20180531-2.211-gbk --distinct

重启信息

# mloginfo mongod.log-20180531-2.211-gbk --restart

副本集切换

# mloginfo mongod.log-20180531-2.211-gbk --rsstate

查询次数

# mloginfo mongod.log-20180531-2.211-gbk --queries --sort count

查看超过10s的慢操作

# mlogfilter mongod.log-20180531-2.211-gbk --slow 10000 --shorten 200

查看慢扫描操作
慢扫描是指该操作需要扫描过多的记录(超过1w行)，且返回数量不足扫描数量的1/100，这样的操作通常对CPU消耗很高，也比较低效

# mlogfilter mongod.log-20180531-2.211-gbk --scan --shorten 200

根据名称空间过滤

# mlogfilter mongod.log-20180531-2.211-gbk --namespace dmspace.DeviceInfo

根据操作类型过滤

# mlogfilter mongod.log-20180531-2.211-gbk --operation update

获取某时间点之后1小时的日志

# mlogfilter mongod.log-20180531-2.211-gbk --from Apr 6 0:00 --to "+1h" | tail -n3

mplotqueries

mplotqueries 是基于tkinter实现的图表组件，可以将日志中扁平的文字信息转换为图表形式。
按操作分组输出的散点图

# mplotqueries mongod.log-20180531-2.211-gbk --group operations --output-file operations.png

按名称空间进行分组(限显示20个)，y轴为nscanned值，即扫描记录数量。

# mplotqueries mongod.log-20180531-2.211-gbk --group namespace --group-limit 20 --type scatter --yaxis nscanned --output-file namespace_nscan.png

默认情况下，y轴的呈现为时长(during)，可指定为其他指标：
指标名称 说明
nscanned 扫描数
nupdated 更新数
ninserted 插入数
ntoreturn 返回数
numYields 让步次数
r 读锁
w 写锁

比如每小时，每个集合的操作比例分布，此时可以采用直方图

# mplotqueries mongod.log-20180531-2.211-gbk --group namespace --bucketsize 3600 --group-limit 10 --type histogram --output-file namespaces_perhour.png

参考：
http://www.mongoing.com/eshu_mtools
https://www.mongodb.com/blog/post/introducing-mtools