Introduction

When there is an issue in a MongoDB instance, the log messages file can provide a lot of information for troubleshooting purposes. That's sounds pretty obvious.

In MongoDB, by default, each statement that takes more than 100ms is written to the log messages file (slowms). Those statements are logged with severity I (for Informational) and usually with msg "Slow query", and that's what I'm are interested in talk about in this article.

Log analysis

Since the version 4.4, all log output is written to the log messages file in json format. This change, makes our job easier, because it's easier parsing each log line and manipulate the data as an object than manipulate the data in text format (it could be truncated, or anything else).

So basically, I wrote an script to read each line of a given log messages file, convert the line (json) in an object, mask any sensible data (the "filter" of a "find", for example), and then group all similar statements by namespace, operation, query patern and execution plan. In this way, we have a summary of "time consuming" statements, and we can focus on those that most impact the performance of the instance.

Let me share a bit more of details about the script. I was interested in these commands: find, getMore, aggregate, count, distinct, insert, update, findandmodify, remove and createIndexes.

For "find", for example, the component ("c") is COMMAND, the "attr.type" is "command", at the "attr.command" there is a "find" key. Inside the "attr.command" we got a lot of information, such as :

• namespace: value of the "att.command.find",
• filter: value of "attr.command.filter". The filter was masked, and named as "query pattern".
• sort: value of "attr.command.sort"
• limit: value of "attr.command.limit"
• execution plan: value of "attr.command.planSummary"
• execution statistics: "attr.command.keysExamined", "attr.command.docsExamined" and "attr.command.nRetuned"
• execution time: "attr.command.durationMillis"

As the "find" statement, we can trace a lot of relevant commands, and develop our own script for specific needs.

It's also interesting to shared that in the log we can get informations about storage (data read and write) and time waiting related with a statement.

Extra

You might know about Ken Chen's scripts, they can be used to guide your development, but all you need is available in the log.

It's also possible to enable the profiler for investigating the slow queries, the data written to the collection "system.profile" has a similar format of the data written to the log messages file, so with a couple of parametrization you can have a single script.

Conclusion

Having a summary of "time consuming" statements is useful for performance analysis.

The real advantage of implementing a periodic check of the log messages file is the possibility of being proactive and taking an action early, preventing major problems later. If you work for a company with thousands of instances, like me, it could be a game changer.

By Danilo Pala, 17/02/2025

Sources:

https://www.mongodb.com/docs/v4.4/reference/log-messages/#json-log-output-format https://www.mongodb.com/docs/manual/reference/log-messages/