Forem: Hafidz Jazuli Luthfi

Find The Hot Spot Operation Using Profiling Method On MongoDB

Hafidz Jazuli Luthfi — Sat, 14 Apr 2018 00:49:22 +0000

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:

Profiling levels
- 0: Off.
- 1: On, but selective to given threshold in milliseconds.
- 2: On and dumb all execution operations.
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.

MongoDB Query Optimization: Covered Query

Hafidz Jazuli Luthfi — Thu, 12 Apr 2018 13:31:04 +0000

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. I like to share what I have already learn from this course. It is about how we optimize MongoDB query by implementing covered query.

This post has correlation with my previous post: How to Evaluate Query Performance on MongoDB. If you want to know more about how to evaluate query performance, than it is good idea to read it before read this post.

Motivation

If we are not used any indexes on the collection, then MongoDB will performs COLLSCAN. It's means, if we have N collections, than MongoDB will perform scanning in N times. Your friend who have computer science degree may said to you, "We can do better!". Yes, we can do better by implementing indexing algorithm. MongoDB has been provides lower bound data structure called B+ trees which gives us Log N performance. If you want to know more about the indexing algorithm, then try to read this documentation.

But, the question is: How we can exploit the indexing algorithm to achieve high performance query?

Query Optimization using Covered Query

MongoDB has excellent documentation about how to optimizing query. In the case to optimize such query operations that are part of such index or indexes, then we can achieve high performance operation by implementing Covered Query. In other word, we expect that such query operations only examined index field, but not document fields.

The Database and Collection

I will be using exactly same collection which used in this post. But in the case you are not have read it or just forget about it, then I will just need to re-explain the same explanation.

In this easy tutorial, we used a school database and students collection contains 1,000,000 documents. All the documents randomly created from javascript file which you can downloaded from here.
Below the description of each key in our document:

student_id: Unique identification of each student.
scores: An array of contains two keys: type (type of score) and score (float value).
class_id: Unique identification of each class where student belongs to.

Implementation

In this section, we want to know any students defined by student_id belong to classes 5, 15, 30. So the query is db.students.find({class_id: {$in: [5, 15, 30]}}, {_id: 0, student_id: 1, class_id: 1})

First implementation: Without indexing

Run this commands in the shell:

var exp = db.students.explain('executionStats').find({class_id: {$in: [5, 15, 30]}}, {_id: 0, student_id: 1, class_id: 1})
exp

We got:

...
"winningPlan" : {
                        "stage" : "PROJECTION",
                        "transformBy" : {
                                "_id" : 0,
                                "student_id" : 1,
                                "class_id" : 1
                        },
                        "inputStage" : {
                                "stage" : "COLLSCAN",
...
"executionStats" : {
                "executionSuccess" : true,
                "nReturned" : 5977,
                "executionTimeMillis" : 840,
                "totalKeysExamined" : 0,
                "totalDocsExamined" : 1000000,
...

Second implementation: With indexing and proper covered query

Run this commands in the shell:

db.students.createIndex({class_id: 1, student_id: 1})
var exp = db.students.explain('executionStats').find({class_id: {$in: [5, 15, 30]}}, {_id: 0, student_id: 1, class_id: 1})
exp

We got:

...
"winningPlan" : {
                        "stage" : "PROJECTION",
                        "transformBy" : {
                                "_id" : 0,
                                "student_id" : 1,
                                "class_id" : 1
                        },
                        "inputStage" : {
                                "stage" : "IXSCAN",
...
"executionStats" : {
                "executionSuccess" : true,
                "nReturned" : 5977,
                "executionTimeMillis" : 16,
                "totalKeysExamined" : 5980,
                "totalDocsExamined" : 0,
...

Conclusion

As you can see from explained result, the Covered Query achieved far higher performance than regular non-indexed query which has 2/105 execution time ratio and only need to examined 5980 keys to return 5977 documents. It is pretty good performance gain right? Your computer science friend may glad to look that proof. :)

Suggestion

Keep to play around with same collection and try to create multi-key indexes {'scores.score': -1, 'scores.type': 1}, then execute var exp = db.students.explain('executionStats'); exp.find({'scores.type': 'exam', 'scores.score': {$gte: 90}}). You may asking why the covered query did not work. Try to read this documentation on Multikey Covering section. You will found out why.

How to Evaluate Query Performance on MongoDB

Hafidz Jazuli Luthfi — Thu, 12 Apr 2018 09:53:18 +0000

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. I like to share what I have already learn from this course. It is about how we evaluate query performance on MongoDB using explain("executionStats").

Motivation

Evaluating query performance may became complicated if we do not really know which part should be measured. Fortunately, MongoDB provides very handy tool which can be used to evaluate query performance: explain("executionStats"). This tool provide us some general measurements such as number of examined document and execution time that can be used to do statistical analysis.

The explain("executionStats")

You can find detailed explanation of explain("executionStats") output from this documentation. To simplify, we only need to focused on some output keys:

nReturned: Number of documents returned by query operation.
executionTimeMillis: Total time in milliseconds needed to complete the operation.
totalKeysExamined: Returns 0 (zero) if no indexes found in the operations, else returns number of scanned index keys in order to complete the operation.
totalDocsExamined: Total number of examined documents in order to complete the operation.

The Database and Collection

student_id: Unique identification of each student.
scores: An array of contains two keys: type (type of score) and score (float value).
class_id: Unique identification of each class where student belongs to.

Evaluation

In this section, we want to know how indexing can improve query performances. In order to simplify the case, we focused only on how to optimizing "Read operation".

Initial evaluation

We need to finds any students that have exam score greater than 90. So the query is: db.students.find({'scores.type': 'exam', 'scores.score': {$gte: 90}})

First evaluation: Without indexing.

Run this commands in the shell:

var exp = db.students.explain('executionStats');
exp.find({'scores.type': 'exam', 'scores.score': {$gte: 90}})

We got:

...
"executionStats" : {
                "executionSuccess" : true,
                "nReturned" : 343310,
                "executionTimeMillis" : 2843,
                "totalKeysExamined" : 0,
                "totalDocsExamined" : 1000000,
...

Second evaluation: With indexing.

Run this commands in the shell:

db.students.createIndex({'scores.score': -1, 'scores.type': 1})
var exp = db.students.explain('executionStats');
exp.find({'scores.type': 'exam', 'scores.score': {$gte: 90}})

We got:

...
"executionStats" : {
                "executionSuccess" : true,
                "nReturned" : 343310,
                "executionTimeMillis" : 2284,
                "totalKeysExamined" : 399171,
                "totalDocsExamined" : 343310,
...

Conclusion

From the two evaluations results, we knew that the operation to find any students that have exam score greater than 90 will run faster by using compound index. In this case, collection with indexes {'scores.score': -1, 'scores.type': 1} performs faster than without indexes (2284 ms vs 2843 ms).

Suggestion

Try to run this explain query:

db.students.explain('executionStats').find({'scores.score': {$gte: 90}, 'scores.type': 'exam'})

This query differs from the explain query which used in the evaluation because we flip the find parameters. Maybe you will convinced yourself that this query should be run faster than the query we used in the evaluation tutorial. But in fact, its not. Try to look winningPlan key on the explain result, you will find out why.

I have created a simple javascript code which measures means of "executionTimeMillis". Just play around with that code to do statistical analysis, such as measure the standard deviation.