MongoDB通过profile监控慢日志

2021-09-04 06:39:30

基础环境

CentOS 7.5
MongoDB 4.2分片集群

开启profile

单机版

> db.getProfilingLevel()
0

> use admin
switched to db admin
> db.setProfilingLevel(1,100)
{ "was" : 0, "slowms" : 100, "sampleRate" : 1, "ok" : 1 }
> db.getProfilingLevel()
1

0为不记录
1为记录慢查询，默认为100ms
2为全部记录
100为慢查询标准，单位毫秒

副本集

副本集中profile每个节点单独控制，所以需要在primary节点和secondary单独开启，开启方式同单机版。

分片集

分片集群需要在mongod节点打开，和副本集一样，需要在primary节点和secondary单独开启，开启方式同单机版。

测试profile

在mongos执行慢查询

mongos> db.test.find({id:{$lt:200,$gt:100}}).skip(10).sort({"id":1})
{ "_id" : ObjectId("608789c01bcca323a261fcee"), "id" : 111, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcef"), "id" : 112, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf0"), "id" : 113, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf1"), "id" : 114, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf2"), "id" : 115, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf3"), "id" : 116, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf4"), "id" : 117, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf5"), "id" : 118, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf6"), "id" : 119, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf7"), "id" : 120, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf8"), "id" : 121, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcf9"), "id" : 122, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcfa"), "id" : 123, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcfb"), "id" : 124, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcfc"), "id" : 125, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcfd"), "id" : 126, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcfe"), "id" : 127, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fcff"), "id" : 128, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fd00"), "id" : 129, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }
{ "_id" : ObjectId("608789c01bcca323a261fd01"), "id" : 130, "name" : "handong", "name1" : "handong", "name2" : "handong", "name3" : "handong" }

在mongod节点进行慢日志查看。

db.system.profile.find().pretty()

也可以使用如下命令查看最新10条慢日志。

db.system.profile.find().limit(10).sort({ts:-1}).pretty()

{
    "op" : "query",
    "ns" : "db3.test",
    "command" : {
        "find" : "test",
        "filter" : {
            "id" : {
                "$lt" : 200,
                "$gt" : 100
            }
        },
        "projection" : {
            "$sortKey" : {
                "$meta" : "sortKey"
            }
        },
        "sort" : {
            "id" : 1
        },
        "runtimeConstants" : {
            "localNow" : ISODate("2021-04-28T06:45:59.790Z"),
            "clusterTime" : Timestamp(1619592355, 1)
        },
        "shardVersion" : [
            Timestamp(0, 0),
            ObjectId("000000000000000000000000")
        ],
        "lsid" : {
            "id" : UUID("45045602-80dc-43b5-ab07-957b4aa2d094"),
            "uid" : BinData(0,"O0CMtIVItQN4IsEOsJdrPL8s7jv5xwh5a/A5Qfvs2A8=")
        },
        "$clusterTime" : {
            "clusterTime" : Timestamp(1619592355, 1),
            "signature" : {
                "hash" : BinData(0,"hsabhJcUvXSZ+19pG120EZLGAm8="),
                "keyId" : NumberLong("6941260985399246879")
            }
        },
        "$audit" : {
            "$impersonatedUsers" : [
                {
                    "user" : "admin",
                    "db" : "admin"
                }
            ],
            "$impersonatedRoles" : [
                {
                    "role" : "root",
                    "db" : "admin"
                }
            ]
        },
        "$client" : {
            "application" : {
                "name" : "MongoDB Shell"
            },
            "driver" : {
                "name" : "MongoDB Internal Client",
                "version" : "4.2.12"
            },
            "os" : {
                "type" : "Linux",
                "name" : "CentOS Linux release 7.9.2009 (Core)",
                "architecture" : "x86_64",
                "version" : "Kernel 3.10.0-1160.24.1.el7.x86_64"
            },
            "mongos" : {
                "host" : "mongo6:30000",
                "client" : "127.0.0.1:48674",
                "version" : "4.2.12"
            }
        },
        "$configServerState" : {
            "opTime" : {
                "ts" : Timestamp(1619592355, 1),
                "t" : NumberLong(22)
            }
        },
        "$db" : "db3"
    },
    "keysExamined" : 0,
    "docsExamined" : 1000000,
    "hasSortStage" : true,
    "cursorExhausted" : true,
    "numYield" : 7813,
    "nreturned" : 99,
    "queryHash" : "39C3AA47",
    "planCacheKey" : "39C3AA47",
    "locks" : {
        "ParallelBatchWriterMode" : {
            "acquireCount" : {
                "r" : NumberLong(1)
            }
        },
        "ReplicationStateTransition" : {
            "acquireCount" : {
                "w" : NumberLong(7815)
            }
        },
        "Global" : {
            "acquireCount" : {
                "r" : NumberLong(7815)
            }
        },
        "Database" : {
            "acquireCount" : {
                "r" : NumberLong(7814)
            }
        },
        "Collection" : {
            "acquireCount" : {
                "r" : NumberLong(7814)
            }
        },
        "Mutex" : {
            "acquireCount" : {
                "r" : NumberLong(2)
            }
        }
    },
    "flowControl" : {

    },
    "storage" : {

    },
    "responseLength" : 14044,
    "protocol" : "op_msg",
    "millis" : 918,
    "planSummary" : "COLLSCAN",
    "execStats" : {
        "stage" : "PROJECTION_DEFAULT",
        "nReturned" : 99,
        "executionTimeMillisEstimate" : 12,
        "works" : 1000103,
        "advanced" : 99,
        "needTime" : 1000003,
        "needYield" : 0,
        "saveState" : 7813,
        "restoreState" : 7813,
        "isEOF" : 1,
        "transformBy" : {
            "$sortKey" : {
                "$meta" : "sortKey"
            }
        },
        "inputStage" : {
            "stage" : "SORT",
            "nReturned" : 99,
            "executionTimeMillisEstimate" : 11,
            "works" : 1000103,
            "advanced" : 99,
            "needTime" : 1000003,
            "needYield" : 0,
            "saveState" : 7813,
            "restoreState" : 7813,
            "isEOF" : 1,
            "sortPattern" : {
                "id" : 1
            },
            "memUsage" : 11583,
            "memLimit" : 33554432,
            "inputStage" : {
                "stage" : "SORT_KEY_GENERATOR",
                "nReturned" : 99,
                "executionTimeMillisEstimate" : 11,
                "works" : 1000003,
                "advanced" : 99,
                "needTime" : 999903,
                "needYield" : 0,
                "saveState" : 7813,
                "restoreState" : 7813,
                "isEOF" : 1,
                "inputStage" : {
                    "stage" : "COLLSCAN",
                    "filter" : {
                        "$and" : [
                            {
                                "id" : {
                                    "$lt" : 200
                                }
                            },
                            {
                                "id" : {
                                    "$gt" : 100
                                }
                            }
                        ]
                    },
                    "nReturned" : 99,
                    "executionTimeMillisEstimate" : 10,
                    "works" : 1000002,
                    "advanced" : 99,
                    "needTime" : 999902,
                    "needYield" : 0,
                    "saveState" : 7813,
                    "restoreState" : 7813,
                    "isEOF" : 1,
                    "direction" : "forward",
                    "docsExamined" : 1000000
                }
            }
        }
    },
    "ts" : ISODate("2021-04-28T06:45:59.724Z"),
    "client" : "172.16.254.136",
    "appName" : "MongoDB Shell",
    "allUsers" : [
        {
            "user" : "__system",
            "db" : "local"
        }
    ],
    "user" : "__system@local"
}

输出解读

system.profile.op
这一项主要包含如下几类

insert
query
update
remove
getmore
command
代表了该慢日志的种类是什么，是查询、插入、更新、删除还是其他。

system.profile.ns

该项表明该慢日志是哪个库下的哪个集合所对应的慢日志。

system.profile.query

该项详细输出了慢日志的具体语句和行为

system.profile.keysExamined

该项表明为了找出最终结果MongoDB搜索了多少个key

system.profile.docsExamined

该项表明为了找出最终结果MongoDB搜索了多少个文档

system.profile.keyUpdates

该项表名有多少个index key在该操作中被更改，更改索引键也会有少量的性能消耗，因为数据库不单单要删除旧Key，还要插入新的Key到B-Tree索引中

system.profile.writeConflicts

写冲突发生的数量，例如update一个正在被别的update操作的文档

system.profile.numYield

为了让别的操作完成而屈服的次数，一般发生在需要访问的数据尚未被完全读取到内存中，MongoDB会优先完成在内存中的操作

system.profile.locks

在操作中产生的锁，锁的种类有多种，如下：

Global	Represents global lock.
MMAPV1Journal	Represents MMAPv1 storage engine specific lock to synchronize journal writes; for non-MMAPv1 storage engines, the mode forMMAPV1Journal is empty.
Database	Represents database lock.
Collection	Represents database lock.
Metadata	Represents database lock.
oplog	Represents lock on the oplog.

锁的模式也有多种，如下：

Lock Mode	Description
R	Represents Shared (S) lock.
W	Represents Exclusive (X) lock.
r	Represents Intent Shared (IS) lock.
w	Represents Intent Exclusive (IX) lock.

system.profile.locks.acquireCoun

在各种不用的种类下，请求锁的次数

system.profile.nreturned

该操作最终返回文档的数量

system.profile.responseLength

结果返回的大小，单位为bytes，该值如果过大，则需考虑limit()等方式减少输出结果

system.profile.millis

该操作从开始到结束耗时多少，单位为毫秒

system.profile.execStats

包含了一些该操作的统计信息，只有query类型的才会显示

system.profile.execStats.stage

包含了该操作的详细信息，例如是否用到索引

system.profile.ts

该操作执行时的时间

system.profile.client

哪个客户端发起的该操作，并显示出该客户端的ip或hostname

system.profile.allUsers

哪个认证用户执行的该操作

system.profile.user

是否认证用户执行该操作，如认证后使用其他用户操作，该项为空

码农公寓

基础环境

开启profile

单机版

副本集

分片集

测试profile

输出解读

相关文章