民工哥 MongoDB 教程：MD 日志分析工具-每日运维

需求背景

MongoDB 数据库的强大的文档模型使其成为处理数据的最佳方式。文档适用于广泛的流行数据模型，支持各种各样的场景。文档模型可以包含键值、关系数据集和图形数据集，当然，还可以包含父子关系、列表/数组以及其他层次关系，它们比传统的关系型数据库技术（表格）具有更大的灵活性。由于文档模型与主流面向对象编程语言中的对象直接对应，因此开发人员可以根据现实世界中实体之间的自然关系存储和组织数据，从而将重点放在以最有意义的方式构建应用程序上，而不是围绕其数据库的局限性开展工作。因此，使用文档模型显著提高了开发人员的生产效率，使组织机构能够更快地进行创新。MongoDB CEO 兼总裁 Dev Ittycheria称之为：文档即未来。

但是 MongoDB 通用的监控工具有限，其中又有一部分还是要收费的,通过工具 Percona Monitoring and Management 进行监控，是个不错的选择。但在慢查询收集方面，需要开启Profiling，对性能方面会有一些侵害，另外，更细粒度的监控项维护起来也不容易。如果不想不开启Profiling，我们还可以通过收集分析mongodb的运行log来来进行性能监控，并且通过运行日志还可以获取更多的运行状态相关的信息。

今天介绍的就是一款专门用来读取、分析 MongoDB 运行日志的工具--Mtools。

mtools工具集介绍

mtools 工具集是什么？

开源地址介绍：https://github.com/rueckstiess/mtools

mtools 是一组工具集脚本，用于解析、过滤和可视化 MongoDB 日志文件 ( mongod, mongos)。mtools也包含mlaunch工具，该工具可以快速搭建本地测试环境。mtransfer工具可以用于数据库之间数据传输。

mtools工具组件介绍

mlogfilter：日志过滤组件，支持按时间切割、合并、过滤慢查询、查找全表扫描操作，支持通过多个属性进行信息过滤，支持输出为JSON格式。
mloginfo：返回有关日志文件的信息，例如：开始和结束时间、版本、二进制文件、重新启动、连接、不同视图等特殊部分
mplotqueries：支持将日志分析结果转换为图表形式，依赖于tkinter(python图形模块)和matplotlib模块。
mlaunch：支持快速部署本地测试环境，可以是单机、副本集、分片集群。（依赖pymongo）
mtransfer：通过复制 WiredTiger 数据文件在 MongoDB 实例之间传输数据库的实验脚本。（需要pymongo和wiredtiger）

mtools工具的使用

#安装mtools工具及依赖
pip3 install mtools
yum install python-tools
pip3 install psutil
pip3 install pymongo
pip3 install matplotlib
pip3 install numpy

#安装Python环境
wget https://www.python.org/ftp/python/3.6.8/Python-3.6.8.tar.xz 
xz -d Python-3.6.8.tar.xz 
tar -xvf Python-3.6.8.tar

cd Python-3.6.8/
./configure --with-ssl             # 带上ssl不然pip会出现错误
make
make install

mloginfo日志统计

日志总体信息，比如：日志的起止时间范围、主机端口、版本、数据库引擎等概要信息。

[root@10-23-85-17 ~]# mloginfo mongodb.log 
     source: mongodb.log
       host: 84b511baa949:27017
      start: 2022 May 27 00:00:05.941
        end: 2022 May 28 00:00:06.954
date format: iso8601-local
   timezone: UTC +0800
     length: 1437359
     binary: mongod
    version: 3.2.7
    storage: wiredTiger

连接数

[root@10-23-85-17 ~]# mloginfo mongodb.log --connections
     source: mongodb.log
       host: 84b511baa949:27017
      start: 2022 May 27 00:00:05.941
        end: 2022 May 28 00:00:06.954
date format: iso8601-local
   timezone: UTC +0800
     length: 1437359
     binary: mongod
    version: 3.2.7
    storage: wiredTiger

CONNECTIONS
     total opened: 14282
     total closed: 14358
    no unique IPs: 4
socket exceptions: 0
127.0.0.1 opened: 12886 closed: 12889
172.21.0.10 opened: 658 closed: 716
172.21.0.20 opened: 461 closed: 490
172.21.0.30 opened: 277 closed: 263

事件统计

即统计出当前某些事件的发生频次

[root@10-23-85-17 ~]# mloginfo mongodb.log --distinct
     source: mongodb.log
       host: 84b511baa949:27017
      start: 2022 May 27 00:00:05.941
        end: 2022 May 28 00:00:06.954
date format: iso8601-local
   timezone: UTC +0800
     length: 1437359
     binary: mongod
    version: 3.2.7
    storage: wiredTiger

DISTINCT
                                                                    
   25460  SocketException handling request, closing client connection:
   19504  assertion ... ns: ... query:
   18464  exception: ... on:
    5075  going to kill op:
     660  Index ... :
     400  Error in heartbeat request to ... ;
     312  build index on: ... properties:
     312  building index using bulk method
     300  Placing a marker at optime
      59  Successfully connected to
      44  Member ... is now in state
      28  DBClientCursor::init call() failed
      27  Socket recv() timeout
      27  SocketException: remote: ... error:
      23  Plan executor error during find: ... , stats:
      18  transition to

慢查询

显示所有慢查询，并按出现次数排序

[root@10-23-85-17 ~]# mloginfo mongodb.log --queries --sort count
     source: mongodb.log
       host: 84b511baa949:27017
      start: 2022 May 27 00:00:05.941
        end: 2022 May 28 00:00:06.954
date format: iso8601-local
   timezone: UTC +0800
     length: 1437359
     binary: mongod
    version: 3.2.7
    storage: wiredTiger

QUERIES
namespace         operation    pattern                                                                count     min (ms)    max (ms)    95%-ile (ms)    sum (ms)       mean (ms)    allowDiskUse
doyo.news         count        {"$or": [{"n_cate": 1}, {"n_prop": 1}], "bigcate": 1, "status": 1}     188339         587      492592         45736.2     1247160002       6621.9    None
doyo.resource     query        {"cate": 1, "status": 1}                                               173569         101      429614          1792.0       78818078        454.1    None
doyo.news         query        {"nid": 1, "status": 1}                                                120989         101     1159648        760531.2    12485218384

重启信息

[root@10-23-85-17 ~]# mloginfo mongodb.log --restart
     source: mongodb.log
       host: 84b511baa949:27017
      start: 2022 May 27 00:00:05.941
        end: 2022 May 28 00:00:06.954
date format: iso8601-local
   timezone: UTC +0800
     length: 1437359
     binary: mongod
    version: 3.2.7
    storage: wiredTiger

RESTARTS
   May 27 08:44:55 version 3.2.7
   May 27 08:59:23 version 3.2.7
   May 27 11:25:00 version 3.2.7

副本切换情况

[root@10-23-85-17 ~]# mloginfo mongodb.log --rsstate
     source: mongodb.log
       host: 84b511baa949:27017
      start: 2022 May 27 00:00:05.941
        end: 2022 May 28 00:00:06.954
date format: iso8601-local
   timezone: UTC +0800
     length: 1437359
     binary: mongod
    version: 3.2.7
    storage: wiredTiger

RSSTATE
date               host                 state/message

May 27 08:44:58    10.23.1.242:27017    ARBITER
May 27 08:44:58    10.23.1.26:27017     PRIMARY
May 27 08:54:42    10.23.1.26:27017     SECONDARY
May 27 08:59:25    10.23.1.242:27017    ARBITER
May 27 08:59:25    10.23.1.26:27017     SECONDARY
May 27 08:59:30    10.23.1.26:27017     PRIMARY
May 27 08:59:42    10.23.1.26:27017     SECONDARY

日志过滤

mlogfilter是一个强大的日志过滤模块，相比linux 的grep/egrep的文本过滤，该组件可以对日志内容进行解析，并按我们想要的结果进行过滤。

查询超过10s的慢查询

[root@10-23-85-17 ~]# mlogfilter mongodb.log --slow 10000 --shorten 200

2022-05-27T08:27:25.862+0800 I COMMAND [conn84751] query doyo.news query: { $query: { nid: { $gt: ...0 } }, Database: { acquireCount: { r: 3795 } }, Collection: { acquireCount: { r: 3795 } } } 10510ms
2022-05-27T08:27:28.254+0800 I COMMAND [conn84689] command doyo.news command: count { count: "news... acquireCount: { r: 3788 } }, Collection: { acquireCount: { r: 3788 } } } protocol:op_query 10247ms

查询慢扫描操作

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

[root@10-23-85-17 ~]# mlogfilter mongodb.log --scan --shorten 200

2022-05-27T12:10:51.816+0800 I COMMAND [conn581] query doyo.news query: { $query: { bigcate: "2", ...0 } }, Database: { acquireCount: { r: 1470 } }, Collection: { acquireCount: { r: 1470 } } } 11869ms
2022-05-27T12:10:53.739+0800 I COMMAND [conn578] query doyo.news query: { $query: { bigcate: "1", ...6 } }, Database: { acquireCount: { r: 3183 } }, Collection: { acquireCount: { r: 3183 } } } 14412ms

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

[root@10-23-85-17 ~]# mlogfilter mongodb.log --from May 27 0:00 --to "+1h" | tail -n3

2022-05-27T00:00:05.941+0800 I CONTROL [conn80893] distarch: x86_64
2022-05-27T00:00:05.941+0800 I CONTROL [conn80893] target_arch: x86_64

根据名称空间过滤

# mlogfilter mongo.log --namespace dmspace.DeviceInfo
2018-05-18T21:50:58.105+0800 I COMMAND [conn31] command dmspace.DeviceInfo appName: "MongoDB Shell...adata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 2963ms
2018-05-18T21:50:59.195+0800 I COMMAND [conn31] command dmspace.DeviceInfo appName: "MongoDB Shell...tadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 936ms
2018-05-18T21:51:00.173+0800 I COMMAND [conn44] command dmspace.DeviceInfo command: insert { inser...tadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 745ms
2018-05-18T21:51:00.433+0800 I COMMAND [conn44] command dmspace.DeviceInfo command: insert { inser...tadata: { acquireCount: { w: 16 } }, oplog: { acquireCount: { w: 16 } } } protocol:op_command 252ms

根据操作类型过滤

# mlogfilter mongo.log --operation update
2018-05-18T21:56:25.114+0800 I WRITE [conn156] update dmspace.PolicyTask query: { _id: "###" } pla...Count: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 2630ms
2018-05-18T21:56:25.114+0800 I WRITE [conn92] update nsspace.TimerTask query: { _id: "###" } planS...Count: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 1264ms
2018-05-18T21:56:25.125+0800 I WRITE [conn43] update dmspace.TaskHistory query: { _id: "###" } pla...Count: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 2643ms
2018-05-18T21:56:30.027+0800 I WRITE [conn532] update dmspace.TaskHistory query: { _id: "###" } pl...eCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 868ms
2018-05-18T21:56:32.115+0800 I WRITE [conn517] update dmspace.TaskHistory query: { _id: "###" } pl...eCount: { w: 2 } }, Metadata: { acquireCount: { w: 1 } }, oplog: { acquireCount: { w: 1 } } } 497ms

链接：https://www.starcto.com/mongodb/295.html

民工哥 MongoDB 教程：MD 日志分析工具

需求背景

mtools工具集介绍

mtools 工具集是什么？

mtools工具组件介绍

mtools工具的使用

mloginfo日志统计

连接数

事件统计

慢查询

重启信息

副本切换情况

日志过滤

查询超过10s的慢查询

查询慢扫描操作

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

根据名称空间过滤

根据操作类型过滤

相关文章

发布评论取消回复

共饮一杯

Oracle回收DBA权限注意事项

MongoDB 入门教学贴从术语到操作（约束怎么建立内部培训贴）

RisingWave 1.10 发布！新增用户自定义聚合函数

民工哥 MongoDB 教程：MD 日志分析工具

需求背景

mtools工具集介绍

mtools 工具集是什么？

mtools工具组件介绍

mtools工具的使用

mloginfo日志统计

连接数

事件统计

慢查询

重启信息

副本切换情况

日志过滤

查询超过10s的慢查询

查询慢扫描操作

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

根据名称空间过滤

根据操作类型过滤

相关文章

发布评论 取消回复

共饮一杯

Oracle回收DBA权限注意事项

MongoDB 入门教学贴 从术语到操作 （约束怎么建立 内部培训贴）

RisingWave 1.10 发布！新增用户自定义聚合函数

发布评论取消回复

MongoDB 入门教学贴从术语到操作（约束怎么建立内部培训贴）