在负载测试期间（模拟用户连接到服务器），前 1750 秒的平均事务/秒速率约为 300-400，峰值约为 700 tr/sec。这些事务正在使用服务器的底层 mysql 数据库，每个事务大约 5 到 10 个查询。没有任何连接、视图或更复杂的东西，而是简单的查询，数据库也被相应地索引，innoDB 存储引擎。这台机器有充足的 RAM 和 CPU 能力，即使在 SQL 异常情况下，监控也显示，这台机器有超过 50% 的可用 CPU/RAM 资源。Db 条目的数量级为 10^5，但我仍然有大约 20-30 个这样的例外：
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)
我相信时间测量是正确的，因为我已经仔细检查过它们。为什么我会得到这样的例外？为什么有时测量的执行时间相当短（甚至 0 ms = 即时异常抛出）？
Mysql 慢日志显示（只是一个大问题？）：
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...
我已尝试更改数据库 jdbc 驱动程序，并确保在我当前使用的 mysql 版本中没有记录此类错误。
谢谢大家的意见！