I am working on a Mule ESB project that processes a significant number of inbound HTTP requests. We have been using MongoDB to log a ton of data because, well, its just awesome. So I dropped the Mule MongoDB Connector (version 2.0.1) into my Maven pom.xml and had everything logging to mongo in minutes. “What a piece of cake!” I thought. Everything was working great at first…until I threw a heavy load at it. It was then that I realized that the Mule Mongo Connector Fails Under Heavy Load. Keep reading to find out what caused the problem and see how I fixed it.
Before I describe the cause of the problem. Let me describe my Mule Flow a little. It is very straight forward so I have no reason to think there is anything about my flow that would cause the Mongo Connector to fail. Here is a simplified version of my mule config.
This flow does the following: receive the incoming request, convert the http post params to a Map, add a collectionName outbound header property, call a business object Java class, convert the payload to JSON, and log it to Mongo.
I tested this flow using ApacheBench. When testing with a concurrency level of 1, everything works great.
d:java>ab -n 1000 -c 1 http://localhost:8081/incoming?code=1111&msg=hello+jeff
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests
Server Software: Mule
Server Hostname: localhost
Server Port: 8081
Document Path: /incoming?code=1111
Document Length: 24 bytes
Concurrency Level: 1
Time taken for tests: 4.549 seconds
Complete requests: 1000
Failed requests: 0
Write errors: 0
Total transferred: 861000 bytes
HTML transferred: 24000 bytes
Requests per second: 219.82 [#/sec] (mean)
Time per request: 4.549 [ms] (mean)
Time per request: 4.549 [ms] (mean, across all concurrent requests)
Transfer rate: 184.83 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.4 0 2
Processing: 2 4 22.6 3 717
Waiting: 2 4 22.6 3 716
Total: 2 4 22.6 3 717
Percentage of the requests served within a certain time (ms)
50% 3
66% 4
75% 4
80% 4
90% 5
95% 7
98% 10
99% 13
100% 717 (longest request)
Looking a the mongo client, everything logged just fine.
d:varlog>mongo
MongoDB shell version: 2.0.2
connecting to: test
> use app-logs
switched to db app-logs
> db.app_log_201207.find().count()
1000
If I change the concurrency level, however. Everything blows up!!!
d:java>ab -n 1000 -c 50 http://localhost:8081/incoming?code=1111&msg=hello+jeff
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
It gets through about 130 requests before it just hangs. Eventually, I get the following Exceptions in my Mule log.
ERROR 2012-07-20 16:59:02,780 [connector.http.mule.default.receiver.03] org.mule.exception.DefaultMessagingExceptionStrategy:
********************************************************************************
Message : Failed to invoke insertObject. Message payload is of type: String
Type : org.mule.api.MessagingException
Code : MULE_ERROR-29999
Payload : {"received":1342817822658,"code":"1111","logged":1342817822666}
JavaDoc : http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/api/MessagingException.html
********************************************************************************
Exception stack is:
1. Connection wait timeout after 120000 ms (com.mongodb.DBPortPool$ConnectionWaitTimeOut)
com.mongodb.DBPortPool:178 (null)
2. Failed to invoke insertObject. Message payload is of type: String (org.mule.api.MessagingException)
org.mule.module.mongo.config.InsertObjectMessageProcessor:464 (http://www.mulesoft.org/docs/site/current3/apidocs/org/mule/api/MessagingException.html)
********************************************************************************
Root Exception stack trace:
com.mongodb.DBPortPool$ConnectionWaitTimeOut: Connection wait timeout after 120000 ms
Checking the mongo client, I can see only 130 requests got logged (I wiped out the collection before running my high concurrency test).
> db.app_log_201207.find().count()
130
From this point forward, nothing else gets logged to Mongo. The Mongo Connector is totally hosed.
So what caused this problem? Digging through the MongoDb Connector source code, I learned that they are using the super awesome Apache Commons GenericKeyedObjectPool to create a ConnectionPool to Mongo. For normal Cloud Connectors, this would probably be a great idea. But this is definitely a big NO NO for the Java Mongo driver. The Mongo documentation specifically states:
The Java MongoDB driver is thread safe. If you are using in a web serving environment, for example, you should create a single Mongo instance, and you can use it in every request.
The GenericKeyedObjectPool will attempt to return an idle Object from its pool if possible. If idle objects do not exist (which they certainly did not under a load with a concurrency of 50), it will attempt to create a new object. When a new object is activated, the following code gets called in the org.mule.module.mongo.MongoCloudConnector class.
public void connect(@ConnectionKey String username, @Password String password) throws ConnectionException
{
DB db = null;
try
{
db = getDatabase(new Mongo(host, port), username, password);
}
catch (UnknownHostException e)
{
throw new ConnectionException(ConnectionExceptionCode.UNKNOWN_HOST, null, e.getMessage());
}
this.client = new MongoClientImpl(db);
}
Line 819 is our culprit. They are creating a NEW instance of the Mongo driver, which, according to the Mongo docs, should not be done. Because there are multiple Mongo instances trying to talk to MongoDB from different threads, a race condition occurs and the mongo driver eventually locks up.
So, how did I fix this issue? Easy! I got rid of the Mule MongoDB Connector and just created my own instance of the Mongo driver as a Spring bean. I also created two very simple Pojo classes that use the spring injected Mongo driver to insert and update a collection in Mongo. Here is my spring config.
And here are my very simple Java classes. The AbstractMongoComponent is a base class I wrote that simply stores the injected Spring properties.
public class InsertMongoComponent extends AbstractMongoComponent {
public String insertObject(@Payload DBObject payload, @OutboundHeaders Map<String, Object> outHeaders) {
String collName = (String)outHeaders.get("collectionName");
logger.debug("Inserting into collection " +collName);
appDb.getCollection(collName).insert(payload, WriteConcern.SAFE);
ObjectId id = (ObjectId) payload.get("_id");
if (id == null) return null;
return id.toStringMongod();
}
}
public class UpdateMongoComponent extends AbstractMongoComponent {
public String updateObject(@Payload Map<String, Object> payload, @OutboundHeaders Map<String, Object> outHeaders) {
DBObject query = (DBObject)payload.get("query");
DBObject element = (DBObject)payload.get("element");
String collName = (String)outHeaders.get("collectionName");
smsDb.getCollection(collName).update(query, element, false, false, WriteConcern.SAFE);
return "";
}
}
Tying it all together, the change to my mule flow was VERY simple. In addition to my spring config (shown above), it now looks like this.
Once I made this change to use the Mongo driver as a global singleton, everything worked great. Here is a repeat of my high concurrency ApacheBench test with this change in place. Mule and Mongo handled this load with no problems whatsoever.
d:java>ab -n 1000 -c 50 http://localhost:8081/incoming?code=1111&msg=hello+jeff
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Completed 400 requests
Completed 500 requests
Completed 600 requests
Completed 700 requests
Completed 800 requests
Completed 900 requests
Completed 1000 requests
Finished 1000 requests
Server Software: Mule
Server Hostname: localhost
Server Port: 8081
Document Path: /incoming?code=1111
Document Length: 24 bytes
Concurrency Level: 50
Time taken for tests: 1.099 seconds
Complete requests: 1000
Failed requests: 0
Write errors: 0
Total transferred: 861000 bytes
HTML transferred: 24000 bytes
Requests per second: 909.87 [#/sec] (mean)
Time per request: 54.953 [ms] (mean)
Time per request: 1.099 [ms] (mean, across all concurrent requests)
Transfer rate: 765.03 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.5 0 3
Processing: 10 53 15.7 51 126
Waiting: 10 53 15.7 51 126
Total: 11 54 15.7 52 127
Percentage of the requests served within a certain time (ms)
50% 52
66% 57
75% 61
80% 64
90% 75
95% 84
98% 96
99% 103
100% 127 (longest request)
Hopefully the guys at MuleSoft will address this matter soon. Although, it was so easy to use the normal Java MongoDB driver, I don’t really know if they should bother.
