‍

‍

MongoDB 8.0 brings significant improvements in performance analysis, especially when it comes to logging slow operations. One key enhancement is the ability to log slow queries based on “working time” — the actual time MongoDB spends processing a query — instead of the total end-to-end latency. This means that factors like lock waits, flow control pauses, or ticket queuing time no longer skew which queries are flagged as slow.

In this blog post, we will explore the key differences between "working time" and "duration" in MongoDB 8.0, how to use the new workingMillis and durationMillis metrics to identify genuine slow queries versus queued operations, and the new log message fields, such as queues.execution.totalTimeQueuedMicros, that provide deeper insights into system performance.

Understanding Working Time vs. Total Duration

In previous versions of MongoDB, slow queries were flagged based on total duration, which included time spent waiting on locks and flow control. While this was helpful, it often meant that some queries appeared “slow” despite having minimal execution time. MongoDB 8.0 improves upon this by introducing two new metrics:

• workingMillis – The time MongoDB actually spends processing the query.
• durationMillis – The total end-to-end latency, which includes waiting for locks, flow control, or queued execution slots.

With slow operation logging now focused on workingMillis by default, MongoDB 8.0 offers a more precise view of query performance. This shift helps identify truly inefficient queries, rather than those delayed due to factors outside of the query itself.

Importance of This Change

Improved Performance Diagnosis

When a query is flagged as “slow” due to a high workingMillis, it’s a clear indication that the query is CPU- or I/O-intensive. In previous MongoDB versions, you might have spent time optimizing queries that were marked as slow due to factors like lock or flow control waits, rather than the query’s actual execution time.

New Insights into Queued Time

With MongoDB 8.0, the addition of queues.execution.totalTimeQueuedMicros provides valuable insights into how long a query spent waiting before execution. If you see a high durationMillis but a low workingMillis, this suggests that the bottleneck may lie in lock contention or ticket availability, rather than the query logic itself.

Unified Reporting Across Tools

Tools like the Query Profiler, Performance Advisor, and Search Query Telemetry will now consistently use workingMillis as the primary metric for identifying slow queries. This creates a more unified and accurate approach to diagnosing performance issues, ensuring that you’re addressing the right problems with the right solutions.

What New Logs Look Like

With MongoDB 8.0, the logging format for slow operations has been updated to include a detailed JSON structure, which provides valuable insights into query performance. An example of such a log entry might look like this:

{
    "t": {
        "$date": "2024-12-22T16:45:16.123Z"
    },
    "s": "I",
    "c": "COMMAND",
    "id": 22428,
    "ctx": "conn123",
    "msg": "Slow query",
    "attr": {
        "type": "command",
        "ns": "myDatabase.myCollection",
        "appName": "MongoDB Shell",
        "command": {
            "find": "myCollection",
            "filter": { "status": "active" },
            "limit": 100,
            "batchSize": 1000,
            "$db": "myDatabase"
        },
        "numYields": 1,
        "planSummary": "COLLSCAN",
        "keysExamined": 0,
        "docsExamined": 100000,
        "workingMillis": 120,
        "durationMillis": 300,
        "queues": {
            "execution": {
                "totalTimeQueuedMicros": 180000
            }
        }
    }
}

Key Metrics:

• workingMillis: This indicates the actual execution time of the query, which in this example is 120 ms.
• durationMillis: This measures the total lifecycle of the query, including time spent waiting for resources like locks or flow control, with a value of 300 ms in this case.
• queues.execution.totalTimeQueuedMicros: This reveals the time the query spent waiting for an available execution slot, in this case, 180,000 microseconds (or 180 ms).

With these new metrics, you can easily differentiate between queries that are truly slow due to their execution time (high workingMillis) and those that are just delayed due to being stuck in a queue (high queues.execution.totalTimeQueuedMicros).

Practical Diagnosis of Slow Queries

Now, let’s explore how you can leverage the new log data to diagnose and act on slow queries:

High workingMillis, Low totalTimeQueuedMicros

• Diagnosis: The query is expensive in terms of actual execution time.
• Action: Focus on optimizing the query itself by considering indexing improvements, refining query patterns, or reworking the schema.

Low workingMillis, High totalTimeQueuedMicros

• Diagnosis: The query executes quickly but is delayed due to waiting for resources (e.g., lock or flow control).
• Action: Improve concurrency by tweaking settings like increasing ticket counts or considering horizontal scaling to better handle query load.

High workingMillis and High totalTimeQueuedMicros

• Diagnosis: The query is both expensive and frequently delayed due to being stuck in the queue.
• Action: Prioritize query optimization. If the query remains queued, explore resource allocation and concurrency configurations to ensure smoother execution.

Workflow Improvements with MongoDB 8.0

‍More Accurate Alerts

‍By focusing on workingMillis, your alerting system will no longer flood you with notifications for brief lock contention. Instead, you'll get alerts only for queries that genuinely strain your CPU or disk, enabling you to prioritize performance issues.

‍Smarter Scaling Decisions

‍If you consistently notice high values in queues.execution.totalTimeQueuedMicros, it could indicate that your cluster is hitting concurrency limits. This insight allows you to make smarter scaling decisions, such as increasing hardware capacity, adjusting connection pool sizes, or adding execution tickets to reduce queuing delays.

‍Holistic Query Tuning

‍With the additional fields like planSummary, keysExamined, and docsExamined, you gain a comprehensive view of your queries. This helps you assess how well your queries are utilizing indexes and how many documents they need to scan. By combining this data with workingMillis, you can quickly identify inefficiencies and optimize your queries.

Best Practices for Implementation

Start with Reasonable Thresholds

‍Set the workingMillis threshold according to your real-time SLAs. While thresholds around 100 ms or 200 ms are common in production environments, make sure to adjust them based on the specific demands of your workload.

Monitor Both Working and Duration

‍Tracking both workingMillis and durationMillis ensures you capture all performance bottlenecks. If lock contention is a recurring issue, the durationMillis will highlight it, allowing you to take corrective action.

Review Logs Regularly

‍Use log management tools or MongoDB’s built-in Performance Advisor and Query Profiler to analyze log patterns over time. Look out for frequent spikes in workingMillis or queues.execution, as these indicate potential performance issues that require deeper investigation.

Scale or Optimize?

1. High workingMillis + High CPU usage = Likely query or index optimization is needed.
2. Low workingMillis + High queue times = Potential need to scale out or adjust concurrency settings.

MongoDB 8.0’s focus on workingMillis marks a significant shift in how we identify and optimize slow operations. By focusing on actual query execution time and providing insights into queue waits, this release offers clearer, more actionable performance data than ever before.

With these improvements, you can now more easily distinguish between genuinely slow queries and those delayed in the queue, align alerting and profiling thresholds with real CPU/IO usage, and fine-tune concurrency settings or scale your cluster with greater precision. The result is less time spent chasing false positives in slow logs and more time optimizing the queries and resources that truly impact your application’s performance.

The new performance insights provided by MongoDB 8.0 are game-changing, but making the most of these enhancements requires expertise. Whether you’re struggling with slow queries, managing concurrency, or optimizing your MongoDB infrastructure, Mydbops offers MongoDB Managed and Consulting Services to help you achieve optimal performance.

Reach out today to learn how Mydbops can support your MongoDB performance needs with tailored solutions that drive results.