CommandHelper

CommandHelper

Bukkit Plugins
46.5k Downloads

query() not reusing existing connection causing a "Too many connections" error.

LadyCailinBot opened this issue ยท 2 comments

commented

CMDHELPER-2826 - Reported by CyaNox

{code:title=auto_include.ms}
proc(_sql_store_value, @key, @value){
@Result = query('testing', 'REPLACE INTO storage SET key=?, value=?', @key, @value)
}

proc(_sql_get_value, @key){
@Result = query('testing', 'SELECT * FROM storage WHERE key=?', @key)
return(@Result[0])
}

{code:title=alias}
/test = >>>
  @names = array('mysql')
  @iterations = array(10, 100, 1000, 5000)
  foreach(@iterations, @iteration){
    sys_out('Now profiling with '.@iteration.' values:')
    foreach(@names, @name){
      @start = time()
      foreach(cslice(1,@iteration), @i){
        _sql_store_value(@name . '.val'.@i, 'value')
      }
      foreach(cslice(1,@iteration), @i){
        _sql_get_value(@name . '.val'.@i)
      }
      @stop = time()
      sys_out('  '.@name.' took '.(@stop - @start).' ms')
    }
  }
<<<

{code:title=console}
20:39:33 [INFO] Now profiling with 10 values:
20:39:33 [INFO] mysql took 137 ms
20:39:33 [INFO] Now profiling with 100 values:
20:39:34 [INFO] mysql took 863 ms
20:39:34 [INFO] Now profiling with 1000 values:
20:39:37 [INFO] SQLException: Too many connections
proc _sql_store_value:/.../auto_include.ms:3
<

>:/.../test.msa:84

20:39:37 [SEVERE] The previous MethodScript error had an attached cause:
20:39:37 [SEVERE] com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: Too many connections
20:39:37 [SEVERE] at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
20:39:37 [SEVERE] at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)
20:39:37 [SEVERE] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
20:39:37 [SEVERE] at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
20:39:37 [SEVERE] at com.mysql.jdbc.Util.handleNewInstance(Util.java:407)
20:39:37 [SEVERE] at com.mysql.jdbc.Util.getInstance(Util.java:382)
20:39:37 [SEVERE] at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013)
20:39:37 [SEVERE] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3593)
20:39:37 [SEVERE] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3525)
20:39:37 [SEVERE] at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:931)
20:39:37 [SEVERE] at com.mysql.jdbc.MysqlIO.secureAuth411(MysqlIO.java:4031)
20:39:37 [SEVERE] at com.mysql.jdbc.MysqlIO.doHandshake(MysqlIO.java:1296)
20:39:37 [SEVERE] at com.mysql.jdbc.ConnectionImpl.coreConnect(ConnectionImpl.java:2338)
20:39:37 [SEVERE] at com.mysql.jdbc.ConnectionImpl.connectOneTryOnly(ConnectionImpl.java:2371)
20:39:37 [SEVERE] at com.mysql.jdbc.ConnectionImpl.createNewIO(ConnectionImpl.java:2163)
20:39:37 [SEVERE] at com.mysql.jdbc.ConnectionImpl.(ConnectionImpl.java:794)
20:39:37 [SEVERE] at com.mysql.jdbc.JDBC4Connection.(JDBC4Connection.java:47)
20:39:37 [SEVERE] at sun.reflect.GeneratedConstructorAccessor27.newInstance(Unknown Source)
20:39:37 [SEVERE] at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
20:39:37 [SEVERE] at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
20:39:37 [SEVERE] at com.mysql.jdbc.Util.handleNewInstance(Util.java:407)
20:39:37 [SEVERE] at com.mysql.jdbc.ConnectionImpl.getInstance(ConnectionImpl.java:378)
20:39:37 [SEVERE] at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java:305)
20:39:37 [SEVERE] at java.sql.DriverManager.getConnection(DriverManager.java:571)
20:39:37 [SEVERE] at java.sql.DriverManager.getConnection(DriverManager.java:233)
20:39:37 [SEVERE] at com.laytonsmith.core.functions.SQL$query.exec(SQL.java:81)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:310)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:272)
20:39:37 [SEVERE] at com.laytonsmith.core.Procedure.execute(Procedure.java:194)
20:39:37 [SEVERE] at com.laytonsmith.core.Procedure.cexecute(Procedure.java:149)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:239)
20:39:37 [SEVERE] at com.laytonsmith.core.functions.DataHandling$foreach.execs(DataHandling.java:524)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:262)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:272)
20:39:37 [SEVERE] at com.laytonsmith.core.functions.DataHandling$foreach.execs(DataHandling.java:524)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:262)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:272)
20:39:37 [SEVERE] at com.laytonsmith.core.functions.DataHandling$foreach.execs(DataHandling.java:524)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:262)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.eval(Script.java:272)
20:39:37 [SEVERE] at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1494)
20:39:37 [SEVERE] at com.laytonsmith.core.MethodScriptCompiler.execute(MethodScriptCompiler.java:1454)
20:39:37 [SEVERE] at com.laytonsmith.core.Script.run(Script.java:164)
20:39:37 [SEVERE] at com.laytonsmith.core.AliasCore.alias(AliasCore.java:150)
20:39:37 [SEVERE] at com.laytonsmith.commandhelper.CommandHelperServerListener.onServerCommand(CommandHelperServerListener.java:41)
20:39:37 [SEVERE] at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
20:39:37 [SEVERE] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
20:39:37 [SEVERE] at java.lang.reflect.Method.invoke(Method.java:606)
20:39:37 [SEVERE] at org.bukkit.plugin.java.JavaPluginLoader$1.execute(JavaPluginLoader.java:425)
20:39:37 [SEVERE] at org.bukkit.plugin.RegisteredListener.callEvent(RegisteredListener.java:62)
20:39:37 [SEVERE] at org.bukkit.plugin.TimedRegisteredListener.callEvent(TimedRegisteredListener.java:30)
20:39:37 [SEVERE] at org.bukkit.plugin.SimplePluginManager.fireEvent(SimplePluginManager.java:478)
20:39:37 [SEVERE] at org.bukkit.plugin.SimplePluginManager.callEvent(SimplePluginManager.java:463)
20:39:37 [SEVERE] at net.minecraft.server.v1_6_R3.DedicatedServer.as(DedicatedServer.java:272)
20:39:37 [SEVERE] at net.minecraft.server.v1_6_R3.DedicatedServer.t(DedicatedServer.java:241)
20:39:37 [SEVERE] at net.minecraft.server.v1_6_R3.MinecraftServer.s(MinecraftServer.java:493)
20:39:37 [SEVERE] at net.minecraft.server.v1_6_R3.MinecraftServer.run(MinecraftServer.java:425)
20:39:37 [SEVERE] at net.minecraft.server.v1_6_R3.ThreadServerApplication.run(SourceFile:583)

commented

Comment by LadyCailin

This should be fixed now, can you verify?

commented

Comment by CyaNox

Confirmed the fix works ... I however wonder if connection pooling or caching may improve the performance. The half wit implementation of a fake PSN performs considerably slower then all the others:

17:49:44 [INFO] Now profiling with 10 values:
17:49:44 [INFO]   mem took 1.934297 ms
17:49:44 [INFO]   sqlite took 186.823123 ms
17:49:44 [INFO]   ser took 61.846668 ms
17:49:44 [INFO]   redis took 6.290877 ms
17:49:44 [INFO] Now profiling with 100 values:
17:49:44 [INFO]   mem took 14.586064 ms
17:49:45 [INFO]   sqlite took 374.064925 ms
17:49:45 [INFO]   ser took 14.026419 ms
17:49:45 [INFO]   redis took 31.897149 ms
17:49:45 [INFO] Now profiling with 1000 values:
17:49:45 [INFO]   mem took 145.459476 ms
17:49:48 [INFO]   sqlite took 3532.073197 ms
17:49:48 [INFO]   ser took 69.506168 ms
17:49:49 [INFO]   redis took 238.288049 ms
17:49:49 [INFO] Now profiling with 5000 values:
17:49:49 [INFO]   mem took 196.148113 ms
17:50:07 [INFO]   sqlite took 17676.441161 ms
17:50:07 [INFO]   ser took 164.629238 ms
17:50:07 [INFO]   redis took 641.210172 ms
17:50:07 [INFO] Now profiling with 10 values:
17:50:07 [INFO]   importexport took 0.106443 ms
17:50:07 [INFO] Now profiling with 100 values:
17:50:07 [INFO]   importexport took 0.676909 ms
17:50:07 [INFO] Now profiling with 1000 values:
17:50:07 [INFO]   importexport took 6.289666 ms
17:50:07 [INFO] Now profiling with 5000 values:
17:50:07 [INFO]   importexport took 33.40111 ms
17:50:07 [INFO] Now profiling with 10 values:
17:50:08 [INFO]   mysql took 292 ms
17:50:08 [INFO] Now profiling with 100 values:
17:50:09 [INFO]   mysql took 886 ms
17:50:09 [INFO] Now profiling with 1000 values:
17:50:16 [INFO]   mysql took 7236 ms
17:50:16 [INFO] Now profiling with 5000 values:
17:50:58 [INFO]   mysql took 42021 ms