Issue Details (XML | Word | Printable)

Key: DERBY-3244
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Mike Matrigali
Reporter: Ole Solberg
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
Derby

NullPointerException in ....B2IRowLocking3.searchLeftAndLockPreviousKey

Created: 03/Dec/07 11:02 AM   Updated: 29/Jun/09 10:43 PM
Return to search
Component/s: Store
Affects Version/s: 10.3.2.1, 10.4.1.3
Fix Version/s: 10.3.3.0, 10.4.1.3

Time Tracking:
Not Specified

Environment: All ?
Issue Links:
Reference
 

Bug behavior facts: Regression Test Failure
Resolution Date: 13/Dec/07 07:19 PM


 Description  « Hide
The last week(48) we have seen a large number of this failure.

It was categorized as DERBY-2589 but these instances all have the NPE.


Exception while trying to insert row number: 52
ERROR XJ001: Java exception: ': java.lang.NullPointerException'.
java.sql.SQLException: Java exception: ': java.lang.NullPointerException'.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.javaException(Unknown Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(Unknown Source)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.createAndLoadTable(OnlineCompressTest.java:140)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.deleteAllRows(OnlineCompressTest.java:494)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.test1(OnlineCompressTest.java:913)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.testList(OnlineCompressTest.java:1500)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.main(OnlineCompressTest.java:1520)
Caused by: java.lang.NullPointerException
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.searchLeftAndLockPreviousKey(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanPreviousRow(Unknown Source)
at org.apache.derby.impl.store.access.btree.BTreeController.doIns(Unknown Source)
at org.apache.derby.impl.store.access.btree.BTreeController.insert(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IController.insert(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexChanger.insert(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(Unknown Source)
at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(Unknown Source)
at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(Unknown Source)
at org.apache.derby.impl.sql.execute.InsertResultSet.open(Unknown Source)
at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
... 8 more


The error statistics shows the occurrences:
(http://dbtg.thresher.com/derby/test/stats_today.html / http://dbtg.thresher.com/derby/test/stats_newest.html )

http://dbtg.thresher.com/derby/test/statistics/2589_48.html :
JIRA: 2589, Week: 48 600335-598009
598009 Daily jvm1.4 vista
598009 Daily jvm1.6 lin
598341 Daily jvm1.6 solN+1
598341 Daily jvm1.6 sparc
598354 10.3Branch jvm1.5 lin
598376 trunk16 jvmAll JDK16Jvm1.5SunOS-5.10_i86pc-i386
598692 Daily jvm1.6 sol
598729 trunk16 jvmAll JDK16Jvm1.6SunOS-5.10_i86pc-i386
599062 Daily jvm1.5 lin
599088 trunk15 jvm1.5 SunOS-5.10_i86pc-i386
599088 trunk15 jvm1.5 SunOS-5.10_sun4u-sparc
599088 trunk16 jvmAll JDK16Jvm1.5SunOS-5.10_i86pc-i386
600335 Daily jvm1.4 lin
Mon Dec 3 09:36:11 CET 2007

http://dbtg.thresher.com/derby/test/statistics/2589_47.html seems to be the first occurence:
JIRA: 2589, Week: 47 597885-597885
597885 Daily jvm1.6 lin
Mon Dec 3 09:36:13 CET 2007

All are seen on trunk except one on the 10.3 branch (598354 10.3Branch jvm1.5 lin).

 All   Comments   Work Log   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Ole Solberg made changes - 05/Dec/07 11:59 AM
Field Original Value New Value
Link This issue is related to DERBY-2589 [ DERBY-2589 ]
Ole Solberg made changes - 07/Dec/07 12:03 PM
Component/s Regression Test Failure [ 12310664 ]
[ Permlink | « Hide ]
Mike Matrigali added a comment - 07/Dec/07 06:34 PM
Do you have any of these failures that include a line number for where the null pointer error happened. If so please post the stack with the line number.

Mike Matrigali made changes - 07/Dec/07 07:02 PM
Assignee Mike Matrigali [ mikem ]
[ Permlink | « Hide ]
Ole Solberg added a comment - 10/Dec/07 01:40 PM - edited
Got one occurrence of the failure in ~10 attempts:


----------------------------------------------------------------
2007-12-10 13:16:02.173 GMT:
 Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.0.0 alpha - (602814): instance c013800d-0116-c432-a688-00000d5a7df3
on database directory /export/home/tmp/os136789/myCleanSandbox/storemore/storemore/OnlineCompressTest/wombat

Database Class Loader started - derby.database.classpath=''
2007-12-10 13:16:23.867 GMT Thread[main,5,main] (XID = 24422), (SESSIONID = 0), (DATABASE = wombat), (DRDAID = null), Cleanup action starting
2007-12-10 13:16:23.867 GMT Thread[main,5,main] (XID = 24422), (SESSIONID = 0), (DATABASE = wombat), (DRDAID = null), Failed Statement is: insert into TEST1 values(?, ?, ?, ?, ?, ?) with 6 parameters begin parameter #1: 247 :end parameter begin parameter #2: 2470 :end parameter begin parameter #3: 24700 :end parameter begin parameter #4: -247 :end parameter begin parameter #5: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa :end parameter begin parameter #6: bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb :end parameter
java.lang.NullPointerException
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.searchLeftAndLockPreviousKey(B2IRowLocking3.java:458)
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanPreviousRow(B2IRowLocking3.java:964)
at org.apache.derby.impl.store.access.btree.BTreeController.doIns(BTreeController.java:444)
at org.apache.derby.impl.store.access.btree.BTreeController.insert(BTreeController.java:1035)
at org.apache.derby.impl.store.access.btree.index.B2IController.insert(B2IController.java:211)
at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:439)
at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383)
at org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:589)
at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268)
at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453)
at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1011)
at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:487)
at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:370)
at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1234)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1650)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(EmbedPreparedStatement.java:1305)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.createAndLoadTable(OnlineCompressTest.java:140)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.checkPurgePhase(OnlineCompressTest.java:780)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.test1(OnlineCompressTest.java:916)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.testList(OnlineCompressTest.java:1500)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.main(OnlineCompressTest.java:1520)
Cleanup action completed

[ Permlink | « Hide ]
Mike Matrigali added a comment - 11/Dec/07 07:40 PM
Thanks ole, that helps a lot. I wasn't having much success reproducing on my machine by just running the
test, but was able to force
a path through the code in the debuggger that got a null at the point in your stack trace. I will be checking in fix after tests pass.

Mike Matrigali made changes - 11/Dec/07 07:40 PM
Component/s Store [ 11412 ]
Repository Revision Date User Message
ASF #603375 Tue Dec 11 21:58:25 UTC 2007 mikem DERBY-3244

In the case of a wait for a latch while traveling left at leaf level, and
a subsequent wait for either a lock or another latch while looking for row
to lock then one path through the code would get a null pointer. The code
was trying to release a latch that had already been released and was tracked
by "current_leaf == null".

I could not get this to fail in my environment, but did force it by code
inspection and changing the path through the code by hand to mimic latch
waits. My assumption is that intermittently on some platforms this single
threaded test is competing for these latches with background deleted row
cleaner thread, probably on a fast multiple processor machine.

-

M java/engine/org/apache/derby/impl/store/access/btree/index/B2IRowLocking3.java
M java/engine/org/apache/derby/impl/store/access/btree/BTreeLockingPolicy.java
Files Changed
MODIFY /db/derby/code/trunk/java/engine/org/apache/derby/impl/store/access/btree/index/B2IRowLocking3.java
MODIFY /db/derby/code/trunk/java/engine/org/apache/derby/impl/store/access/btree/BTreeLockingPolicy.java

[ Permlink | « Hide ]
Mike Matrigali added a comment - 11/Dec/07 10:02 PM
checked in fix to trunk:
m2_ibm15:42>svn commit

Sending java\engine\org\apache\derby\impl\store\access\btree\BTreeLockingPolicy.java
Sending java\engine\org\apache\derby\impl\store\access\btree\index\B2IRowLocking3.java
Transmitting file data ..
Committed revision 603375.

I will wait awhile before closing as I never actually could make the bug happen by running the test on my laptop. The fix does stop the nullpointer at the line number that Ole reported, and that I caused by hand by forcing the code through the left latch wait error path.

Repository Revision Date User Message
ASF #603774 Wed Dec 12 23:14:59 UTC 2007 mikem DERBY-3244

backport svn 603375 from trunk to 10.3.

In the case of a wait for a latch while traveling left at leaf level, and
a subsequent wait for either a lock or another latch while looking for row
to lock then one path through the code would get a null pointer. The code
was trying to release a latch that had already been released and was tracked
by "current_leaf == null".

I could not get this to fail in my environment, but did force it by code
inspection and changing the path through the code by hand to mimic latch
waits. My assumption is that intermittently on some platforms this single
threaded test is competing for these latches with background deleted row
cleaner thread, probably on a fast multiple processor machine.
Files Changed
MODIFY /db/derby/code/branches/10.3/java/engine/org/apache/derby/impl/store/access/btree/index/B2IRowLocking3.java
MODIFY /db/derby/code/branches/10.3/java/engine/org/apache/derby/impl/store/access/btree/BTreeLockingPolicy.java

[ Permlink | « Hide ]
Ole Solberg added a comment - 13/Dec/07 02:01 PM
I did 100 storemore test runs on 603375 without seeing the failure.
(On 603319 it hit after 11 runs.)


Mike Matrigali made changes - 13/Dec/07 07:19 PM
Resolution Fixed [ 1 ]
Status Open [ 1 ] Resolved [ 5 ]
Fix Version/s 10.0.2.0 [ 10920 ]
Fix Version/s 10.3.2.1 [ 12312876 ]
Fix Version/s 10.4.0.0 [ 12312540 ]
Ole Solberg made changes - 21/Dec/07 02:04 PM
Status Resolved [ 5 ] Closed [ 6 ]
[ Permlink | « Hide ]
Kathey Marsden added a comment - 04/Apr/08 04:49 PM
Fixing the fix version. This went into the 10.3 branch at 603774 and the 10.3.2.1 release was at 599110.

Kathey Marsden made changes - 04/Apr/08 04:49 PM
Fix Version/s 10.3.2.2 [ 12312885 ]
Fix Version/s 10.3.2.1 [ 12312876 ]
Kathey Marsden made changes - 04/Apr/08 04:50 PM
Fix Version/s 10.0.2.0 [ 10920 ]
Dag H. Wanvik made changes - 29/Jun/09 10:41 PM
Derby Categories [Regression Test Failure]
Dag H. Wanvik made changes - 29/Jun/09 10:43 PM
Component/s Regression Test Failure [ 12310664 ]

Powered by a free Atlassian JIRA open source license for Apache Software Foundation. Try JIRA - bug tracking software for your team.
Atlassian JIRA the Professional Issue Tracker. (Enterprise Edition, Version: 3.13.2-#335) - Bug/feature request - Atlassian news - Contact Administrators