[CORE-149] JDBC calls to interrupted threads throw sqlexceptions - Queries do not leave medium queue Created: 18/Sep/14 Updated: 10/Nov/16 Resolved: 23/Jul/15 |
|
| Status: | Closed |
| Project: | i2b2 Core Software |
| Component/s: | CRC Cell |
| Affects Version/s: | 1.7.03 |
| Fix Version/s: | 1.7.06 |
| Type: | Bug | Priority: | Major |
| Reporter: | Michael Horvath | Assignee: | Janice Donahoe |
| Resolution: | Fixed | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original Estimate: | Not Specified | ||
| Environment: |
Java SE Runtime Environment (build 1.6.0_16-b01)
JBoss AS 7.1.1.Final |
||
| Rank: | 0|i001hj: |
| i2b2 Feature/s: |
Queries - Large
|
| i2b2 Sponsored Project/s: |
i2b2 Core
|
| Affects Database/s: |
Oracle
|
| Affects Web Browser/s: |
All Web Browsers
|
| Developer Notes: | Development done by Mike Mendis |
| Testing Notes: | Test Date: 04/10/2015
Build Number: Test Status: Passed Test Comments: Tested with the latest web client build and it appears to be working correctly. The query is now running to completion and the status in Previous Queries is being updated correctly. Clients Tested : i2b2 Web Client Environments Tested : Browsers: Not applicable for this test Databases: SQL Server and Oracle Client OS: Mac OS and Windows ++++++++++++++++++++++++++++++++++++++++++++++++++++++++ Test Date: 04/09/2015 Build Number: Test Status: Failed Test Comments: Tested with the latest web client build and it is not working correctly. The query never finishes running. It stays in a processing state. It will go from the small to medium queue but it does not appear to go from the medium to large queue. It remains in the medium queue and is never updated with an end date. Clients Tested : i2b2 Web Client Environments Tested : Browsers: Not applicable for this test Databases: SQL Server and Oracle Client OS: Mac OS and Windows |
| Participant/s: |
| Description |
|
When moving from small to medium queue, the thread processing the query is interrupted (edu.harvard.i2b2.crc.ejb.QueryManagerBeanUtil:234). The interruptedException is being caught by the jboss jdbc adapters (BaseWrapperManagedConnection.tryLock(BaseWrapperManagedConnection.java:384)) upon any calls to the database and throwing a general sqlexception (java.sql.SQLException: Interrupted attempting lock).
The below error is shown in the logs (and additional related errors upon calls to clean up the temporary tables, etc.). The query never finishes, and shows a processing in the database. As a temporary fix, we've commented out the t.interrupt() call without any ill effects. 09:01:57,048 INFO [stdout] (Thread-203) insert into i2b2data.DX ( patient_num ) select * from ( select distinct patient_num from i2b2data.QUERY_GLOBAL_TEMP where panel_count = 1 ) q 09:06:50,376 ERROR [edu.harvard.i2b2.crc.dao.CRCDAO] (Thread-203) Error while executing sql: java.sql.SQLException: Interrupted attempting lock: org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@998944 at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.tryLock(BaseWrapperManagedConnection.java:384) at org.jboss.jca.adapters.jdbc.WrappedConnection.lock(WrappedConnection.java:146) at org.jboss.jca.adapters.jdbc.WrappedStatement.lock(WrappedStatement.java:110) at org.jboss.jca.adapters.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:359) at edu.harvard.i2b2.crc.dao.setfinder.QueryExecutorHelperDao.executeQuery(QueryExecutorHelperDao.java:309) [CRC-core.jar:] at edu.harvard.i2b2.crc.dao.setfinder.QueryExecutorDao.executeSQL(QueryExecutorDao.java:320) [CRC-core.jar:] at edu.harvard.i2b2.crc.ejb.ExecRunnable.processQueryRequest(ExecRunnable.java:469) [CRC-core.jar:] at edu.harvard.i2b2.crc.ejb.ExecRunnable.run(ExecRunnable.java:184) [CRC-core.jar:] at java.lang.Thread.run(Thread.java:744) [rt.jar:1.7.0_51] |
| Comments |
| Comment by Nathan Graham [ 10/Feb/15 ] |
|
We just ran in to this issue at KUMC as well. I applied Michael's temporary fix and it seems to work in at least one case.
Michael's workaround really helped us out with an urgent data request! Thanks Michael! |
| Comment by Michael Horvath [ 10/Feb/15 ] |
|
Glad that it could be of some use. We still occasionally see issues that I think are related do to the poor nature of my "fix", that end up requiring a restart of the jboss server. I think the long term response would be to catch the SQLException on any calls to the jdbc library, and check for an interruptedException as the cause, then rethrow the interrupt.
See https://github.com/swaldman/c3p0/issues/37 and https://issues.apache.org/bugzilla/show_bug.cgi?id=52066 It's a real nuisance that the jdbc library is swallowing the exception, but at least they're providing a way out be encapsulating it in an sqlexception. |
| Comment by Janice Donahoe [ 09/Apr/15 ] |
| See testing notes for more information on why the issue is reopened. |
| Comment by Janice Donahoe [ 12/May/15 ] |
| Version 1.7.05 of the i2b2 Software has been released and is available for download on the i2b2 website (http://www.i2b2.org/software). |
| Comment by Michael Horvath [ 10/Jun/15 ] |
|
I am still seeing this issue in 1.7.05 when a query tries to move into the medium queue.
2015-06-10 15:07:32,110 ERROR [edu.harvard.i2b2.crc.dao.CRCDAO] (Thread-141) Error while executing sql: java.sql.SQLException: IJ031013: Interrupted attempting lock: org.jboss.jca.adapters.jdbc.local.LocalManagedConnection@5df04a03 at org.jboss.jca.adapters.jdbc.BaseWrapperManagedConnection.tryLock(BaseWrapperManagedConnection.java:409) at org.jboss.jca.adapters.jdbc.WrappedConnection.lock(WrappedConnection.java:149) at org.jboss.jca.adapters.jdbc.WrappedStatement.lock(WrappedStatement.java:114) at org.jboss.jca.adapters.jdbc.WrappedStatement.executeUpdate(WrappedStatement.java:363) at edu.harvard.i2b2.crc.dao.setfinder.QueryExecutorHelperDao.executeQuery(QueryExecutorHelperDao.java:309) at edu.harvard.i2b2.crc.dao.setfinder.QueryExecutorDao.executeSQL(QueryExecutorDao.java:320) at edu.harvard.i2b2.crc.ejb.ExecRunnable.processQueryRequest(ExecRunnable.java:469) at edu.harvard.i2b2.crc.ejb.ExecRunnable.run(ExecRunnable.java:184) at java.lang.Thread.run(Thread.java:744) Can consistently replicate by setting the small_queue timeout to 2s (modifying the thinClientName:'queryTimeout' key/value pair of js-i2b2/cells/CRC/cell_config_data.js in the webclient) and running a simple query. |
| Comment by Tom Morris [ 23/Jul/15 ] |
| From memory, the core issue is that there's a bug in the logging code of the exception handler for the SQL processing. The "interrupted" exception goes through this path, but any other SQL error will as well. While disabling the interrupt call will handle the common case of queue timeout, any other SQL error will trigger the same behavior with all queue processing dying, requiring the server to be restarted. |
| Comment by Janice Donahoe [ 18/Aug/15 ] |
|
The fix for this issue was included in the 1.7.06 release.
i2b2 version 1.7.06 was released on August 12, 2015. |
| Comment by George Kowalski [ 23/Jan/16 ] |
| Should we still be seeing this error in 1.7.06 with Jobs going from the Medium to Long queue ? If so is there any effect on the i2b2 instance or does it function "Normally" ? Our instance is having issues where long running queries just never return , showing up as "PROCESSING". Sometimes they do so and there are result counts in the QT_QUERY_MASTER table ... |
| Comment by Hubert Hickman [ 10/Nov/16 ] |
| This bug still seems to happen both in 1.7.07 and 1.7.08 when jobs initially timeout and go into the medium queue. I'll enter another ticket to open it back up but noting here in cause it is the same issue. |