You are viewing a plain text version of this content. The canonical link for it is here.
Posted to derby-user@db.apache.org by Svata Dedic <ga...@volny.cz> on 2008/04/16 22:15:24 UTC
Deadlock when getting DB metadata
Hello,
I am new to this list - so please accept my apologies if I ask something
well known (I did a keyword google/list search with no reasonable results)
I have the following issue: my code changes DB structure (create a
column), then immediately after setting autocommit back to true, the
code rescans the DB metadata
DatabaseMetaData.getColumns(catalog, schemaName, tableName, null);
I am sometimes getting a deadlock with these operations:
2008-04-16 19:50:47.833 GMT Thread[Default RequestProcessor,1,system]
(XID = 569844), (SESSIONID = 2), (DATABASE =
/..../a3/.config/localdb/db), (DRDAID = null), Cleanup action starting
2008-04-16 19:50:47.833 GMT Thread[Default RequestProcessor,1,system]
(XID = 569844), (SESSIONID = 2), (DATABASE =
/..../IJCProjects/a3/.config/localdb/db), (DRDAID = null), Failed
Statement is: EXECUTE STATEMENT SYS."getColumns"
ERROR 40XL2: A lock could not be obtained within the time requested.
The lockTable dump is:
2008-04-16 19:50:47.796 GMT
XID |TYPE |MODE|LOCKCOUNT|LOCKNAME
|STATE|TABLETYPE /
LOCKOBJ |INDEXNAME / CONTAINER_ID / (MODE for LATCH
only) |TABLENAME / CONGLOM_ID |
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
*** The following row is the victim ***
569852 |ROW |X |0 |(44,7)
|WAIT |S
|NULL
|SYSSTATEMENTS |
*** The above row is the victim ***
the stacktrace of the operation causing the deadlock is
at
org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at
org.apache.derby.impl.services.locks.Timeout.createException(Unknown Source)
at
org.apache.derby.impl.services.locks.Timeout.buildException(Unknown Source)
at
org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown
Source)
at
org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
at
org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown
Source)
at
org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown
Source)
at
org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown
Source)
at
org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown
Source)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown
Source)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown
Source)
at
org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown
Source)
at
org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown
Source)
at
org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(Unknown Source)
at
org.apache.derby.impl.sql.catalog.TabInfoImpl.updateRow(Unknown Source)
at
org.apache.derby.impl.sql.catalog.TabInfoImpl.updateRow(Unknown Source)
at
org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateSPS(Unknown
Source)
at
org.apache.derby.iapi.sql.dictionary.SPSDescriptor.updateSYSSTATEMENTS(Unknown
Source)
at
org.apache.derby.iapi.sql.dictionary.SPSDescriptor.getPreparedStatement(Unknown
Source)
at
org.apache.derby.iapi.sql.dictionary.SPSDescriptor.getPreparedStatement(Unknown
Source)
at
org.apache.derby.impl.sql.compile.ExecSPSNode.generate(Unknown Source)
at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown
Source)
at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown
Source)
at
org.apache.derby.impl.sql.GenericPreparedStatement.rePrepare(Unknown Source)
at
org.apache.derby.impl.sql.GenericPreparedStatement.execute(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.executeQuery(Unknown
Source)
at
org.apache.derby.impl.jdbc.EmbedDatabaseMetaData.doGetCols(Unknown Source)
at
org.apache.derby.impl.jdbc.EmbedDatabaseMetaData.getColumns(Unknown Source)
I am quite positive that, at the time, no other threads access the
database (and there are no pending DB operations on the threaddump while
waiting on the lock).
I've seen the deadlock occur during several get-metadata operations
(getImportedKeys, ...), each time waiting on the SYSSTATEMENTS
apparently because of internally constructed PreparedStatement.
Can anyone give me pointers how to solve or avoid these issues ? I am
able to reproduce this rather reliably, so any guidance what to test,
what to debug or log in order to pinpoint the bug would be most appreciated.
Thanks,
-Svata
Re: Deadlock when getting DB metadata
Posted by Tim Dudgeon <td...@informaticsmatters.com>.
Any ideas on this issue?
The problem seems to have been identified.
Does anyone have suggestions for a fix or workaround?
Tim
Svata Dedic wrote:
> Hi,
>
>> There is one workaround you may try out: Right after you have created
>> the database you can invoke DatabaseMetaData.getColumns() and any other
>> meta-data calls you expect to use. Then the internal meta-data queries
>> will be compiled and their execution plans stored in the database
>
> thanks for the hint - I debugged the application a little and noticed a
> strange thing. After the start, a series of begin/end/execute prepared
> statements is printed:
>
> ---------%<-----------------------%<--------------
> Begin compiling prepared statement: EXECUTE STATEMENT SYS."getColumns"
> :End prepared statement
> End compiling prepared statement: EXECUTE STATEMENT SYS."getColumns"
> :End prepared statement
>
> Executing prepared statement: EXECUTE STATEMENT SYS."getColumns" :End
> prepared statement with 4 parameters begin parameter #1: % :end
> parameter begin parameter #2: APP :end parameter begin parameter #3:
> XXXXX :end parameter begin parameter #4: % :end parameter
> ---------%<-----------------------%<--------------
>
> When the deadlock occurs, the "real" SQL into systables is beign
> compiled (I traced this sql to be the value of "getColumns" key in
> org/apache/derby/impl/jdbc/metadata.properties file):
> ---------%<-----------------------%<--------------
> Begin compiling prepared statement: SELECT CAST ('' AS VARCH
> AR(128)) AS PKTABLE_CAT, S.SCHEMANAME AS PKTABLE_SCHEM, TABLENAME AS
> PKTABLE_NAME, COLS.COLUMNNAME AS PKCOLUMN_NAME, CAS
> T ('' AS VARCHAR(128)) AS FKTABLE_CAT, FKTABLE_SCHEM, FKTABLE_NAME,
> FKCOLUMN_NAME, CAST ...
> ---------%<-----------------------%<--------------
>
> For some reason, isUpToDate() on the getColumns() statement becomes
> false and the statement is recompiled.
>
> So - doing all queries at the start does not help: they are recompiled
> during the DB usage anyways :-/
>
> Any other idea for workaround or fix ?
>
> Thanks for all the help so far,
> -Svata
>
> Dag H. Wanvik wrote:
>> Svata Dedic <ga...@volny.cz> writes:
>>
>>> Is there a logger I can enable to see exact statements being compiled
>>> internally ? I would like to verify the above, or at least discover
>>> which type of commands are executed.
>> You can enable trace with this setting in derby.properties:
>>
>> derby.language.logStatementText=true
>>
>> You can find the trace in derby.log.
>>
>> Dag
>>
>>
>>
>
Re: Deadlock when getting DB metadata
Posted by Svata Dedic <ga...@volny.cz>.
Hi,
> There is one workaround you may try out: Right after you have created
> the database you can invoke DatabaseMetaData.getColumns() and any other
> meta-data calls you expect to use. Then the internal meta-data queries
> will be compiled and their execution plans stored in the database
thanks for the hint - I debugged the application a little and noticed a
strange thing. After the start, a series of begin/end/execute prepared
statements is printed:
---------%<-----------------------%<--------------
Begin compiling prepared statement: EXECUTE STATEMENT SYS."getColumns"
:End prepared statement
End compiling prepared statement: EXECUTE STATEMENT SYS."getColumns"
:End prepared statement
Executing prepared statement: EXECUTE STATEMENT SYS."getColumns" :End
prepared statement with 4 parameters begin parameter #1: % :end
parameter begin parameter #2: APP :end parameter begin parameter #3:
XXXXX :end parameter begin parameter #4: % :end parameter
---------%<-----------------------%<--------------
When the deadlock occurs, the "real" SQL into systables is beign
compiled (I traced this sql to be the value of "getColumns" key in
org/apache/derby/impl/jdbc/metadata.properties file):
---------%<-----------------------%<--------------
Begin compiling prepared statement: SELECT CAST ('' AS VARCH
AR(128)) AS PKTABLE_CAT, S.SCHEMANAME AS PKTABLE_SCHEM, TABLENAME AS
PKTABLE_NAME, COLS.COLUMNNAME AS PKCOLUMN_NAME, CAS
T ('' AS VARCHAR(128)) AS FKTABLE_CAT, FKTABLE_SCHEM, FKTABLE_NAME,
FKCOLUMN_NAME, CAST ...
---------%<-----------------------%<--------------
For some reason, isUpToDate() on the getColumns() statement becomes
false and the statement is recompiled.
So - doing all queries at the start does not help: they are recompiled
during the DB usage anyways :-/
Any other idea for workaround or fix ?
Thanks for all the help so far,
-Svata
Dag H. Wanvik wrote:
> Svata Dedic <ga...@volny.cz> writes:
>
>> Is there a logger I can enable to see exact statements being compiled
>> internally ? I would like to verify the above, or at least discover
>> which type of commands are executed.
>
> You can enable trace with this setting in derby.properties:
>
> derby.language.logStatementText=true
>
> You can find the trace in derby.log.
>
> Dag
>
>
>
Re: Deadlock when getting DB metadata
Posted by "Dag H. Wanvik" <Da...@Sun.COM>.
Svata Dedic <ga...@volny.cz> writes:
> Is there a logger I can enable to see exact statements being compiled
> internally ? I would like to verify the above, or at least discover
> which type of commands are executed.
You can enable trace with this setting in derby.properties:
derby.language.logStatementText=true
You can find the trace in derby.log.
Dag
Re: Deadlock when getting DB metadata
Posted by Svata Dedic <ga...@volny.cz>.
Knut Anders Hatlen wrote:
> There is one workaround you may try out: Right after you have created
> the database you can invoke DatabaseMetaData.getColumns() and any other
> meta-data calls you expect to use. Then the internal meta-data queries
> will be compiled and their execution plans stored in the database, so
> that you don't need to compile them at the point where you now see the
> deadlock. It is the (internal) compilation of the meta-data queries that
> causes the deadlock.
>
The application attempts to read the DB schema right after it connects
to the database. Then, after DB schema change operation, it re-reads
some tables/indexes/foreign keys to keep the 'mental image' up-to-date,
using the same code (although limited to scan just some table(s) metadata).
In this situation, the DB already contained some tables when the app
started, so statements to discover exported/imported FKs, indexes,
column and table definitions were already processed and compiled at the
start, long before the operation that caused the deadlock was executed.
Is there a logger I can enable to see exact statements being compiled
internally ? I would like to verify the above, or at least discover
which type of commands are executed.
Thanks,
-Svata
Re: Deadlock when getting DB metadata
Posted by Knut Anders Hatlen <Kn...@Sun.COM>.
Svata Dedic <ga...@volny.cz> writes:
> Knut Anders Hatlen wrote:
>> Svata Dedic <ga...@volny.cz> writes:
>>
>>> Can anyone give me pointers how to solve or avoid these issues ? I am
>>> able to reproduce this rather reliably, so any guidance what to test,
>>> what to debug or log in order to pinpoint the bug would be most appreciated.
>>>
>> hile
>> before it successfully continues, but the deadlock may still be logged
>> in derby.log. That bug is tracked here:
>> https://issues.apache.org/jira/browse/DERBY-177
>>
> Thanks. Yes, indeed the operation completes successfully, but the delay
> has deadly impact on user experience with the application.
>
> The issue #177 talks about transactions and subtransactions (spawned
> internally by the statement compilations) - in my case, there should be
> no outer transaction (autocommit = on) at the time metadata is
> requested. Dumb question: does the issue apply even to this scenario
> (DatabaseMetadata called without turning autocommit to false) ?
Hi Svata,
Yes, the issue applies since you also have transactions when auto-commit
is turned on. The difference between auto-commit on and auto-commit off
isn't whether or not you have transactions, but whether or not the
transactions are automatically committed when a statement is completed.
There is one workaround you may try out: Right after you have created
the database you can invoke DatabaseMetaData.getColumns() and any other
meta-data calls you expect to use. Then the internal meta-data queries
will be compiled and their execution plans stored in the database, so
that you don't need to compile them at the point where you now see the
deadlock. It is the (internal) compilation of the meta-data queries that
causes the deadlock.
--
Knut Anders
Re: Deadlock when getting DB metadata
Posted by Svata Dedic <ga...@volny.cz>.
Knut Anders Hatlen wrote:
> Svata Dedic <ga...@volny.cz> writes:
>
>> Can anyone give me pointers how to solve or avoid these issues ? I am
>> able to reproduce this rather reliably, so any guidance what to test,
>> what to debug or log in order to pinpoint the bug would be most appreciated.
>>
> hile
> before it successfully continues, but the deadlock may still be logged
> in derby.log. That bug is tracked here:
> https://issues.apache.org/jira/browse/DERBY-177
>
Thanks. Yes, indeed the operation completes successfully, but the delay
has deadly impact on user experience with the application.
The issue #177 talks about transactions and subtransactions (spawned
internally by the statement compilations) - in my case, there should be
no outer transaction (autocommit = on) at the time metadata is
requested. Dumb question: does the issue apply even to this scenario
(DatabaseMetadata called without turning autocommit to false) ?
Thanks for the response,
-Svata
Re: Deadlock when getting DB metadata
Posted by Knut Anders Hatlen <Kn...@Sun.COM>.
Svata Dedic <ga...@volny.cz> writes:
> Hello,
>
> I am new to this list - so please accept my apologies if I ask something
> well known (I did a keyword google/list search with no reasonable results)
>
> I have the following issue: my code changes DB structure (create a
> column), then immediately after setting autocommit back to true, the
> code rescans the DB metadata
> DatabaseMetaData.getColumns(catalog, schemaName, tableName, null);
>
[...]
> I am sometimes getting a deadlock with these operations:
> I am quite positive that, at the time, no other threads access the
> database (and there are no pending DB operations on the threaddump while
> waiting on the lock).
>
> I've seen the deadlock occur during several get-metadata operations
> (getImportedKeys, ...), each time waiting on the SYSSTATEMENTS
> apparently because of internally constructed PreparedStatement.
>
> Can anyone give me pointers how to solve or avoid these issues ? I am
> able to reproduce this rather reliably, so any guidance what to test,
> what to debug or log in order to pinpoint the bug would be most appreciated.
Do the deadlock exceptions propagate out to your code, or do you only
see them in derby.log? I know that there is some code in that area that
may cause internal deadlocks or timeouts, but it successfully recovers
from the errors and doesn't expose the exceptions to the users. When
that happens, you may experience that your application hangs for a while
before it successfully continues, but the deadlock may still be logged
in derby.log. That bug is tracked here:
https://issues.apache.org/jira/browse/DERBY-177
--
Knut Anders