京公网安备11010502063487号慢查询日志和 system.profile 是两回事吗?slowms 到底影响什么?把 profiler 开到级别 2 会拖慢多少?这篇逐个验证。
test> db.getProfilingStatus()
{
was: 0,
slowms: 100,
slowinprogms: Long('5000'),
sampleRate: 1,
ok: 1
…(共 7 行)
test> db.system.profile.countDocuments({})
0profile 级别 0,slowms = 100,sampleRate = 1;system.profile 是空的。
阈值 100 ms:跑了 20 次全表扫描后,日志里新增的 "Slow query" 数 = 0
test> db.setProfilingLevel(0, {slowms: 5})
{
was: 0,
slowms: 100,
slowinprogms: Long('5000'),
…(共 7 行)
阈值 5 ms:同样的 20 次之后,新增 "Slow query" = 28 按命令分: {'find': 20, 'getMore': 8}
最后一条 find 的 Slow query 日志的字段: ['appName', 'collectionType', 'command', 'cursorid', 'docsExamined', 'durationMillis', 'hasSortStage', 'inUseTrackedMemBytes', 'isFromPriorityPortConnection', 'isFromUserConnection', 'keysExamined', 'locks', 'nBatches', 'nreturned', 'ns', 'numInterruptChecks', 'numYields', 'opid', 'peakTrackedMemBytes', 'planCacheKey', 'planCacheShapeHash', 'planRanker', 'planSummary', 'planningTimeMicros', 'priorityLowered', 'protocol', 'queryFramework', 'queryHash', 'queryShapeHash', 'queues', 'remote', 'reslen', 'storage', 'type', 'wasMarkedNonDeprioritizable', 'workingMillis']
其中 durationMillis = 15,docsExamined = 50000,planSummary = COLLSCAN,keysExamined = 0,nreturned = 101超过 slowms 的操作写进 mongod 日志(Slow query),profile 级别为 0 时也会写;日志按操作记,find 和 getMore 各一条,字段包括 durationMillis、docsExamined、planSummary。
test> db.setProfilingLevel(1, {slowms: 5})
{ was: 0, slowms: 5, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }
test> db.system.profile.aggregate([{$group: {_id: {op: '$op', ns: '$ns', plan: '$planSummary'}, n: {$sum: 1}, maxMillis: {$max: '$millis'}}}, {$sort: {'_id.op': 1}}]).toArray()
[
{
_id: { op: 'getmore', ns: 'test.t', plan: 'COLLSCAN' },
n: 5,
maxMillis: 8
},
{
_id: { op: 'query', ns: 'test.t', plan: 'COLLSCAN' },
n: 5,
maxMillis: 18
}
]
test> db.system.profile.countDocuments({ns: 'test.small'}) // findOne 很快,级别 1 没记录
0
test> db.setProfilingLevel(2)
{ was: 1, slowms: 5, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }
test> db.small.findOne({_id: 1})
{ _id: 1 }
test> db.system.profile.find({ns: 'test.small'}).sort({ts: -1}).limit(1) // 级别 2 下 findOne 的一条记录
{
op: 'query',
ns: 'test.small',
isFromPriorityPortConnection: false,
command: {
find: 'small',
filter: { _id: 1 },
limit: 1,
lsid: { id: UUID('16a05724-c041-4ce3-8974-b910045ccff0') },
'$db': 'test'
},
opid: 83972,
keysExamined: 1,
docsExamined: 1,
nBatches: 1,
cursorExhausted: true,
numYield: 0,
nreturned: 1,
queryFramework: 'classic',
planRanker: 'none',
locks: { Global: { acquireCount: { r: Long('1') } } },
flowControl: {},
responseLength: 116,
protocol: 'op_msg',
queues: {
ingress: { admissions: 1, totalTimeQueuedMicros: Long('0') },
ingress_request: {},
execution: { admissions: 1, totalTimeQueuedMicros: Long('0') },
writeThrottle: {}
},
millis: 0,
micros: 73,
planSummary: 'EXPRESS_IXSCAN { _id: 1 }',
planningTimeMicros: 31,
execStats: {
isCached: false,
stage: 'EXPRESS_IXSCAN',
keyPattern: { _id: 1 },
indexName: '_id_',
nReturned: 1,
…(共 50 行)
test> Object.keys(<那条记录>).join(', ')
op, ns, isFromPriorityPortConnection, command, opid, keysExamined, docsExamined, nBatches, cursorExhausted, numYield, nreturned, queryFramework, planRanker, locks, flowCo
test> db.setProfilingLevel(0)
{ was: 2, slowms: 5, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }级别 1 把超过 slowms 的操作写进 system.profile,级别 2 写所有操作;每条记录有命令、keysExamined、docsExamined、planSummary、耗时等。
test> db.system.profile.stats().capped, maxSize
true 1048576
test> db.setProfilingLevel(0); db.system.profile.drop(); db.createCollection('system.profile', {capped: true, size: 4 * 1024 * 1024}); db.setProfilingLevel(2); db.system.profile.stats().maxSize
4194304
test> db.setProfilingLevel(0)
{ was: 2, slowms: 5, slowinprogms: Long('5000'), sampleRate: 1, ok: 1 }system.profile 是 1 MB 的 capped 集合;想放大要关 profile、drop、再按大小重建。
级别 0:293 ms;级别 1:295 ms;级别 2:337 ms(级别 2 是级别 0 的 1.15 倍)
级别 2 下一共执行了 (1 次预热 + 5 次) × 3,000 = 18,000 次 findOne
test> db.system.profile.countDocuments({}) // 级别 2 跑完后,system.profile 是 4 MB 的 capped 集合
4280级别 2 让 3,000 次 findOne 从 293 ms 变成 337 ms(1.15 倍),并且旧记录会被覆盖:18,000 次操作后只剩 4,280 条。
test> db.getProfilingStatus()
{
was: 0,
slowms: 0,
slowinprogms: Long('5000'),
sampleRate: 0.1,
ok: 1
…(共 7 行)
slowms = 0、sampleRate = 0.1:1,000 次 findOne 后日志里新增 "Slow query" = 104slowms = 0 加 sampleRate = 0.1,1,000 次操作只记录了 104 条日志。