Find The Hot Spot Operation Using Profiling Method On MongoDB

Introduction

Hi, my name Hafidz. I am just regular software developer like almost of you. Currently, I have enrolled MongoDB for Developers course from MongoDB university. This course is great and has awesome instructors. While attending the course, I find myself enjoy reading a book Parallel Programming by Barry Wilkinson and Michael Allen. By reading this book, I found more insight about how to evaluate operation performance on MongoDB.

Here, I like to share what I have already learn from the course and book. It is about how we find The Hot Spot Operation Using Profiling Method On MongoDB.

Motivation

Gustafson's law tells us that latency can be used to measure implemented parallel program. Lower the latency we gain, better performance we have. But, find the way to reduce the latency rate is somehow difficult if we have many possible tasks to be executed. One easy way to do that is by optimizing most executed operations. Such operation called as hot spot.

Database Profiler on MongoDB

You can find detailed explanation about Database Profiler from this documentation. To simplify, we only need to focused on these key points:

1. Profiling levels

   • 0: Off.
   • 1: On, but selective to given threshold in milliseconds.
   • 2: On and dumb all execution operations.

2. Get profiler output
   Run this command db.system.profile.find() to get profiled data. You can found the detailed explanation of profiling output in this documentation. In order to make this tutorial straight forward, we only focused on some key output:

   • op: Executed operation.
   • ns: Namespace of the operation.
   • responseLength: Document length in bytes resulted from corresponding operation.
   • millis: Time in milliseconds needed by operations to complete the requested documents. Some people called this as latency speed.

Profiling to Find Hot Spot Operations

Suppose we already have some collections and want to do some performance testing. We want to inspect application behavior to find which most executed operations, then save them in the Hot Spot pool and find the best way to optimize them.

Okay, let get started:

• Start mongod with profiling option on but be selective to only dump any operations that exceed 100 milliseconds threshold.

mongod --dbpath /usr/local/share/mongodb --port 27001 --profile 1 --slowms 100

• Or alternatively, you can activate profiling in specific database by execute this command:

db.setProfilingLevel(1, { slowms: 100 })

• Do some operations on the database. MongoDB will create a collection called system.profile which contains operations profile data.
• Get top five slowest operations

db.system.profile.find().sort({millis: -1}).limit(10).pretty()

• Suppose we just execute some query on school2.students collection. So, in the profiling log we got output something like this:

{
    ...
    "op" : "query",
    "ns" : "school2.students",
    ...
    "millis" : 15820
},
{
    ...
    "op" : "query",
    "ns" : "school2.students",
    ...
    "millis" : 12560
},
{
    ...
    "op" : "query",
    "ns" : "school2.students",
    ...
    "millis" : 11084
},
{
    ...
    "op" : "query",
    "ns" : "school2.students",
    ...
    "millis" : 9493
},
{
    ...
    "op" : "query",
    "ns" : "school2.students",
    ...
    "millis" : 9059
}

Conclusion

It's look like that query operation on school2.student2 collection is the Hot Spot operations executed within about one seconds. We may used explain(executionStats) to the Hot Spot operation in order to analyze execution statistics of the operation. You may find this article would be helpful.

Suggestion

Profiling may became easier if we can plot the profiling output into histogram. You may interested this tool or find your own way to plot the profiling output into histogram.