JDBC "Show Warnings" performance impact

[chris.w...@ubit.ee]

It appears that every JDBC (mysql) query, jooq makes an additional query of  "Show Warnings". What is the performance impact of this?

Trace snippet for a simple select:

        at org.jooq.tools.jdbc.DefaultStatement.getWarnings(DefaultStatement.java:182)
at org.jooq.impl.Utils.consumeWarnings(Utils.java:2151)
at org.jooq.impl.AbstractResultQuery.execute(AbstractResultQuery.java:270)

which executes the query "SHOW WARNINGS". 

[Lukas Eder]

Hi Chris,

Thanks for reporting!

The call to consumeWarnings was added because of these issues here:

- https://github.com/jOOQ/jOOQ/issues/3011

- https://github.com/jOOQ/jOOQ/issues/3076

When I implemented #3011, I wasn't aware of any server-side side-effects that the call to getWarnings() could have. In 95% of all cases, the extra effort to eagerly fetch those warnings is not worth the added "value". I gues the best way forward to prevent such calls would be to add a new Setting flag. I have registered a feature request for such a Setting:

https://github.com/jOOQ/jOOQ/issues/3558

Do you experience any overhead at all on your MySQL instance?

Best Regards,

Lukas

--
You received this message because you are subscribed to the Google Groups "jOOQ User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[chris.w...@ubit.ee]

Hi Lukas,

Thanks for the response. Toggling the warning collection behavior would be reasonable.

We don't have any perf issue per se at this time; we are simply evaluating jooq and looking at what it does under the hood.

Thanks,

Chris

[Lukas Eder]

Hi Chris,

Great. Thanks again for reporting this. If you find any other peculiarities, we'll be very happy to know about them.

Best Regards,

Lukas

[Lukas Eder]

#3558 (settings to disable warnings) is now implemented for jOOQ 3.5.0

[thisisafak...@gmail.com]

Hi Lukas,

On this issue, I am actually experiencing issues.  Somehow the underlying Prepared Statement is getting closed before calling getWarnings when calling the store method on a generated TableRecord.  When is 3.5.0 expected out?

While I understand the importance of capturing SQL warnings, it is throwing a SQLException: 

com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:57)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

at java.lang.reflect.Constructor.newInstance(Constructor.java:526)

at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)

at com.mysql.jdbc.Util.getInstance(Util.java:383)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1023)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:997)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:983)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:928)

at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:466)

at com.mysql.jdbc.StatementImpl.getWarnings(StatementImpl.java:2463)

at com.jolbox.bonecp.StatementHandle.getWarnings(StatementHandle.java:893)

at org.jooq.tools.jdbc.DefaultStatement.getWarnings(DefaultStatement.java:182)

at org.jooq.impl.Utils.consumeWarnings(Utils.java:2200)

at org.jooq.impl.AbstractStoreQuery.execute(AbstractStoreQuery.java:349)

at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:331)

... 41 more

[Mark H]

I looked further into this, it's not actually the cause of the SQLException, but rather it masks the real SQLException by trying to get the warnings after a SQLException was thrown, which in-turn throws its own SQLException.

[Lukas Eder]

Hi Mark,

We expect 3.5.0 to be released in Q4 2014.

Interesting, so what would be the original SQLException? A constraint violation? And then, fetching warnings causes issues? How can I reproduce it?

Cheers,

Lukas

[Mark H]

Hi Lukas -

The original SQLException was a null constraint violation.  There was a table in the DB that I had removed the auto increment from, and then forgotten about entirely, and I was trying to insert into it.

If you were to create a table on MySQL 5.6 like:

CREATE TABLE Test_Table(

id INT(22) UNSIGNED PRIMARY KEY,

data VARCHAR(255) NOT NULL

);

 

And then tried to insert into it using the generated TableRecord via the store() method with a null id field, you would see the getWarnings error, but not the null violation on id.

[Lukas Eder]

OK, thanks for the feedback and details. I'll investigate this and keep you posted

[Lukas Eder]

Hi Mark,

I tried reproducing this but with a very canonical test, I couldn't. The statement is still open when the warnings are fetched by jOOQ via getWarnings() . Do you have any ExecuteListeners or connection pools running that might eagerly close connections?

Cheers

Lukas

[Mark H]

Hi Lukas,

I haven't added any listeners to it to close connections, but I'm running on top of BoneCP.  While it's possible, I'd be very surprised to see Bone eagerly closing connections.  

If you're interested, my Bone CP config is below:

final BoneCPConfig config = new BoneCPConfig();
 config.setConnectionTestStatement("SELECT @@VERSION");
 config.setIdleMaxAge(4, TimeUnit.HOURS);
 config.setJdbcUrl(buildMysqlJDBCUrl(server, database, port));
 config.setConnectionTimeout(1, TimeUnit.MINUTES);
 config.setPartitionCount(4);
 config.setMinConnectionsPerPartition(1);
 config.setMaxConnectionsPerPartition(5);
 config.setPassword(pwd);
 config.setUsername(uid);
 config.setAcquireIncrement(2);

 final Properties clientInfo = new Properties();
 clientInfo.setProperty("APP-ID", Version.getVersion());
 config.setClientInfo(clientInfo);
 config.sanitize();

[Lukas Eder]

Hello,

I'm afraid that I might not have enough info to reproduce this. I'm trying this with com.jolbox:bonecp:0.8.0.RELEASE:

        final BoneCPConfig config = new BoneCPConfig();

        config.setConnectionTestStatement("SELECT @@VERSION");

        config.setIdleMaxAge(4, TimeUnit.HOURS);

        config.setJdbcUrl(getURL());

        config.setConnectionTimeout(1, TimeUnit.MINUTES);

        config.setPartitionCount(4);

        config.setMinConnectionsPerPartition(1);

        config.setMaxConnectionsPerPartition(5);

        config.setPassword(getPassword());

        config.setUsername(getUsername());

        config.setAcquireIncrement(2);

        final Properties clientInfo = new Properties();

        clientInfo.setProperty("APP-ID", "Test");

        config.setClientInfo(clientInfo);

        config.sanitize();

        BoneCP pool = new BoneCP(config);

        DSLContext ctx = DSL.using(pool.getConnection(), dialect());

        TAuthorRecord author = ctx.newRecord(T_AUTHOR);

        author.changed(true);

        author.store();

And I'm getting:

org.jooq.exception.DataAccessException: SQL [insert into `test`.`t_author` (`ID`, `FIRST_NAME`, `LAST_NAME`, `DATE_OF_BIRTH`, `YEAR_OF_BIRTH`, `ADDRESS`) values (?, ?, ?, ?, ?, ?)]; Column 'ID' cannot be null

at org.jooq.impl.Utils.translate(Utils.java:1550)

at org.jooq.impl.DefaultExecuteContext.sqlException(DefaultExecuteContext.java:571)

at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:348)

at org.jooq.impl.TableRecordImpl.storeInsert0(TableRecordImpl.java:175)

at org.jooq.impl.TableRecordImpl$1.operate(TableRecordImpl.java:141)

at org.jooq.impl.RecordDelegate.operate(RecordDelegate.java:123)

at org.jooq.impl.TableRecordImpl.storeInsert(TableRecordImpl.java:137)

at org.jooq.impl.UpdatableRecordImpl.store0(UpdatableRecordImpl.java:185)

at org.jooq.impl.UpdatableRecordImpl.access$4(UpdatableRecordImpl.java:153)

at org.jooq.impl.UpdatableRecordImpl$1.operate(UpdatableRecordImpl.java:135)

at org.jooq.impl.RecordDelegate.operate(RecordDelegate.java:123)

at org.jooq.impl.UpdatableRecordImpl.store(UpdatableRecordImpl.java:131)

at org.jooq.impl.UpdatableRecordImpl.store(UpdatableRecordImpl.java:123)

at org.jooq.test.MySQLTest.testMySQLClosingStatements(MySQLTest.java:978)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at java.lang.reflect.Method.invoke(Method.java:483)

at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)

at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)

at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)

at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)

at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)

at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)

at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)

at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)

at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)

at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)

at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)

at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)

at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)

at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)

at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)

at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)

at org.junit.runners.ParentRunner.run(ParentRunner.java:309)

at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50)

at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:459)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:675)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:382)

at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:192)

Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLIntegrityConstraintViolationException: Column 'ID' cannot be null

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)

at java.lang.reflect.Constructor.newInstance(Constructor.java:408)

at com.mysql.jdbc.Util.handleNewInstance(Util.java:408)

at com.mysql.jdbc.Util.getInstance(Util.java:383)

at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1049)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4208)

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4140)

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2597)

at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2758)

at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2826)

at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2082)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2334)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2262)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2246)

at com.jolbox.bonecp.PreparedStatementHandle.executeUpdate(PreparedStatementHandle.java:205)

at org.jooq.tools.jdbc.DefaultPreparedStatement.executeUpdate(DefaultPreparedStatement.java:88)

at org.jooq.impl.AbstractStoreQuery.execute(AbstractStoreQuery.java:390)

at org.jooq.impl.AbstractQuery.execute(AbstractQuery.java:334)

... 38 more

This looks as expected to me. Can you please provide me with a full test case that can help me reproduce the issue you're having?

Cheers,
Lukas

[Mark H]

Hi Lukas,

Sorry for the delay in replying.  The only thing I was doing differently was trying to run it from a JUnit 4 test case.  I am also using Bone CP 0.8.0-RELEASE.  I think we're reaching the point of diminishing return on this issue, and my situation must be a very narrow case that is nearly impossible to reproduce.

-Mark

[Lukas Eder]

Hi Mark,

That's a pity. Let us know if you find out more about how this could be reproduced.

- Lukas