|
[
Permlink
| « Hide
]
Kathey Marsden added a comment - 13/Mar/09 02:45 PM
It does reproduce with a local transaction, autocommit off, and connection holdability set to ResultSet.CLOSE_CURSORS_AT_COMMIT as well, so apparently there is an unexpected commit occurring.
Most of what I have found on this issue today is quite mysterious to me, but I figure I will summarize it here for weekend contemplation and attack it again on Monday.
Here is the little program I use to reproduce the issue. Unfortunately table and trigger information I can't post here, except to say there is a after delete statement trigger that inserts some rows into a table. import org.apache.derby.jdbc.EmbeddedDataSource; import java.sql.*; public class ReproRSClosedLocal { public static void main(String[] args) throws Exception { EmbeddedDataSource ds = new EmbeddedDataSource(); ds.setDatabaseName("mydb"); Connection conn = ds.getConnection(); conn.setAutoCommit(false); conn.setHoldability(ResultSet.CLOSE_CURSORS_AT_COMMIT); Statement s = conn.createStatement(); s.executeUpdate("DELETE FROM XXX WHERE WSID=9"); conn.rollback(); conn.close(); } } Notice the program rolls back so there should be no change from one run to the next in terms of what gets deleted and what trigger fires. I am not sure yet, what version the user database was upgraded from, just that with the database as I got it from the user, the trigger works fine up until 660483 where the version was bumped and we start getting the error. What I have noticed is. - With the failing and passing runs we get the same number of commits, so there doesn't seem to be an extra commit. - If I run the program at 660482 (before the version change) and *then* move up to 660483 the trigger works fine. I have to unzip the db to get the error again. - If I drop and recreate the trigger, and then run the program it runs fine. - If I connect with 10.4 with soft upgrade the program works fine. In the failing case we go through VTIResultSet.reopenCore during execution of the trigger and close the ResultSet associated with the TriggerOldTransitionRows VTI. Here is the trace when we go through this code.
java.lang.Exception: TemporaryRowHolderResultSet.close() at org.apache.derby.impl.sql.execute.TemporaryRowHolderResultSet.close(TemporaryRowHolderResultSet.java:574) at org.apache.derby.impl.jdbc.EmbedResultSet.close(EmbedResultSet.java:596) at org.apache.derby.impl.sql.execute.VTIResultSet.reopenCore(VTIResultSet.java:258) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.reopenCore(ProjectRestrictResultSet.java:212) at org.apache.derby.impl.sql.execute.JoinResultSet.openRight(JoinResultSet.java:266) at org.apache.derby.impl.sql.execute.NestedLoopJoinResultSet.getNextRowCore(NestedLoopJoinResultSet.java:147) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:255) at org.apache.derby.impl.sql.execute.NormalizeResultSet.getNextRowCore(NormalizeResultSet.java:186) at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(DMLWriteResultSet.java:127) at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:496) at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:370) at org.apache.derby.impl.sql.execute.GenericTriggerExecutor.executeSPS(GenericTriggerExecutor.java:173) at org.apache.derby.impl.sql.execute.StatementTriggerExecutor.fireTrigger(StatementTriggerExecutor.java:81) at org.apache.derby.impl.sql.execute.TriggerEventActivator.notifyEvent(TriggerEventActivator.java:278) at org.apache.derby.impl.sql.execute.DeleteResultSet.fireAfterTriggers(DeleteResultSet.java:479) at org.apache.derby.impl.sql.execute.DeleteResultSet.open(DeleteResultSet.java:167) at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:370) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1203) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:596) at org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(EmbedStatement.java:176) at ReproRSClosedLocal.main(ReproRSClosedLocal.java:16) In VTIResultSet reopenCore we have: /** * If the VTI is a version2 vti that does not * need to be instantiated multiple times then * we simply close the current ResultSet and * create a new one via a call to * PreparedStatement.executeQuery(). * * @see NoPutResultSet#openCore * @exception StandardException thrown if cursor finished. */ public void reopenCore() throws StandardException { if (reuseablePs) { /* close the user ResultSet. */ if (userVTI != null) { try { --> We close the RS here userVTI.close(); userVTI = userPS.executeQuery(); /* Save off the target VTI */ if (isTarget) { activation.setTargetVTI(userVTI); } } catch (SQLException se) { throw StandardException.unexpectedUserException(se); } } } else { close(); openCore(); } } The TriggerOldTransitionRows VTI seems to have reusablePs set to true, so we close the ResultSet and call executeQuery() on the VTI prepared statement, but our TriggerOldTransitionRows.executeQuery() method only returns the existing resultSet, even if it has been closed and this the issue. It is not really a reusable prepared statement. If I change executeQuery to rebuild the resultSet like: public ResultSet executeQuery() throws SQLException { TriggerExecutionContext tec = Factory.getTriggerExecutionContext(); resultSet = tec.getOldRowSet(); return resultSet; } instead of just returning the existing ResultSet, it works ok, but I am not sure that this is the right fix. In the working case we don't seem to go through this reopenCore code. I'm not entirely sure why, perhaps a different plan? Also not clear to me is what CLOSE_CURSORS_AT_COMMIT has to do with this, because it doesn't seem to be a commit that is closing the result set. I will debug more and try to find answers to those questions but thought I would post my findings so far. So yes, the failing case was using a different plan which reopened the VTI multiple times, which just happened to change on upgrade. I was able to construct a reproduction (Derby4095Local.java) by using optimizer directives in the trigger definition.
I think the CLOSE_CURSORS_AT_COMMIT was a red herring. I was able to reproduce with the original user case without setting CLOSE_CURSORS_AT_COMMIT, so that was not really part of it. Anyway, here is the trunk stack trace. >java Derby4095Local Exception in thread "main" java.sql.SQLException: The exception 'java.sql.SQLException: ResultSet not open. Operation 'n ext' not permitted. Verify that autocommit is OFF.' was thrown while evaluating an expression. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:87) at org.apache.derby.impl.jdbc.Util.seeNextException(Util.java:223) at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:398) at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346) at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2201) at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1323) at org.apache.derby.impl.jdbc.EmbedStatement.execute(EmbedStatement.java:625) at org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(EmbedStatement.java:175) at ReproDerby4095Local.main(ReproDerby4095Local.java:14) Caused by: java.sql.SQLException: The exception 'java.sql.SQLException: ResultSet not open. Operation 'next' not permitt ed. Verify that autocommit is OFF.' was thrown while evaluating an expression. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:11 9) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70) ... 10 more Caused by: java.sql.SQLException: ResultSet not open. Operation 'next' not permitted. Verify that autocommit is OFF. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:11 9) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:87) at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:93) at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:172) at org.apache.derby.impl.jdbc.EmbedConnection.newSQLException(EmbedConnection.java:2951) at org.apache.derby.impl.jdbc.ConnectionChild.newSQLException(ConnectionChild.java:151) at org.apache.derby.impl.jdbc.EmbedResultSet.checkIfClosed(EmbedResultSet.java:4275) at org.apache.derby.impl.jdbc.EmbedResultSet.checkExecIfClosed(EmbedResultSet.java:4287) at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:387) at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:371) at org.apache.derby.impl.sql.execute.VTIResultSet.getNextRowCore(VTIResultSet.java:338) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:255) at org.apache.derby.impl.sql.execute.NestedLoopJoinResultSet.getNextRowCore(NestedLoopJoinResultSet.java:116) at org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(ProjectRestrictResultSet.java:255) at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore(DMLWriteResultSet.java:127) at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1058) at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:495) at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416) at org.apache.derby.impl.sql.GenericPreparedStatement.executeSubStatement(GenericPreparedStatement.java:286) at org.apache.derby.impl.sql.execute.GenericTriggerExecutor.executeSPS(GenericTriggerExecutor.java:159) at org.apache.derby.impl.sql.execute.StatementTriggerExecutor.fireTrigger(StatementTriggerExecutor.java:80) at org.apache.derby.impl.sql.execute.TriggerEventActivator.notifyEvent(TriggerEventActivator.java:269) at org.apache.derby.impl.sql.execute.DeleteResultSet.fireAfterTriggers(DeleteResultSet.java:465) at org.apache.derby.impl.sql.execute.DeleteResultSet.open(DeleteResultSet.java:158) at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(GenericPreparedStatement.java:416) at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:297) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1235) I think I will pursue the fix of having TriggerOldTransitionRows reconstruct the ResultSet on executeQuery. Please let me know if that does not sound acceptable. Attached is a patch for this issue.
It changes TriggerOldTransitionRows.java and TriggerNewTransitionRows.java to intialize the ResultSet on executeQuery to fix the ResultSet not open problem when a nested loop join is performed. It adds two tests to TriggerTest testDerby4095OldTriggerRows() and testDerby4095NewTriggerRows() I am running tests now. Tests passed. Please review patch derby-4095_diff.txt.
With the patch, we always reinitialize the result set on executeQuery(), even if the existing one has not been closed. Is there a way to avoid it? And is it worth avoiding? (I don't know what the initialization does and if it's a heavy operation.)
Well ResultSet.isClosed() is not available in the 1.5 context which this seems to be, so we can''t tell if the ResultSet is closed or not, but I think even if the ResultSet wasn't closed but was positioned on a different row than the first it would need to be reinitialized, so probably safest to do it always.
Hi Kathey, the patch looks good. I just had one question.
Seems like, during the initialization of the new resultset, the following piece of code gets executed for TriggerNewTransitionRows(very similar code gets executed for TriggerOldTransitionRows). I was just wondering if we should close the old resultset that we are not going to use. public java.sql.ResultSet getNewRowSet() throws SQLException { ensureProperContext(); if (afterResultSet == null) { return null; } try { /* We should really shallow clone the result set, because it could be used * at multiple places independently in trigger action. This is a bug found * during the fix of beetle 4373. */ CursorResultSet ars = afterResultSet; if (ars instanceof TemporaryRowHolderResultSet) ars = (CursorResultSet) ((TemporaryRowHolderResultSet) ars).clone(); else if (ars instanceof TableScanResultSet) ars = (CursorResultSet) ((TableScanResultSet) ars).clone(); ars.open(); java.sql.ResultSet rs = cc.getResultSet(ars); resultSetVector.addElement(rs); return rs; } catch (StandardException se) { throw PublicAPI.wrapStandardException(se); } } Thanks Mamta for looking at the patch. I changed it to close the previous ResultSet and am rerunning tests now and will wait to see what Knut says about the performance concern. I hope I can get this checked in tomorrow as there is a user on 10.3 that needs it. Perhaps if more performance work is needed I could check that in as a separate patch? Since we are moving from not working to working the performance is a lot better than it was before #:)
Changing the title of the bug since this really could occur on any version if the plan with the problem is chosen. Leaving as regression, since from the user perspective, this was a regression triggered by upgrade.
Kathey, I agree that performance can be addressed later on so feel free to checkin tomorrow the patch that you are testing.
Tests ran fine. Attached is the new patch closing the previous ResultSet (derby-4095_diff2.txt). I'll commit tomorrow morning if I hear no objection.
committed to trunk and 10.3. Will commit to 10.5,10.4.10.2, and 10.1 next week. Leaving this issue open until then.
Sorry for not responding earlier, I've been on the road for a couple of days.
I'm fine with the patch as it is. The reinitialization of the result set apparently creates a shallow clone of the underlying result set (see InternalTriggerExecutionContext.getNewRowSet()) so it shouldn't be that expensive to perform it twice, even if the before or after image is big. Thanks Knut for looking at the performance issue. I will go ahead and backport and close this out then as is.
For 10.1 I don't think this bug exists because TriggerNewTransitionRows and TriggerOldTransitionRows extend VTITemplate insted of UpdatableVTITemplate (This was changed in
I am not *totally* sure the problematic plan does not have a problem in 10.1 because we don't have optimizer directives in 10.1 so can't try it out, but for now we will leave this just as affecting 10.2 |
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
 |
|
Bug
Closed
Major
Trigger fails with ERROR 38000: The exception 'java.sql.SQLException: ResultSet not open during VTIResultSet.getNextRowCore()
