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!

Selecionando o que observar

Analisando as informações coletadas

Mais informações? Sem problemas

Conclusão

SQL Plan Management: como aceitar planos não recomendados

Como funciona o Advanced Row Compression?

Publicar comentário Cancelar resposta