during load tests (simulating users connecting to the server), for the first 1750 seconds there is a mean transaction / second rate of about 300-400, with peak of about 700 tr/sec. These transaction are making some use of server's underlying mysql database, at a rate of about 5 - 10 queries per transaction. There are not any joins, views or more complicated stuff, but straightforward queries, db being indexed accordingly too, innoDB storage engine. The machine has plenty of RAM and CPU power, and monitoring reveals even at SQL Exceptions, the machine has way more than 50% free CPU/RAM resources. Db entries are of the order of magnitude 10^5, and still, I have about 20-30 of these exceptions:
2012-06-07 01:56:55 XGateRoster.<init>() SEVERE: Error getting data list for: +39128516@xmpp.xgate.com.hk/offline/XGate/PhoneBook; method took 14672 ms, thread: 878
tigase.db.TigaseDBException: Error getting data list for: +39128516@xmpp.xgate.com.hk/offline/XGate/PhoneBook; method took 14672 ms, thread: 878
at tigase.db.jdbc.JDBCRepository.getDataList(JDBCRepository.java:482)
at tigase.db.UserRepositoryMDImpl.getDataList(UserRepositoryMDImpl.java:225)
at tigase.xmpp.RepositoryAccess.getDataList(RepositoryAccess.java:393)
at tigase.xmpp.RepositoryAccess.getOfflineDataList(RepositoryAccess.java:458)
at tigase.xmpp.impl.XGateRoster.<init>(XGateRoster.java:94)
at sun.reflect.GeneratedConstructorAccessor50.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at tigase.xmpp.impl.DynamicRoster.init_settings(DynamicRoster.java:294)
at tigase.xmpp.impl.DynamicRoster.getDynamicRosters(DynamicRoster.java:214)
at tigase.xmpp.impl.DynamicRoster.getBuddiesList(DynamicRoster.java:137)
at tigase.xmpp.impl.DynamicRoster.addBuddies(DynamicRoster.java:83)
at tigase.xmpp.impl.Presence.broadcastProbe(Presence.java:685)
at tigase.xmpp.impl.Presence.processOutInitial(Presence.java:1518)
at tigase.xmpp.impl.Presence.process(Presence.java:914)
at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2135)
at tigase.util.WorkerThread.run(WorkerThread.java:132)
Caused by: java.sql.SQLException: Query execution was interrupted
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1055)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3491)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3423)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1936)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
at com.mysql.jdbc.CallableStatement.executeQuery(CallableStatement.java:894)
at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:668)
at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:1553)
at tigase.db.jdbc.JDBCRepository.getNodeNID(JDBCRepository.java:1539)
at tigase.db.jdbc.JDBCRepository.getDataList(JDBCRepository.java:436)
at tigase.db.UserRepositoryMDImpl.getDataList(UserRepositoryMDImpl.java:225)
at tigase.xmpp.RepositoryAccess.getDataList(RepositoryAccess.java:393)
at tigase.xmpp.RepositoryAccess.getOfflineDataList(RepositoryAccess.java:458)
at tigase.xmpp.impl.XGateRoster.<init>(XGateRoster.java:94)
at sun.reflect.GeneratedConstructorAccessor50.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at tigase.xmpp.impl.DynamicRoster.init_settings(DynamicRoster.java:294)
at tigase.xmpp.impl.DynamicRoster.getDynamicRosters(DynamicRoster.java:214)
at tigase.xmpp.impl.DynamicRoster.getBuddiesList(DynamicRoster.java:137)
at tigase.xmpp.impl.DynamicRoster.addBuddies(DynamicRoster.java:83)
at tigase.xmpp.impl.Presence.broadcastProbe(Presence.java:685)
at tigase.xmpp.impl.Presence.processOutInitial(Presence.java:1518)
at tigase.xmpp.impl.Presence.process(Presence.java:914)
at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2135)
at tigase.util.WorkerThread.run(WorkerThread.java:132)
2012-06-07 01:57:14 XGateRoster.<init>() SEVERE: Error getting data list for: +3919522@xmpp.xgate.com.hk/offline/XGate/PhoneBook; method took 0 ms, thread: 835
tigase.db.TigaseDBException: Error getting data list for: +3919522@xmpp.xgate.com.hk/offline/XGate/PhoneBook; method took 0 ms, thread: 835
at tigase.db.jdbc.JDBCRepository.getDataList(JDBCRepository.java:482)
at tigase.db.UserRepositoryMDImpl.getDataList(UserRepositoryMDImpl.java:225)
at tigase.xmpp.RepositoryAccess.getDataList(RepositoryAccess.java:393)
at tigase.xmpp.RepositoryAccess.getOfflineDataList(RepositoryAccess.java:458)
at tigase.xmpp.impl.XGateRoster.<init>(XGateRoster.java:94)
at sun.reflect.GeneratedConstructorAccessor50.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at tigase.xmpp.impl.DynamicRoster.init_settings(DynamicRoster.java:294)
at tigase.xmpp.impl.DynamicRoster.getDynamicRosters(DynamicRoster.java:214)
at tigase.xmpp.impl.DynamicRoster.setItemExtraData(DynamicRoster.java:361)
at tigase.xmpp.impl.JabberIqRoster.dynamicSetRequest(JabberIqRoster.java:169)
at tigase.xmpp.impl.JabberIqRoster.process(JabberIqRoster.java:329)
at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2135)
at tigase.util.WorkerThread.run(WorkerThread.java:132)
Caused by: java.sql.SQLException: Query execution was interrupted
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1055)
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:956)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3491)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3423)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1936)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2060)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2542)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1734)
at com.mysql.jdbc.PreparedStatement.executeQuery(PreparedStatement.java:1885)
at com.mysql.jdbc.CallableStatement.executeQuery(CallableStatement.java:894)
at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:668)
at tigase.db.jdbc.JDBCRepository.getUserUID(JDBCRepository.java:1553)
at tigase.db.jdbc.JDBCRepository.getNodeNID(JDBCRepository.java:1539)
at tigase.db.jdbc.JDBCRepository.getDataList(JDBCRepository.java:436)
at tigase.db.UserRepositoryMDImpl.getDataList(UserRepositoryMDImpl.java:225)
at tigase.xmpp.RepositoryAccess.getDataList(RepositoryAccess.java:393)
at tigase.xmpp.RepositoryAccess.getOfflineDataList(RepositoryAccess.java:458)
at tigase.xmpp.impl.XGateRoster.<init>(XGateRoster.java:94)
at sun.reflect.GeneratedConstructorAccessor50.newInstance(Unknown Source)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
at tigase.xmpp.impl.DynamicRoster.init_settings(DynamicRoster.java:294)
at tigase.xmpp.impl.DynamicRoster.getDynamicRosters(DynamicRoster.java:214)
at tigase.xmpp.impl.DynamicRoster.setItemExtraData(DynamicRoster.java:361)
at tigase.xmpp.impl.JabberIqRoster.dynamicSetRequest(JabberIqRoster.java:169)
at tigase.xmpp.impl.JabberIqRoster.process(JabberIqRoster.java:329)
at tigase.server.xmppsession.SessionManager$ProcessorWorkerThread.process(SessionManager.java:2135)
at tigase.util.WorkerThread.run(WorkerThread.java:132)
I believe the time measurements to be correct as I have double checked them. Why do I get such exceptions ? why is it that sometimes the measured execution time is fairly low (even 0 ms = instant exception throw) ?
Mysql slow logs reveal (just one big issue ?):
root@XMPP:/var/log/mysql# egrep "# Query_time: [1-9]+?\..*" /var/log/mysql/mysql-slow.log.1
# Query_time: 27.826251 Lock_time: 0.000077 Rows_sent: 0 Rows_examined: 2
# Query_time: 2.038984 Lock_time: 0.000272 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.040937 Lock_time: 0.000298 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.039785 Lock_time: 0.000347 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.040286 Lock_time: 0.000242 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.039634 Lock_time: 0.000048 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.039647 Lock_time: 0.000043 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.039711 Lock_time: 0.000059 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.103542 Lock_time: 0.000078 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.104395 Lock_time: 0.000053 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.103512 Lock_time: 0.000201 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.103431 Lock_time: 0.000038 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.375416 Lock_time: 0.000205 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.911025 Lock_time: 0.000039 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.083049 Lock_time: 0.000047 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.081169 Lock_time: 0.000036 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.649307 Lock_time: 0.000233 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.082557 Lock_time: 0.000062 Rows_sent: 0 Rows_examined: 1
# Query_time: 3.129848 Lock_time: 0.000124 Rows_sent: 0 Rows_examined: 1
# Query_time: 3.158479 Lock_time: 0.000083 Rows_sent: 0 Rows_examined: 0
# Query_time: 3.412682 Lock_time: 0.000194 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.900394 Lock_time: 0.000073 Rows_sent: 0 Rows_examined: 0
# Query_time: 3.414437 Lock_time: 0.000068 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.900706 Lock_time: 0.000202 Rows_sent: 0 Rows_examined: 0
# Query_time: 3.195506 Lock_time: 0.000198 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.901220 Lock_time: 0.000323 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.278411 Lock_time: 0.000204 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.284154 Lock_time: 0.000198 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.205004 Lock_time: 0.000342 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.204605 Lock_time: 0.000338 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.205250 Lock_time: 0.000131 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.274901 Lock_time: 0.000059 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.285315 Lock_time: 0.000099 Rows_sent: 0 Rows_examined: 1
# Query_time: 3.303273 Lock_time: 0.000060 Rows_sent: 0 Rows_examined: 1
# Query_time: 3.468223 Lock_time: 0.000041 Rows_sent: 0 Rows_examined: 1
# Query_time: 3.461232 Lock_time: 0.000053 Rows_sent: 0 Rows_examined: 1
# Query_time: 3.460767 Lock_time: 0.000399 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.758039 Lock_time: 0.000309 Rows_sent: 0 Rows_examined: 0
# Query_time: 3.462436 Lock_time: 0.000049 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.757907 Lock_time: 0.000276 Rows_sent: 0 Rows_examined: 0
# Query_time: 4.063776 Lock_time: 0.000183 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.012213 Lock_time: 0.000335 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.232263 Lock_time: 0.000270 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.831812 Lock_time: 0.000052 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.832423 Lock_time: 0.000074 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.232429 Lock_time: 0.000270 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.832328 Lock_time: 0.000053 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.231343 Lock_time: 0.000213 Rows_sent: 0 Rows_examined: 0
# Query_time: 4.234587 Lock_time: 0.000047 Rows_sent: 0 Rows_examined: 1
# Query_time: 4.458741 Lock_time: 0.000180 Rows_sent: 50 Rows_examined: 50
# Query_time: 5.739855 Lock_time: 0.000199 Rows_sent: 0 Rows_examined: 0
# Query_time: 5.726863 Lock_time: 0.000289 Rows_sent: 0 Rows_examined: 0
# Query_time: 5.742442 Lock_time: 0.000052 Rows_sent: 0 Rows_examined: 1
# Query_time: 5.726623 Lock_time: 0.000048 Rows_sent: 0 Rows_examined: 1
# Query_time: 5.727539 Lock_time: 0.000234 Rows_sent: 0 Rows_examined: 0
# Query_time: 5.726928 Lock_time: 0.000222 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.165082 Lock_time: 0.000208 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.161232 Lock_time: 0.000046 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.583766 Lock_time: 0.000249 Rows_sent: 0 Rows_examined: 0
# Query_time: 3.011636 Lock_time: 0.000227 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.510544 Lock_time: 0.000227 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.921829 Lock_time: 0.000091 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.920549 Lock_time: 0.000315 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.922647 Lock_time: 0.000239 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.377067 Lock_time: 0.000208 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.511974 Lock_time: 0.000070 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.360768 Lock_time: 0.000051 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.378182 Lock_time: 0.000104 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.806293 Lock_time: 0.000100 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.378549 Lock_time: 0.000056 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.378903 Lock_time: 0.000088 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.879465 Lock_time: 0.000212 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.020542 Lock_time: 0.000054 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.019749 Lock_time: 0.000493 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.036685 Lock_time: 0.000303 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.019717 Lock_time: 0.000197 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.963536 Lock_time: 0.000161 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.019353 Lock_time: 0.000129 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.019624 Lock_time: 0.000128 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.820161 Lock_time: 0.000051 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.255717 Lock_time: 0.000167 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.413679 Lock_time: 0.000247 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.402931 Lock_time: 0.000148 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.255956 Lock_time: 0.000189 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.353527 Lock_time: 0.000195 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.402936 Lock_time: 0.000204 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.255460 Lock_time: 0.000234 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.169004 Lock_time: 0.000135 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.576578 Lock_time: 0.000039 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.578367 Lock_time: 0.000139 Rows_sent: 1 Rows_examined: 3
# Query_time: 2.154770 Lock_time: 0.000209 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.327091 Lock_time: 0.000123 Rows_sent: 0 Rows_examined: 1
# Query_time: 2.154538 Lock_time: 0.000209 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.674249 Lock_time: 0.000430 Rows_sent: 0 Rows_examined: 0
# Query_time: 2.913024 Lock_time: 0.000076 Rows_sent: 0 Rows_examined: 1
# Query_time: 1.674312 Lock_time: 0.000435 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.992658 Lock_time: 0.000354 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.756505 Lock_time: 0.000247 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.978150 Lock_time: 0.000208 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.979560 Lock_time: 0.000210 Rows_sent: 0 Rows_examined: 0
# Query_time: 1.416010 Lock_time: 0.000458 Rows_sent: 0 Rows_examined: 0
etc...
I have tried changing the database jdbc driver, and I have made sure no such bugs are documented in the mysql version I am currently using.
Thank you all for your input!
