MongoDB慢查询日志之Profiling配置

一、慢日志Profiling功能介绍

1.1 Profiling是什么？

官网介绍：https://www.mongodb.com/docs/v4.2/tutorial/manage-the-database-profiler/index.html

MongoDB Profiling可以收集运行中的数据库执行命令的详细信息。其中包含，CRUD操作以及配置和管理命令等。分析器会将收集的所有数据写入一个system.profile集合中。Profiling默认是关闭的，可以根据业务需求去设置Profiling级别。当然启用后，分析过程会对数据库性能和磁盘IO产生一定影响。不建议业务高峰期开启或长期开启。

1.2 Profiling级别有哪些？

注：上述即为官网对Profiling级别的描述。0是Profiling默认级别，即关闭Profiling功能，不进行任何数据收集；1代表收集操作时长超过慢日志阀值（slowms的值）的所有数据；2代表收集所有操作数据。（2非常消耗性能，不建议设置）

二、Profiling配置方法

2.1 配置文件修改Profiling参数

systemLog :
    destination : file
    logAppend : true
    path : /opt/udb/instance/mongodb-3.6/xxxxxxxx/log/mongodb.log  # 日志记录，含慢日志
operationProfiling:
   slowOpThresholdMs: 100                                          # 查询超过100ms即认为是慢查询
   mode: slowOp

2.2 命令设置Profiling参数

（1）查询Profiling参数

#（1）查看Profiling默认参数设置
udb-4qg23pzn:PRIMARY> db.getProfilingStatus()
{
	"was" : 0,                                    # 级别0
	"slowms" : 100,                               # 查询超过100ms记录为慢查询
	"sampleRate" : 1,
	"operationTime" : Timestamp(1653719217, 2),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1653719217, 2),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	}
}

#（2）查询Profiling当前级别
udb-4qg23pzn:PRIMARY> db.getProfilingLevel()
0

（2）修改Profiling参数

#（1）设置Profiling级别为1
udb-4qg23pzn:PRIMARY> db.setProfilingLevel(1)
{
	"was" : 0,
	"slowms" : 100,
	"sampleRate" : 1,
	"ok" : 1,
	"operationTime" : Timestamp(1653719517, 2),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1653719517, 2),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	}
}

#（2）设置级别1及慢查询时间0ms
udb-4qg23pzn:PRIMARY> db.setProfilingLevel(1,0)
{
	"was" : 1,
	"slowms" : 100,
	"sampleRate" : 1,
	"ok" : 1,
	"operationTime" : Timestamp(1653719617, 1),
	"$clusterTime" : {
		"clusterTime" : Timestamp(1653719617, 1),
		"signature" : {
			"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
			"keyId" : NumberLong(0)
		}
	}
}

注：为了方便观察现象，我这里把慢查询设置为0ms，即任何一个查询操作都会被记录成慢查询！！！！

（3）效果验证

# 执行一条查询
udb-4qg23pzn:PRIMARY> use admin
udb-4qg23pzn:PRIMARY> db.system.users.find()

# 查看慢日志记录
udb-4qg23pzn:PRIMARY> db.system.profile.find().pretty().limit(1)
{
	"op" : "query",                    # 操作类型有insert、query、update、remove、getmore、command
	"ns" : "admin.system.users",       # 操作集合
	"command" : {
		"find" : "system.users",
		"filter" : {
			
		},
		"lsid" : {
			"id" : UUID("781d4c24-98ed-4f56-a8e7-095c295d70e9")
		},
		"$clusterTime" : {
			"clusterTime" : Timestamp(1653720747, 1),
			"signature" : {
				"hash" : BinData(0,"AAAAAAAAAAAAAAAAAAAAAAAAAAA="),
				"keyId" : NumberLong(0)
			}
		},
		"$db" : "admin"
	},
	"keysExamined" : 0,
	"docsExamined" : 3,
	"cursorExhausted" : true,
	"numYield" : 0,
	"locks" : {
		"Global" : {
			"acquireCount" : {
				"r" : NumberLong(2)
			}
		},
		"Database" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		},
		"Collection" : {
			"acquireCount" : {
				"r" : NumberLong(1)
			}
		}
	},
	"nreturned" : 3,                            # 返回的记录数
	"responseLength" : 1139,    
	"protocol" : "op_msg",
	"millis" : 0,                               # 查询耗时
	"planSummary" : "COLLSCAN",
	"execStats" : {
		"stage" : "COLLSCAN",
		"nReturned" : 3,
		"executionTimeMillisEstimate" : 0,
		"works" : 5,
		"advanced" : 3,
		"needTime" : 1,
		"needYield" : 0,
		"saveState" : 0,
		"restoreState" : 0,
		"isEOF" : 1,
		"invalidates" : 0,
		"direction" : "forward",
		"docsExamined" : 3
	},
	"ts" : ISODate("2022-05-28T06:52:44.876Z"),   # 查询发生时间
	"client" : "10.25.135.106",
	"appName" : "MongoDB Shell",
	"allUsers" : [
		{
			"user" : "root",
			"db" : "admin"
		}
	],
	"user" : "root@admin"
}

2.3 常见其它操作命令

#（1）查询最近的1条慢查询记录
db.system.profile.find().limit(1).sort({ ts : -1 }).pretty()

#（2）查询特定集合的慢查询记录
db.system.profile.find( { ns : 'admin.system.users' } ).pretty()

#（3）查询大于200ms的慢查询记录
db.system.profile.find( { millis : { $gt : 200 } } ).pretty()

#（4）查询当前数据库的时间
new Date()
ISODate("2022-05-28T07:11:51.042Z")

#（5）查询某个时间范围内的慢查询记录
db.system.profile.find({
  ts : {
    $gt : new ISODate("2022-05-28T06:52:00Z") ,
    $lt : new ISODate("2022-05-28T06:53:00Z")
  }}).pretty()
  
#（6）查询指定时间内，某个user的慢查询信息，并按照耗时排序
db.system.profile.find({
  ts : {
    $gt : new ISODate("2022-05-28T06:52:00Z") ,
    $lt : new ISODate("2022-05-28T06:53:00Z")
  }},
   { user : 0 }
  ).sort( { millis : -1 } )

注：即使不开启Profiling参数，即Profiling设置为0，MongoDB照样会按照slowms的值大小，记录慢日志到错误日志文件中，即mongodb.log。所有建议可以短期开启Profiling参数用于分析和定位数据库异常，不建议长期开启，否则会严重拖慢数据库性能，并且占用额外磁盘空间。