NoSQL Zone is brought to you in partnership with:

Michael has posted 2 posts at DZone. View Full User Profile

How I Identified a MongoDB Performance Anti Pattern in 5 Minutes

02.06.2013
| 6654 views |
  • submit to reddit

The other day I was looking at a web application that was using MongoDB as its central database. We were analyzing the application for potential performance problems and inside 5 minutes I detected what I must consider to be a MongoDB anti pattern and had a 40% impact on response time. The funny thing: It was a Java best practice that triggered it!

Analyzing the Application

The first thing I always do is look at the topology of an application to get a feel for it.

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]Overall Transaktion Flow of the Application

Overall Transaction Flow of the Application

Overall Transaction Flow of the Application

As we see it’s a modestly complex web application and it’s using MongoDB as its datastore. Overall MongoDB contributes about 7% to the response time of the application. I noticed that about half of all transactions are actually calling MongoDB so I took a closer look.

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]Flow of Transactions that access MongoDB, showing 10% response time contribution of MongoDB



Flow of Transactions that access MongoDB, showing 10% response time contribution of MongoDB

Those transactions that actually do call MongoDB spend about 10% of their response time in that popular document database. As a next step I wanted to know what was being executed against MongoDB.

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]Overview of all MongoDB commands. This shows that the JourneyCollection find and getCount contribute the most to response time


Overview of all MongoDB commands. This shows that the JourneyCollection find and getCount contribute the most to response time

One immediately notices the first two lines, which contribute much more to the response time per transaction than all the others. What was interesting was that thegetCount on the JourneyCollection had the highest contribution time, but the developer responsible was not aware that he was even using it anywhere.

Things get interesting – the mysterious getCount call

Taking things one level deeper, we looked at all transactions that were executing the ominous getCount on the JourneyCollection.

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]Transactions that call JourneyCollection.getCount spend nearly half their time in MongoDB


Transactions that call JourneyCollection.getCount spend nearly half their time in MongoDB

What jumps out is that those particular transactions spend indeed over 40% of their time in MongoDB, so there was a big potential for improvement here. Another click and we looked at all MongoDB calls that were executed within the context of the same transaction as the getCount call we found so mysterious.

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]All MongoDB Statements that run within the same transaction context as the JourneyCollection.getCount


All MongoDB Statements that run within the same transaction context as the JourneyCollection.getCount

What struck us as interesting was that the number of executions per transaction of thefind and getCount on the JourneyCollection seemed closely connected. At this point we decided to look at the transactions themselves – we needed to understand why that particular MongoDB call was executed.

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]Single Transactions that execute the ominous getCount call


Single Transactions that execute the ominous getCount call

It’s immediately clear that several different transaction types are executing that particular getCount. What that meant for us is that the problem was likely in the core framework of that particular application rather than being specific to any one user action. Here is the interesting snippet:

" style="color: rgb(0, 102, 204); text-decoration: initial; outline-color: invert; outline-style: none;" ]The Transaction Trace shows where the getCount is executed exactly


The Transaction Trace shows where the getCount is executed exactly

We see that the WebService findJourneys spends all its time in the two MongoDB calls. The first is the actual find call to the Journey Collection. The MongoDB client is good at lazy loading, so the find does not actually do much yet. It only calls the server once we access the result set. We can see the round trip to MongoDB visualized in thecall node at the end.

We also see the offending getCount. We see that it is executed by a method calledsize which turns out to be com.mongodb.DBCursor.size method. This was news to our developer. Looking at several other transactions we found that this was a common pattern. Every time we search for something in the JourneyCollection thegetCount would be executed by com.mongodb.DBCursor.size. This always happens before we would really execute the send the find  command to the server(which happens in the call method). So we used CompuwareAPM DTM’s (a.k.a dynaTrace) developer integration and took a look at the offending code. Here is what we found:

BasicDBObject fields = new BasicDBObject(); fields.put(journeyStr + "." + MongoConstants.ID, 1); fields.put(MongoConstants.ID, 0); Collection locations = find(patternQuery, fields);
ArrayList results = new ArrayList(locations.size());
for (DBObject dbObject : locations) {
  String loc = dbObject.getString(journeyStr);
  results.add(loc);
}
return results;

The code looks harmless enough; we execute a find, create an array for the result and fill it. The offender is the location.size(). MongoDBs DBCursor is similar to theResultSet in JDBC, it does not return the whole data set at once, but only a subset. As a consequence it doesn’t really know how many elements the find will end up with. The only way for MongoDB to determine the final size seems to be to execute agetCount with the same criteria as the original find. In our case that additional unnecessary roundtrip made up 40% of the web services response time!

An Anti-Patter triggered by a Best Practice

So it turns out that calling size on the DBCursor must be considered an anti-pattern! The real funny thing is that the developer thought he was writing performant code. He was following the best practice to pre-size arrays. This avoids any unnecessary re-sizing ;-) . In this particular case however, that minor theoretical performance improvement led to a 40% performance degradation!

Conclusion

The take away here is not that MongoDB is bad or doesn’t perform. In fact the customer is rather happy with it. But mistakes happen and similar to other database applications we need to have the visibility into a running application to see how much it contributes to the overall response time. We also need to have that visibility to understand which statements are called where and why.

In addition this also demonstrates nicely why premature micro optimization, without leveraging an APM solution, in production will not lead to better performance. In some cases – like this one – it can actually lead to worse performance!

Published at DZone with permission of its author, Michael Kopp.

(Note: Opinions expressed in this article and its replies are the opinions of their respective authors and not those of DZone, Inc.)

Comments

Andy Bailey replied on Wed, 2013/02/13 - 9:46am

I wouldn't call pre-sizing a collection instance Java Best Practice at all.

This sort of "best practice" sprang up along with things like "object pooling" because of poor understanding of how the heap is managed and how things like collections implementations actually work.

As a consequence of this things like pre-sizing collections has been mistakenly assumed to be a Java Best Practice and is promoted as such by people who really ought to know better.

The developer concerned should have chosen a more suitable collection implementation instead: ArrayList is the one people know too well and is often abused as in this case even if the returned type is required to be one.

As you correctly pointed out premature optimisation helped cause the problem but more gravely the developer has developed a couple of bad habits.

Szqe Szwee replied on Thu, 2013/02/14 - 2:58am

 What kind of tools are you using for detecting these performance botleneck

Michael Kopp replied on Thu, 2013/02/14 - 3:08am in response to: Andy Bailey

Hi Andy,


I wouldn't be so harsh on that particular Best Practice. The reason that you presize ArrayLists is not to avoid object allocation (that would be stupid except for very large arrays) but to avoid the resize. A resize in an ArrayList will copy the data from the old array to the new one. This is a linear operation and on large arrays this can be quite expensive, at least as far as micro benchmarking goes.

I do agree that in most cases it is a rather insignificant improvement to presize arrays, but normally it doesn't hurt really.

However the real issue is that developers often assume they write performant code, and maybe do microbenchmarking on their desktop, while not analyzing performance under real world circumstances, in production or at least load test. To be honest without an APM solution they are not able to do that...

Best

Michael

Michael Kopp replied on Thu, 2013/02/14 - 3:09am in response to: Szqe Szwee

The APM Solution used here is CompuwareAPM dynaTrace.

Andy Bailey replied on Wed, 2013/03/13 - 4:57am

Hi Michael,

perhaps I was being a little harsh there.

The issue is not that the list was pre-sized but that the developer was in the habit of doing so: this drove the developer to obtain the value for a suitable size resulting, in this case, in a performance problem. Assuming that the return type was List<V> then LinkedList would/should have been a better choice of data structure, at least as far as the collection of String values from the result set is concerned. If the use of ArrayList is mandated then there is a simple re-sizing strategy that can be used to alleviate the problem.

As an aside I checked ArrayList to see how it handles resizing and was rather surprised to see that it doesn't use a default size (10) and a chunk resize strategy for the internal array which, if memory serves me correctly, slightly more archaic Java versions of Collections ArrayList used.

Microbenchmarking is useful but only when, where applicable, scalability is part of those tests and only when using a tool such as the one you mentioned is rigorously employed.

In any event the use of the size() method on result sets should be considered anathema when taking the fact that the returned value should never be relied upon in practice.

Comment viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.