OF 3.6.0a - SQLException - maximum connection count

Openfire Openfire Support
1

I have some database problems with OF 3.6.0a. Openfire says in info.log that there are no database connections available. I found three different kinds of exceptions, listed below. Altogether I got 336 exceptions of this kind in the last 4-5 days, distributed in 6 phases of each approx. 2 minutes. In these 2-min-phases the server was probably not responding. I can say that, because my statistics plugin (webreg) missed some update points at the given time, so I have leaks in statistics.

2008.09.11 23:05:05 Unable to get a connection from the database pool (attempt 1 out of 10).
java.sql.SQLException: Couldn't get connection because we are at maximum connection count (15/15) and there are none available
        at org.logicalcobwebs.proxool.Prototyper.quickRefuse(Prototyper.java:309)
        at org.logicalcobwebs.proxool.ConnectionPool.getConnection(ConnectionPool.java:152)
        at org.logicalcobwebs.proxool.ProxoolDriver.connect(ProxoolDriver.java:89)
        at java.sql.DriverManager.getConnection(DriverManager.java:582)
        at java.sql.DriverManager.getConnection(DriverManager.java:154)
        at org.jivesoftware.database.DefaultConnectionProvider.getConnection(DefaultConnectionProvider.java:75)
        at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager.java:104)
        at org.jivesoftware.openfire.privacy.PrivacyListProvider.loadDefaultPrivacyList(PrivacyListProvider.java:205)
        at org.jivesoftware.openfire.privacy.PrivacyListManager.getDefaultPrivacyList(PrivacyListManager.java:141)
        at org.jivesoftware.openfire.roster.Roster.broadcastPresence(Roster.java:575)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.broadcastUpdate(PresenceUpdateHandler.java:283)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:137)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:112)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:176)
        at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:134)
        at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:70)
        at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:76)
        at org.jivesoftware.openfire.SessionManager$ClientSessionListener.onConnectionClose(SessionManager.java:1133)
        at org.jivesoftware.openfire.nio.NIOConnection.notifyCloseListeners(NIOConnection.java:202)
        at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:185)
        at org.jivesoftware.openfire.nio.ConnectionHandler.sessionClosed(ConnectionHandler.java:87)
        at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.sessionClosed(AbstractIoFilterChain.java:550)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633)
        at org.apache.mina.common.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:65)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633)
        at org.apache.mina.filter.codec.ProtocolCodecFilter.sessionClosed(ProtocolCodecFilter.java:259)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633)
        at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:249)
        at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:283)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
        at java.lang.Thread.run(Thread.java:619)

2008.09.11 23:05:05 Unable to get a connection from the database pool (attempt 1 out of 10).
java.sql.SQLException: Couldn't get connection because we are at maximum connection count (15/15) and there are none available
        at org.logicalcobwebs.proxool.Prototyper.quickRefuse(Prototyper.java:309)
        at org.logicalcobwebs.proxool.ConnectionPool.getConnection(ConnectionPool.java:152)
        at org.logicalcobwebs.proxool.ProxoolDriver.connect(ProxoolDriver.java:89)
        at java.sql.DriverManager.getConnection(DriverManager.java:582)
        at java.sql.DriverManager.getConnection(DriverManager.java:154)
        at org.jivesoftware.database.DefaultConnectionProvider.getConnection(DefaultConnectionProvider.java:75)
        at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager.java:104)
        at org.jivesoftware.openfire.group.DefaultGroupProvider.getGroupNames(DefaultGroupProvider.java:340)
        at org.jivesoftware.openfire.group.GroupManager.getGroups(GroupManager.java:435)
        at org.jivesoftware.openfire.roster.Roster.<init>(Roster.java:106)
        at org.jivesoftware.openfire.roster.RosterManager.getRoster(RosterManager.java:86)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.broadcastUpdate(PresenceUpdateHandler.java:282)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:137)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:112)
        at org.jivesoftware.openfire.handler.PresenceUpdateHandler.process(PresenceUpdateHandler.java:176)
        at org.jivesoftware.openfire.PresenceRouter.handle(PresenceRouter.java:134)
        at org.jivesoftware.openfire.PresenceRouter.route(PresenceRouter.java:70)
        at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:76)
        at org.jivesoftware.openfire.SessionManager$ClientSessionListener.onConnectionClose(SessionManager.java:1133)
        at org.jivesoftware.openfire.nio.NIOConnection.notifyCloseListeners(NIOConnection.java:202)
        at org.jivesoftware.openfire.nio.NIOConnection.close(NIOConnection.java:185)
        at org.jivesoftware.openfire.nio.ConnectionHandler.sessionClosed(ConnectionHandler.java:87)
        at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.sessionClosed(AbstractIoFilterChain.java:550)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633)
        at org.apache.mina.common.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:65)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633)
        at org.apache.mina.filter.codec.ProtocolCodecFilter.sessionClosed(ProtocolCodecFilter.java:259)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextSessionClosed(AbstractIoFilterChain.java:269)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$800(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.sessionClosed(AbstractIoFilterChain.java:633)
        at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:249)
        at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:283)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
        at java.lang.Thread.run(Thread.java:619)

2008.09.11 23:06:54 Unable to get a connection from the database pool (attempt 1 out of 10).
java.sql.SQLException: Couldn't get connection because we are at maximum connection count (15/15) and there are none available
        at org.logicalcobwebs.proxool.Prototyper.quickRefuse(Prototyper.java:309)
        at org.logicalcobwebs.proxool.ConnectionPool.getConnection(ConnectionPool.java:152)
        at org.logicalcobwebs.proxool.ProxoolDriver.connect(ProxoolDriver.java:89)
        at java.sql.DriverManager.getConnection(DriverManager.java:582)
        at java.sql.DriverManager.getConnection(DriverManager.java:154)
        at org.jivesoftware.database.DefaultConnectionProvider.getConnection(DefaultConnectionProvider.java:75)
        at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager.java:104)
        at org.jivesoftware.openfire.pubsub.PubSubPersistenceManager.removePublishedItem(PubSubPersistenceManager.java:1052)
        at org.jivesoftware.openfire.pubsub.PublishedItemTask.run(PublishedItemTask.java:62)
        at java.util.TimerThread.mainLoop(Timer.java:512)
        at java.util.TimerThread.run(Timer.java:462)
2

If was online during one of this things. Openfire was not responding for approx. 5 min.

One more:

2008.09.15 13:48:55 Unable to get a connection from the database pool (attempt 1 out of 10).
java.sql.SQLException: Couldn't get connection because we are at maximum connection count (15/15) and there are none availab$
        at org.logicalcobwebs.proxool.Prototyper.quickRefuse(Prototyper.java:309)
        at org.logicalcobwebs.proxool.ConnectionPool.getConnection(ConnectionPool.java:152)
        at org.logicalcobwebs.proxool.ProxoolDriver.connect(ProxoolDriver.java:89)
        at java.sql.DriverManager.getConnection(DriverManager.java:582)
        at java.sql.DriverManager.getConnection(DriverManager.java:154)
        at org.jivesoftware.database.DefaultConnectionProvider.getConnection(DefaultConnectionProvider.java:75)
        at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager.java:104)
        at org.jivesoftware.openfire.vcard.DefaultVCardProvider.loadVCard(DefaultVCardProvider.java:72)
        at org.jivesoftware.openfire.vcard.VCardManager.getOrLoadVCard(VCardManager.java:222)
        at org.jivesoftware.openfire.vcard.VCardManager.getVCard(VCardManager.java:215)
        at org.jivesoftware.openfire.handler.IQvCardHandler.handleIQ(IQvCardHandler.java:108)
        at org.jivesoftware.openfire.handler.IQHandler.process(IQHandler.java:49)
        at org.jivesoftware.openfire.IQRouter.handle(IQRouter.java:351)
        at org.jivesoftware.openfire.IQRouter.route(IQRouter.java:101)
        at org.jivesoftware.openfire.spi.PacketRouterImpl.route(PacketRouterImpl.java:68)
        at org.jivesoftware.openfire.net.StanzaHandler.processIQ(StanzaHandler.java:311)
        at org.jivesoftware.openfire.net.ClientStanzaHandler.processIQ(ClientStanzaHandler.java:79)
        at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:276)
        at org.jivesoftware.openfire.net.StanzaHandler.process(StanzaHandler.java:175)
        at org.jivesoftware.openfire.nio.ConnectionHandler.messageReceived(ConnectionHandler.java:133)
        at org.apache.mina.common.support.AbstractIoFilterChain$TailFilter.messageReceived(AbstractIoFilterChain.java:570)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648)
        at org.apache.mina.common.IoFilterAdapter.messageReceived(IoFilterAdapter.java:80)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648)
        at org.apache.mina.filter.codec.support.SimpleProtocolDecoderOutput.flush(SimpleProtocolDecoderOutput.java:58)
        at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:185)
        at org.apache.mina.common.support.AbstractIoFilterChain.callNextMessageReceived(AbstractIoFilterChain.java:299)
        at org.apache.mina.common.support.AbstractIoFilterChain.access$1100(AbstractIoFilterChain.java:53)
        at org.apache.mina.common.support.AbstractIoFilterChain$EntryImpl$1.messageReceived(AbstractIoFilterChain.java:648)
        at org.apache.mina.filter.executor.ExecutorFilter.processEvent(ExecutorFilter.java:239)
        at org.apache.mina.filter.executor.ExecutorFilter$ProcessEventsRunnable.run(ExecutorFilter.java:283)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
        at java.lang.Thread.run(Thread.java:619)
3

I did a big grep on OF 3.6.0a source to find all opened connections:

cd openfire_src_3_6_0_a/src/java/org/
grep -r "DbConnectionManager.getConnection()" *

Then I checked for all occurrences, if the connection is closed properly. This is the case for all 139 getConnection() calls. (10 of that are getTransactionConnection() calls)

There remain three possibilities:

  1. There are more worker threads than open database connections.

  2. Openfire can freeze for a few minutes somewhere between an open/close.

  3. compiled Openfire (tar.gz) does differ from source code version (I don’t think so )

4

Ok, I think I found the problem:

The default value for ‘database.defaultProvider.maxConnections’ (XMLProperty) was changed in OF 3.6.0a to 25 connections (*). In 3.5.2 there where only 15 connections, this is still my setting in openfire.xml, because I always keep it when updating.

I’m using MySQL 5.0.45-7.el5 database on CentOS 5. Question: Is it save to change this to 25?

(*) openfire_src_3_6_0_a/src/web/setup/setup-datasource-standard.jsp, line 191

5

I changed this now, but when restarting Openfire I got again such an exception…that’s probably not the solution.

6

I’m betting that you either have a loop that does an insane amount of queries, or you’ve got a bit of code somewhere that doesn’t properly release the connection back into the pool.

I’ve found this adminpage to be very helpful in tracking down problems like these: https://localhost:9091/server-db-stats.jsp

It is, by the way, fine to increase the number of connections in the database pool. We’re running with 70 on each cluster node.

7

I’ve found this adminpage to be very helpful in tracking down problems like these
Thanks, have activated this now. Will see if we find this problem…

We’re running with 70 on each cluster node.
Openfire has only 18 worker threads by default…it should not need more database connections… ( JM-1368 )

8

The JIRA issue that you are referring to indicates the opposite of what you are suggesting. Basically, the JIRA issue says that every worker thread should at least be able to retrieve one connection from the database pool. This makes sense in a setup where every action is synchronous (in other words: the client thread does all the work).

This synchronicity, however, is very bad for performance. I think it’s a major flaw in the Openfire design (I’ve discussed this with Gato offline). If there’s one particular action that takes some time, for any reason, it will block your client thread from doing anything else. At that time, the capacity of your entire server is affected. If there’s a bug that causes a number of threads to wait on such a synchronous action, your entire server will lock up.

9

Ten days after the last server reboot I got now exceptions again. I got 31 of these, all in the same second:

{code}2008.09.26 12:07:55 Unable to get a connection from the database pool (attempt 1 out of 10).
java.sql.SQLException: Couldn’t get connection because we are at maximum connection count (25/25) and there are none available
at org.logicalcobwebs.proxool.Prototyper.quickRefuse(Prototyper.java:309)
at org.logicalcobwebs.proxool.ConnectionPool.getConnection(ConnectionPool.java:152 )
at org.logicalcobwebs.proxool.ProxoolDriver.connect(ProxoolDriver.java:89)
at java.sql.DriverManager.getConnection(DriverManager.java:582)
at java.sql.DriverManager.getConnection(DriverManager.java:154)
at org.jivesoftware.database.DefaultConnectionProvider.getConnection(DefaultConnec tionProvider.java:75)
at org.jivesoftware.database.DbConnectionManager.getConnection(DbConnectionManager .java:104)
at org.jivesoftware.openfire.pubsub.PubSubPersistenceManager.removePublishedItem(P ubSubPersistenceManager.java:1052)
at org.jivesoftware.openfire.pubsub.PublishedItemTask.run(PublishedItemTask.java:6 2)
at java.util.TimerThread.mainLoop(Timer.java:512)

at java.util.TimerThread.run(Timer.java:462){code}

Any ideas? I don’t think that an higher connection count will solve this problem. I have attached my database statistics from last week. Maybe someone can do anything with that. Filenames are date/time when I saved that file and cleared stats after that.

Maybe someone could agregate that data and find average/variance values per hour. Then compare that with the last log and find outliers. However, may stochastics lecture was long time ago
dbstats.tar.gz (18534 Bytes)

10

Those dumps don’t look terribly alarming to me. Generally, we try to keep every execution average as a one-digit number where possible.

You can expose the JMX interface of the database connection pool to gather a lot of information. We did it by slightly modifying the start() method in DefaultConnectionProvider, to include this line:

{code}settings.setProperty(“proxool.jmx”, “true”);{code}

While you’re at it, you might want to do this as well (although it won’t solve your current problem):

{code}settings.setProperty(“proxool.simultaneous-build-throttle”, Integer.toString(getMaxConnections()));{code}

As soon as you’ve done this, you can, at runtime, set the ‘trace’ option of proxool. If you do this, and proxool hits the maximum-active-time threshold on a particular connection, it’ll log the last know query on that connection when it forces the connection to close. You should see something like:

{quote}# was active for milliseconds and has been removed automaticaly. The Thread responsible was named ‘’, and the last SQL it performed is ‘’.{quote}

If this gets in your logfiles, you should be able to use the query that got last executed to identify the cause of your problem.

There’s more information on the Proxool properties at its website: http://proxool.sourceforge.net/properties.html

11

Thanks, but my server is an production system. I don’t want to play around in the source, mount my own Provider, etc.

Since I set max connection count to 25, the problem appears less often. Maybe it is as you said: There is no problem, I have just to many concurrent users. However, I’m still below 1000 packets per minute.

I will try a higher connection count, e.g. 50. Is there a way to set this without restarting Openfire?

12

I’m pretty sure that the (Jive) settings you can modify, are used at startup to configure the Proxool database manager. After that’s done, you can change those settings again, but those changes won’t take effect until you restart. I think you can configure Proxool at runtime, but for that you need that JMX interface enabled.

13

I just encountered the same issue.

For me, it was just as suggested, that somewhere I wasn’t closing all of my connections and returning them to the pool.

I found I had several small utility functions that were just meant to grab an id from the database, and in these I was not closing the connection. After fixing those problems everything appears to be running fine…but I’ll reply if I encounter it again.