Mule Mongo Connector Fails Under Heavy Load

Posted in Enterprise Java on by Jeff

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 though. 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.

1
2
3
4
5
6
7
8
9
10
11
12
   <flow name="Incoming_Flow">
        <http:inbound-endpoint path="incoming" />
        <http:body-to-parameter-map-transformer />
        <transformer ref="getCollectionName" />
 
        <!-- Do some business logic -->
        <component class="com.thorntech.MyBusinessPojo">
 
        <!-- Log to mongo  -->
        <json:object-to-json-transformer />
        <mongo:insert-object collection="#[header:outbound:collectionName]" dbObject-ref="#[payload]" />
   </flow>

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:\var\log>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.

814
815
816
817
818
819
820
821
822
823
824
825
826
    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.

1
2
3
4
5
6
7
8
9
10
11
    <spring:beans>
    	<spring:bean id="mongoDb" class="com.mongodb.Mongo" scope="singleton"/>    	
    	<spring:bean id="updateMongo" class="com.thorntech.mongo.UpdateMongoComponent" scope="singleton" init-method="init">
    		<spring:property name="mongoDb" ref="mongoDb"/>
    		<spring:property name="dbName" value="app-logs"/>
    	</spring:bean>
    	<spring:bean id="insertMongo" class="com.thorntech.mongo.InsertMongoComponent" scope="singleton" init-method="init">
    		<spring:property name="mongoDb" ref="mongoDb"/>
    		<spring:property name="dbName" value="app-logs"/>
    	</spring:bean>    	
    </spring:beans>

And here are my very simple Java classes. The AbstractMongoComponent is a base class I wrote that simply stores the injected Spring properties.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
    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.

1
2
3
4
5
6
7
8
9
10
11
12
13
   <flow name="Incoming_Flow">
        <http:inbound-endpoint path="incoming" />
        <http:body-to-parameter-map-transformer />
        <transformer ref="getCollectionName" />
 
        <!-- Do some business logic -->
        <component class="com.thorntech.MyBusinessPojo">
 
        <!-- Log to mongo  -->
  	<component>
	    <spring-object bean="insertMongo"/>
	</component>  
   </flow>

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.

7 Responses to Mule Mongo Connector Fails Under Heavy Load

  1. Kevin says:

    Great analysis…but i think you just got bit by the mule. You might want to pool your components. I think default instance under pooled components is 5, but a regular component will create and destroy and instance for every request unless you do what you did and singleton’d and delegated the responsibility to your java class. K

    • Jeff says:

      The normal Mongo Java driver maintains its own pool of connections. It was designed to be used as a singleton like I’ve shown. So there really is no need for mule to pool connections also.

  2. Steve Ardis says:

    I was having the exact same problem you were. Oddly, I was able to get rid of the problem by setting the “connectionsPerHost” property, i.e..:

    Does this seem reasonable?

    Steve Ardis

    • Jeff says:

      Sure, that would probably work if you set it to 1. That would have the same effect as just using the Mongo driver directly – only one instance of the object. Essentially, you are using a pool of Mongo driver instances with only one instance in the pool. A little redundant, in my opinion.

      • Steve Ardis says:

        Just noticed my original comment doesn’t show the XML I provided. I set the “connectionsPerHost” property to “20″. I’m able to load 500,000 records with this setting.

        Steve Ardis

  3. Leandro says:

    The version 2.2.1 of the mongo datacloud connector for mule still have this same issue :(

  4. Ethan says:

    I found that my application was crashing after making more than 5 concurrent requests with apachebench. As above, the Mongo Connector was completely nuked. I noticed that the maxActive connections in the pooling profile for the component was set to 5 – lo and behold, if you bump this up to something like 50, it will handle that many connections before failing. It’s not a great solution, but hopefully it will work well enough in lieu of a refactoring away from the Mongo Connector.

Leave a Reply