Analyze mongodb3.x slow query log with filebeat and elasticsearch

Izek Chen
2 min readJun 15, 2021

The log format for MongoDB v.3.x compare with later version are very different. And it is not working with default filebeat pipeline. However, there is a way we can parse it

Default filebeat mongodb pipeline

The grok part below are not working in the old version of mongodb logs

log example:

{ aggregate: "orders", pipeline: [ { $match: { items._profiles.type: "sale", items._profiles.Id: ObjectId('xxxxxxxx'), createdAt: { $gte: new Date(1483203600000), $lt: new Date(1623776399999) } } }, { $unwind: "$items" }, { $unwind: "$items._profiles" }, { $match: { items._profiles.type: "sale", items._profiles.Id: ObjectId('xxxxxxxxxx'), createdAt: { $gte: new Date(1483203600000), $lt: new Date(1623776399999) } } }, { $group: { _id: "$_id", riskScoreByOrder: { $avg: "$_riskScore" } } }, { $group: { _id: 0, avgRiskScore: { $avg: "$riskScoreByOrder" } } } ], allowDiskUse: true, maxTimeMS: 60000, cursor: {}, $readPreference: { mode: "secondaryPreferred" }, $db: "testDB" } planSummary: IXSCAN { items._profiles.Id: 1, items._profiles.type: 1, createdAt: -1 } keysExamined:120572 docsExamined:120518 cursorExhausted:1 numYields:1039 nreturned:1 reslen:283 locks:{ Global: { acquireCount: { r: 2308 }, acquireWaitCount: { r: 1017 }, timeAcquiringMicros: { r: 11453345 } }, Database: { acquireCount: { r: 1154 } }, Collection: { acquireCount: { r: 1154 } } }

pipeline:

GET _ingest/pipeline/filebeat-7.13.2-mongodb-log-pipeline
{
"filebeat-7.13.2-mongodb-log-pipeline" : {
"description" : "Pipeline for parsing MongoDB logs",
"processors" : [
{
"set" : {
"field" : "event.ingested",
"value" : "{{_ingest.timestamp}}"
}
},
{
"grok" : {
"ignore_missing" : true,
"field" : "message",
"patterns" : [
"""%{TIMESTAMP_ISO8601:mongodb.log.timestamp}%{SPACE}%{MONGO3_SEVERITY:log.level}%{SPACE}%{MONGO3_COMPONENT:mongodb.log.component}%{SPACE}(?:\[%{DATA:mongodb.log.context}\])?%{SPACE}%{GREEDYDATA:message}"""
]
}
},
{
"rename" : {
"field" : "@timestamp",
"target_field" : "event.created"
}
},
{
"date" : {
"field" : "mongodb.log.timestamp",
"target_field" : "@timestamp",
"formats" : [
"yyyy-MM-dd'T'HH:mm:ss.SSSZZ"
]
}
},
...
],
"on_failure" : [
{
"set" : {
"field" : "error.message",
"value" : "{{ _ingest.on_failure_message }}"
}
}
]
}
}

Custom pipeline

We can copy the official pipeline and create a custom one with extra grok to easy parsing the data.

Added one grok and one convert to change the time_taken to interger

PUT _ingest/pipeline/mongodb-log-pipeline-custom
{
"description": "Pipeline for parsing MongoDB logs",
"processors": [
{
"set": {
"field": "event.ingested",
"value": "{{_ingest.timestamp}}"
}
},
{
"grok": {
"ignore_missing": true,
"field": "message",
"patterns": [
"""(-|%{WORD:severity}\:\s%{GREEDYDATA:details}\s+)command\s+%{GREEDYDATA:database}\.%{GREEDYDATA:collection}\s+command:\s+%{WORD:command_type}\s+%{GREEDYDATA:mongo_query}\s+protocol:%{GREEDYDATA:protocal}\s%{GREEDYDATA:time_taken}ms""",
"""command\s+%{GREEDYDATA:database}\.%{GREEDYDATA:collection}\s+command:\s+%{WORD:command_type}\s+%{GREEDYDATA:mongo_query}\s+protocol:%{GREEDYDATA:protocal}\s%{GREEDYDATA:time_taken}ms"""
]
}
},
...,
{
"convert": {
"field": "time_taken",
"type": "integer"
}
}
],
"on_failure": [
{
"set": {
"field": "error.message",
"value": "{{ _ingest.on_failure_message }}"
}
}
]
}

Modify filebeat module

add the custom pipeline to the mongodb module

- module: mongodb
# All logs
log:
enabled: true
var.paths: ["/var/log/mongodb/mongod.log"]
input:
pipeline: mongodb-log-pipeline-custom

Grafana + Elasticsearch graph

At the end, you can use the graph to quickly find out the slow query and monitor the trend

MongoDB Slow query determination

TBC

--

--