Find The Hot Spot Operation Using Profiling Method On MongoDB
Tags: mongodb, parallelprogramming, monitoring, optimization
Published: 2018-04-14 00:49:22

---
title: Find The Hot Spot Operation Using Profiling Method On MongoDB
published: true
description: Find The Hot Spot Operation Using Profiling Method On MongoDB
tags: MongoDB, parallel-programming, monitoring, optimization
---

## Introduction
Hi, my name Hafidz. I am just regular software developer like almost of you. Currently, I have enrolled [MongoDB for Developers](https://university.mongodb.com/courses/M101P/about) 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](https://www.amazon.com/Parallel-Programming-Techniques-Applications-Workstations/dp/0131405632). 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](https://en.wikipedia.org/wiki/Gustafson%27s_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](https://docs.mongodb.com/manual/tutorial/manage-the-database-profiler/). 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](https://docs.mongodb.com/manual/reference/database-profiler/). 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
```
<br><br>
* Or alternatively, you can activate profiling in specific database by execute this command:

```
db.setProfilingLevel(1, { slowms: 100 })
```
<br><br>
* Do some operations on the database. MongoDB will create a collection called `system.profile` which contains operations profile data.
<br><br>
* Get top five slowest operations

```
db.system.profile.find().sort({millis: -1}).limit(10).pretty()
```
<br><br>
* 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](https://dev.to/bladefidz/how-to-evaluate-query-performance-on-mongodb-4dbm) would be helpful.


## Suggestion
Profiling may became easier if we can plot the profiling output into histogram. You may interested [this tool](https://late.am/post/2011/09/22/professor-a-mongodb-profile-viewer.html) or find your own way to plot the profiling output into histogram.