It might happen to you anytime: Be ready! profiling, analyzing and creating indexes to support your App

Hi Everyone,

Logwriter here! How are you?

Usually when you are a Developer/DBA, you probably have a tied control of what queries your application does against the database and you kinda know which indexes will be necessary to support the queries.

But I bet that a lot of us working in the enterprise companies have the Developer/DBA role splitted because of the organization. So, you’re a DBA or you’re a Developer.

When that is the case and you’re the DBA, doesn’t matter how many times you’ve attended to SCRUM meetings with the Developer team, they will create a new feature that is querying data without an index. If this situation has never happened to you:

  • You are lucky guy, but there is always a first time for everything in life
  • Feel free to stop reading here if you don’t believe that it will never happen with you

It’s a wonderful day, you’re working in your comfy chair and all of a sudden you get a ticket about performance issues in the application forwarded by the application team to you. Of course my friend, the application team will always blame the database (they are supposed to do that, is their mission in life).

Users are complaining about slowness in the app when accessing/filtering cities per population sizes.

How you will find out what is happening?

One approach could be turning on database profiling:

> db.setProfilingLevel(1,10)
{ "was" : 0, "slowms" : 100, "ok" : 1 }

Right after the execution of the above command, you have a new collection in your database known as “system.profile”.

> show collections
system.profile
zips

Any operation that exceeds 10ms will be recorded in the system.profile collection.

note1: let’s assume that 10ms is the ceiling of acceptable latency for my app. Just because I don’t have a humongous database here.

I’m a lucky guy and the issue just happened and was recorded in the system.profile collection. So, analyzing the output:

> db.system.profile.find().pretty()
{
 "op" : "getmore",
 "ns" : "postal.zips",
 "query" : {
 "getMore" : NumberLong("25579730777"),
 "collection" : "zips"
 },
 "originatingCommand" : {
 "find" : "zips",
 "filter" : {
 "pop" : {
 "$gt" : 12000
 }
 }
 },
 "cursorid" : 25579730777,
 "keysExamined" : 0,
 "docsExamined" : 29178,
 "cursorExhausted" : true,
 "numYield" : 228,
 "locks" : {
 "Global" : {
 "acquireCount" : {
 "r" : NumberLong(458)
 }
 },
 "Database" : {
 "acquireCount" : {
 "r" : NumberLong(229)
 }
 },
 "Collection" : {
 "acquireCount" : {
 "r" : NumberLong(229)
 }
 }
 },
 "nreturned" : 6751,
 "responseLength" : 681209,
 "protocol" : "op_command",
 "millis" : 12,
 "planSummary" : "COLLSCAN",
 "execStats" : {
 "stage" : "COLLSCAN",
 "filter" : {
 "pop" : {
 "$gt" : 12000
 }
 },
 "nReturned" : 6852,
 "executionTimeMillisEstimate" : 11,
 "works" : 29469,
 "advanced" : 6852,
 "needTime" : 22616,
 "needYield" : 0,
 "saveState" : 231,
 "restoreState" : 231,
 "isEOF" : 1,
 "invalidates" : 0,
 "direction" : "forward",
 "docsExamined" : 29467
 },
 "ts" : ISODate("2017-04-12T00:39:53.808Z"),
 "client" : "127.0.0.1",
 "appName" : "MongoDB Shell",
 "allUsers" : [ ],
 "user" : ""
}
> 

I highlighted the fields that I believe that are important for this troubleshooting.

Q: Which collection has been reported with an operation that exceeds 
the 10ms threshold?
A: zips.
"ns": "postal.zips"
Q: Which operation has exceeded the 10ms threshold? 
A: getmore.
"op": "getmore"
Q: Which command has been executed?
A: find command, using a filter where the field pop should be greater
than 12000.
"originatingCommand" : {
 "find" : "zips",
 "filter" : {
 "pop" : {
 "$gt" : 12000
 }
Q: How long was the execution of this command?
A: 12ms.
"millis" : 12
Q: Was this query supported by an index?
A: No, it wasn't. The query planner has pointed that this query is a
collection scan. 
"planSummary" : "COLLSCAN"
Q: How many documents were examined and how many were returned?
A: All documents in the collection (29,467) were examined and 
6,852 were returned.
"docsExamined" : 29467
"nReturned" : 6852

Since we have what we were looking for let’s disable the database profiling:

> db.setProfilingLevel(0)
{ "was" : 1, "slowms" : 10, "ok" : 1 }
> db.system.profile.drop()
true
>

OK, there is one treat here: COLLSCAN. How do we avoid a collection scan? Creating an index to support the query.

The application is executing a query filtering on the field “pop”, so let’s create an index to support this query:

> db.zips.createIndex( { "pop": 1 } )
{
 "createdCollectionAutomatically" : false,
 "numIndexesBefore" : 1,
 "numIndexesAfter" : 2,
 "ok" : 1
}
>

Index has been created, but how can I check if the execution time has been improved by the index?

Let’s create an explainable object and try the same query as the application:

> var execplan = db.zips.explain("executionStats")
> execplan.find( { "pop": { $gt: 12000 } } )
{
 "queryPlanner" : {
 "plannerVersion" : 1,
 "namespace" : "postal.zips",
 "indexFilterSet" : false,
 "parsedQuery" : {
 "pop" : {
 "$gt" : 12000
 }
 },
 "winningPlan" : {
 "stage" : "FETCH",
 "inputStage" : {
 "stage" : "IXSCAN",
 "keyPattern" : {
 "pop" : 1
 },
 "indexName" : "pop_1",
 "isMultiKey" : false,
 "multiKeyPaths" : {
 "pop" : [ ]
 },
 "isUnique" : false,
 "isSparse" : false,
 "isPartial" : false,
 "indexVersion" : 2,
 "direction" : "forward",
 "indexBounds" : {
 "pop" : [
 "(12000.0, inf.0]"
 ]
 }
 }
 },
 "rejectedPlans" : [ ]
 },
 "executionStats" : {
 "executionSuccess" : true,
 "nReturned" : 6852,
 "executionTimeMillis" : 8,
 "totalKeysExamined" : 6852,
 "totalDocsExamined" : 6852,
 "executionStages" : {
 "stage" : "FETCH",
 "nReturned" : 6852,
 "executionTimeMillisEstimate" : 10,
 "works" : 6853,
 "advanced" : 6852,
 "needTime" : 0,
 "needYield" : 0,
 "saveState" : 53,
 "restoreState" : 53,
 "isEOF" : 1,
 "invalidates" : 0,
 "docsExamined" : 6852,
 "alreadyHasObj" : 0,
 "inputStage" : {
 "stage" : "IXSCAN",
 "nReturned" : 6852,
 "executionTimeMillisEstimate" : 10,
 "works" : 6853,
 "advanced" : 6852,
 "needTime" : 0,
 "needYield" : 0,
 "saveState" : 53,
 "restoreState" : 53,
 "isEOF" : 1,
 "invalidates" : 0,
 "keyPattern" : {
 "pop" : 1
 },
 "indexName" : "pop_1",
 "isMultiKey" : false,
 "multiKeyPaths" : {
 "pop" : [ ]
 },
 "isUnique" : false,
 "isSparse" : false,
 "isPartial" : false,
 "indexVersion" : 2,
 "direction" : "forward",
 "indexBounds" : {
 "pop" : [
 "(12000.0, inf.0]"
 ]
 },
 "keysExamined" : 6852,
 "seeks" : 1,
 "dupsTested" : 0,
 "dupsDropped" : 0,
 "seenInvalidated" : 0
 }
 }
 },
 "serverInfo" : {
 "host" : "brbrain",
 "port" : 27017,
 "version" : "3.4.0-rc3",
 "gitVersion" : "7d68067e5a6272bb463acc4e7a6c6a144148039c"
 },
 "ok" : 1
}
> 

Not going on too much detail here, but no more COLLSCANs, now the query is supported by the index ( “stage” : “IXSCAN”).

The number of examined and returned documents are the same, indicating a returned per examined documents rate of 1 which is an excellent thing to have. (“nReturned” : 6852, “totalDocsExamined” : 6852).

The execution time came down to 8ms (“executionTimeMillis” : 8).

Database profiling is an powerful tool that can be used to identify which indexes can be created in your collection to improve execution times.

It’s a simple example, but I believe that you got the idea, right? 🙂

Thanks for reading it and let me know if you have any questions.

See you next post!

Logwriter

Advertisements

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s