Como encontrar Slow Queries no MongoDB
Seja qual for o SGBD com o qual trabalhemos, sabemos que ter queries com uma performance ruim (as slow queries) pode prejudicar e muito o ambiente como um todo. Essas queries agem como sanguessugas de recursos dos nosso servidores, drenando o que há de mais valioso neles: recursos computacionais, como CPU, memória e I/O. Como administradores destes ambientes, temos o dever de identificar essas queries e melhorar sua performance.
No Mongo não é diferente, e por se tratar de um banco NoSQL, onde a velocidade é um ponto chave, a diferença de míseros milissegundos no retorno de uma query pode gerar um grande impacto na ponta do processo.
Importante: neste post estou usando a versão 7.0.16 do Mongo.
Selecionando o que observar
Para identificar as slow queries ofensoras utilizamos o Database Profiler. Essa funcionalidade coleta dados de comandos executados contra o banco de dados e os escreve na collection system.profile que existe dentro de cada database da instância do Mongo. A informação de slow queries também é exibida no log da instância do Mongo.
Por padrão, o profiler fica desabilitado. Podemos verificar seu status com o comando db.getProfilingStatus(), enquanto conectado a um database. No meu caso vou conectar ao database spotify que tenho na minha instância e verificar o status do profiler:
rsMongoServer [direct: primary] admin> use spotify
switched to db spotify
rsMongoServer [direct: primary] spotify> db.getProfilingStatus()
{
was: 0,
slowms: 100,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742344574, i: 1 }),
signature: {
hash: Binary.createFromBase64('nUhvCv9TXd6uCxLZ1dEGCTKUXlI=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742344574, i: 1 })
}
No documento retornado, o campo “was” mostra o nível do profiler. Existem três níveis para o profiler:
- 0 (zero): o profiler não coleta nenhum dado. Este é o default;
- 1: o profiler coleta dados de operações que levam mais tempo que o valor do campo “slowms” ou que satisfaçam um filtro configurado no profiler;
- 2: o profiler coleta dados para todas as operações;
É importante ter em mente que um overhead na performance é adicionado a cada nível que subimos, uma vez que o banco precisa fazer um trabalho extra, logando as informações para cada nível habilitado.
Para alterar o nível do profiler, usamos o comando db.setProfilingLevel() passando o nível desejado por parâmetro, e opcionalmente parâmetros para controlar o que será logado:
rsMongoServer [direct: primary] spotify> db.setProfilingLevel(1)
{
was: 0,
slowms: 100,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358087, i: 1 }),
signature: {
hash: Binary.createFromBase64('OpoKZ46LUU9AvsuHfX5mUV+bASg=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358087, i: 1 })
Nesse caso o documento retornado mostra o nível do profile anterior no campo “was”. Podemos ver o nível 1 habilitado com o comando db.getProfilingStatus():
{
was: 1,
slowms: 100,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358097, i: 1 }),
signature: {
hash: Binary.createFromBase64('pFqKwmFyXskiuIKR9JKjs7ICstQ=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358097, i: 1 })
}
Por padrão, o valor do campo “slowms” é de 100ms, mas podemos alterá-lo passando o valor como parâmetro:
rsMongoServer [direct: primary] spotify> db.setProfilingLevel(1, {"slowms" : 200})
{
was: 1,
slowms: 100,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358277, i: 1 }),
signature: {
hash: Binary.createFromBase64('zwvuHbWmzYbuIMZaKRDaBhQAQqM=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358277, i: 1 })
}
rsMongoServer [direct: primary] spotify> db.getProfilingStatus()
{
was: 1,
slowms: 200,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358277, i: 1 }),
signature: {
hash: Binary.createFromBase64('zwvuHbWmzYbuIMZaKRDaBhQAQqM=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358277, i: 1 })
}
Uma estratégia interessante é iniciar com um valor de “slowms” mais alto e o diminuir de acordo com a necessidade, pois dessa forma o banco reduz o volume de operações logadas.
Outra forma de diminuir o que está sendo logado é através do parâmetro “sampleRate“, onde definimos a fração de operações lentas que desejamos logar. Por exemplo, caso desejássemos logar apenas 40% das operações lentas, usaríamos:
rsMongoServer [direct: primary] spotify> db.setProfilingLevel(1, {"sampleRate" : 0.40})
{
was: 1,
slowms: 200,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358617, i: 1 }),
signature: {
hash: Binary.createFromBase64('SM49mleSUVNE+H4/VyaP3eTr52g=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358617, i: 1 })
}
rsMongoServer [direct: primary] spotify> db.getProfilingStatus()
{
was: 1,
slowms: 200,
sampleRate: 0.4,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358627, i: 1 }),
signature: {
hash: Binary.createFromBase64('5Ueyk4Plc+VQw7VvN/8NUQIaugg=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358627, i: 1 })
}
Por fim, a última forma de controlar o que será logado, é através da implementação de um filtro. Em um cenário onde desejamos logar apenas queries que levem mais de 1 segundo para executarem, usaríamos:
rsMongoServer [direct: primary] spotify> db.setProfilingLevel( 1, { filter: { op: "query", millis: { $gt: 1000 } } } )
{
was: 1,
slowms: 200,
sampleRate: 0.4,
note: 'When a filter expression is set, slowms and sampleRate are not used for profiling and slow-query log lines.',
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358777, i: 1 }),
signature: {
hash: Binary.createFromBase64('1+HTMCeBluqsGLiXJVCd9geAdPw=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358777, i: 1 })
}
rsMongoServer [direct: primary] spotify> db.getProfilingStatus()
{
was: 1,
slowms: 200,
sampleRate: 0.4,
filter: {
'$and': [ { op: { '$eq': 'query' } }, { millis: { '$gt': 1000 } } ]
},
note: 'When a filter expression is set, slowms and sampleRate are not used for profiling and slow-query log lines.',
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358777, i: 1 }),
signature: {
hash: Binary.createFromBase64('1+HTMCeBluqsGLiXJVCd9geAdPw=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358777, i: 1 })
}
Como a própria nota reportada no retorno do comando db.getProfilingStatus() cita, quando usamos um filtro, o Mongo desconsidera os valores configurados para “slowms” e “sampleRate“. Para desativar o filtro usamos o valor “unset“:
rsMongoServer [direct: primary] spotify> db.setProfilingLevel( 1, { filter: "unset" } )
{
was: 1,
slowms: 200,
sampleRate: 0.4,
filter: {
'$and': [ { op: { '$eq': 'query' } }, { millis: { '$gt': 1000 } } ]
},
note: 'When a filter expression is set, slowms and sampleRate are not used for profiling and slow-query log lines.',
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358897, i: 1 }),
signature: {
hash: Binary.createFromBase64('MCkZmHmKMpWKOYHjKlCtHUZ3htE=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358897, i: 1 })
}
rsMongoServer [direct: primary] spotify> db.getProfilingStatus()
{
was: 1,
slowms: 200,
sampleRate: 0.4,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742358897, i: 1 }),
signature: {
hash: Binary.createFromBase64('MCkZmHmKMpWKOYHjKlCtHUZ3htE=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742358897, i: 1 })
}
Para os testes, vou manter os valores padrão para “slowms” e “sampleRate“:
rsMongoServer [direct: primary] spotify> db.setProfilingLevel(1, {"slowms" : 100,"sampleRate" : 1})
{
was: 1,
slowms: 200,
sampleRate: 0.4,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742359037, i: 1 }),
signature: {
hash: Binary.createFromBase64('GXtp9wkoun0AmgVJ0tSKf/fLkLY=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742359037, i: 1 })
}
Analisando as informações coletadas
Para fins de teste, vou realizar uma consulta dentro da collection playlists, filtrando por um campo sem índice, para que a operação seja logada pelo profiler. Na sequência desabilitamos o profiler:
rsMongoServer [direct: primary] spotify> db.playlists.find({num_tracks : 75},{name:1, num_tracks:1,_id:0})
[
{ name: 'Classical', num_tracks: 75 },
{ name: 'Running', num_tracks: 75 },
{ name: 'Chillll', num_tracks: 75 },
{ name: 'Meow', num_tracks: 75 },
{ name: 'Running', num_tracks: 75 },
{ name: 'Sleepy', num_tracks: 75 },
{ name: 'Chill', num_tracks: 75 },
{ name: 'Summer drives', num_tracks: 75 },
{ name: "John's Playlist", num_tracks: 75 },
{ name: 'Run It', num_tracks: 75 },
{ name: 'disney channel', num_tracks: 75 },
{ name: 'summerrr', num_tracks: 75 },
{ name: '😍😍😍', num_tracks: 75 },
{ name: 'Car Beats', num_tracks: 75 },
{ name: 'Volleyball', num_tracks: 75 },
{ name: 'Oldies', num_tracks: 75 },
{ name: '/chill', num_tracks: 75 },
{ name: 'RAP', num_tracks: 75 },
{ name: 'Study Playlist', num_tracks: 75 },
{ name: 'September 2016', num_tracks: 75 }
]
Type "it" for more
rsMongoServer [direct: primary] spotify> db.setProfilingLevel(0)
{
was: 1,
slowms: 100,
sampleRate: 1,
ok: 1,
'$clusterTime': {
clusterTime: Timestamp({ t: 1742360837, i: 1 }),
signature: {
hash: Binary.createFromBase64('d75/HdAzTwdxSvHPzbJatFImoYo=', 0),
keyId: Long('7417017111232380934')
}
},
operationTime: Timestamp({ t: 1742360837, i: 1 })
}
Verificando o último registro do log que contém a expressão “Slow”, temos o seguinte retorno:
$ cat /var/log/mongodb/mongod.log | grep "Slow" | tail -n 1
{"t":{"$date":"2025-03-19T04:45:58.834+00:00"},"s":"I", "c":"COMMAND", "id":51803, "ctx":"conn43","msg":"Slow query",
"attr":{"type":"command","ns":"spotify.playlists","appName":"mongosh 2.3.1","command":{"find":"playlists",
"filter":{"num_tracks":75},"projection":{"name":1,"num_tracks":1,"_id":0},"lsid":{"id":{"$uuid":
"0f5d5b70-ef56-4f63-96ef-55449af4e1cb"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1742359547,"i":1}},"signature":
{"hash":{"$binary":{"base64":"/IxouAZJuMlh2TDghDaul03Pu0g=","subType":"0"}},"keyId":7417017111232380934}},"$readPreference"
:{"mode":"primaryPreferred"},"$db":"spotify"},"planSummary":"COLLSCAN","planningTimeMicros":99,"cursorid":
6680968565243767053,"keysExamined":0,"docsExamined":18079,"nBatches":1,"numYields":45,"nreturned":101,"queryHash":
"4F5B942E","planCacheKey":"4F5B942E","queryFramework":"classic","reslen":4748,"locks":{"FeatureCompatibilityVersion":
{"acquireCount":{"r":46}},"Global":{"acquireCount":{"r":46}}},"readConcern":{"level":"local","provenance":"implicitDefault"},"storage":"data":"bytesRead":355737612,"timeReadingMicros":490735}},"cpuNanos":380919276,"remote":"127.0.0.1:48324","protocol":"op_msg","durationMillis":778}}
Se este é o primeiro trecho de log do Mongo que você está tendo contato, eu entendo o seu sentimento (que bagunça é essa?). O Mongo organiza o seu de uma forma com que cada registro dele seja um documento. Vamos analisar aqui alguns campos específicos:
- “t“: timestamp da mensagem;
- “s“: severidade, neste caso “I” de “Informational“;
- “c“: componente, neste caso “COMMAND” remete a um comando executado contra o banco;
- “msg“: mensagem gerada pelo server;
- “attr“: atributos com informações adicionais.
É no campo “attr” que podemos ver qual query foi executada, olhando para o atributo “command“:
"command":{"find":"playlists","filter":{"num_tracks":75},"projection":{"name":1,"num_tracks":1,"_id":0},"lsid":{"id":{"$uuid":"0f5d5b70-ef56-4f63-96ef-55449af4e1cb"}},"$clusterTime":{"clusterTime":{"$timestamp":{"t":1742359547,"i":1}},"signature":{"hash":{"$binary":{"base64":"/IxouAZJuMlh2TDghDaul03Pu0g=","subType":"0"}},"keyId":7417017111232380934}},"$readPreference":{"mode":"primaryPreferred"},"$db":"spotify"}
- “find”:”playlists”: comando find, na collection playlists;
- “filter”:{“num_tracks”:75}: filtro de documentos com o campo num_tracks = 75;
- “projection”:{“name”:1,”num_tracks”:1,”_id”:0}: projeção, lista de campos retornados (1) e omitidos (0);
- “$db”:”spotify”: database onde o comando foi executado;
Logo após o atributo “command“, podemos ver o “planSummary” mostrando um COLLSCAN, que significa que o banco está fazendo um scan em todos os documentos de uma collection (da mesma forma que um FULL TABLE SCAN ocorre em um banco relacional), indicando o problema de performance.
Mais informações? Sem problemas
Caso as informações do log não sejam suficientes para análise, podemos consultar a collection system.profile dentro do database no qual a query foi logada (requer a role de dbAdmin no database). Vamos ver a estrutura do documento retornado, com o commando findOne():
rsMongoServer [direct: primary] spotify> db.system.profile.findOne()
{
op: 'query',
ns: 'spotify.playlists',
command: {
find: 'playlists',
filter: { num_tracks: 75 },
projection: { name: 1, num_tracks: 1, _id: 0 },
lsid: { id: UUID('8f620c8f-f493-4b2b-95fc-14ad3f535367') },
'$clusterTime': {
clusterTime: Timestamp({ t: 1742344654, i: 1 }),
signature: {
hash: Binary.createFromBase64('DXysXWuc0a+sonFyjpNF0xTejWk=', 0),
keyId: Long('7417017111232380934')
}
},
'$readPreference': { mode: 'primaryPreferred' },
'$db': 'spotify'
},
cursorid: Long('9013903626341513349'),
keysExamined: 0,
docsExamined: 18079,
nBatches: 1,
numYield: 26,
nreturned: 101,
queryHash: '4F5B942E',
planCacheKey: '4F5B942E',
queryFramework: 'classic',
locks: {
FeatureCompatibilityVersion: { acquireCount: { r: Long('28') } },
Global: { acquireCount: { r: Long('28') } }
},
flowControl: {},
readConcern: { level: 'local', provenance: 'implicitDefault' },
storage: {
data: { bytesRead: Long('89659414'), timeReadingMicros: Long('138362') }
},
responseLength: 4748,
protocol: 'op_msg',
cpuNanos: 106646554,
millis: 218,
planSummary: 'COLLSCAN',
planningTimeMicros: 98,
execStats: {
stage: 'PROJECTION_SIMPLE',
nReturned: 101,
executionTimeMillisEstimate: 207,
works: 18079,
advanced: 101,
needTime: 17978,
needYield: 0,
saveState: 27,
restoreState: 26,
isEOF: 0,
transformBy: {},
inputStage: {
stage: 'COLLSCAN',
filter: { num_tracks: { '$eq': 75 } },
nReturned: 101,
executionTimeMillisEstimate: 207,
works: 18079,
advanced: 101,
needTime: 17978,
needYield: 0,
saveState: 27,
restoreState: 26,
isEOF: 0,
direction: 'forward',
docsExamined: 18079
}
},
ts: ISODate('2025-03-19T00:37:44.686Z'),
client: '127.0.0.1',
appName: 'mongosh 2.3.1',
allUsers: [ { user: 'admin', db: 'admin' } ],
user: 'admin@admin'
}
Conhecendo essa estrutura agora conseguimos montar queries buscando por campos específicos. Digamos que eu queira analisar o usuário e o comando executado para queries mais lentas que 200ms. Eu usaria:
rsMongoServer [direct: primary] spotify> db.system.profile.find({millis: {$gt:200}},{ user: 1, command: 1})
[
{
command: {
find: 'playlists',
filter: { num_tracks: 75 },
projection: { name: 1, num_tracks: 1, _id: 0 },
lsid: { id: UUID('8f620c8f-f493-4b2b-95fc-14ad3f535367') },
'$clusterTime': {
clusterTime: Timestamp({ t: 1742344654, i: 1 }),
signature: {
hash: Binary.createFromBase64('DXysXWuc0a+sonFyjpNF0xTejWk=', 0),
keyId: Long('7417017111232380934')
}
},
'$readPreference': { mode: 'primaryPreferred' },
'$db': 'spotify'
},
user: 'admin@admin'
},
{
command: {
find: 'playlists',
filter: { num_tracks: 75 },
projection: { name: 1, num_tracks: 1, _id: 0 },
lsid: { id: UUID('0f5d5b70-ef56-4f63-96ef-55449af4e1cb') },
'$clusterTime': {
clusterTime: Timestamp({ t: 1742359547, i: 1 }),
signature: {
hash: Binary.createFromBase64('/IxouAZJuMlh2TDghDaul03Pu0g=', 0),
keyId: Long('7417017111232380934')
}
},
'$readPreference': { mode: 'primaryPreferred' },
'$db': 'spotify'
},
user: 'admin@admin'
}
]
Conclusão
O profiler é uma ótima ferramenta para utilizar quando notamos um aumento de recursos no banco, pois geralmente esse aumento é ocasionado por alguma slow query rodando no ambiente. Quanto antes a identificarmos mais rápida será a tratativa.
Como leitura complementar a este artigo sugiro:
Grande abraço a todos!
1 comentário