Ok, below is the log output for the first two compresses. Running select
right before the first compress showed no locks so I included the output
for the second compress as that was more interesting, though the
transaction ids don't match. I removed a bunch of normal qpid data flow
logging stuff to shorten the output for clarity, and I formatted the locks
printout to hopefully be more readable.
-------------------------------------
2022-09-30T20:48:32,186Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - connection.getAutoCommit() is false
2022-09-30T20:48:32,186Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - Running select from lock table
2022-09-30T20:48:32,259Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - Locks are:
2022-09-30T20:48:32,260Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - Compressing qpid_queue_entries
2022-09-30T20:48:52,554Z ERROR [IO-/147.18.139.60:45964]
(o.a.q.s.d.DerbyRepackingMessageStore) - Failed to enqueue messages
java.sql.SQLTransactionRollbackException: A lock could not be obtained due
to a deadlock, cycle of locks and waiters is:
Lock : TABLE, QPID_QUEUE_ENTRIES, Tablelock
Waiting XID : {627716261, IX} , APP, INSERT INTO QPID_QUEUE_ENTRIES
(queue_id, message_id) values (?,?)
Granted XID : {627715588, X}
Lock : ROW, SYSCONGLOMERATES, (7,6)
Waiting XID : {627715588, X} , APP, alter table
"APP"."QPID_QUEUE_ENTRIES" compress
Granted XID : {627715588, S} , {627716262, S} , {627716261, S}
. The selected victim is XID : 627716261.
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:100)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:230)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:431)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:360)
at
org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2405)
at
org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:88)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(EmbedPreparedStatement.java:152)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement42.<init>(EmbedPreparedStatement42.java:41)
at
org.apache.derby.iapi.jdbc.Driver42.newEmbedPreparedStatement(Driver42.java:56)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1740)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1568)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore.enqueueMessages(AbstractJDBCMessageStore.java:684)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore.access$700(AbstractJDBCMessageStore.java:81)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$JDBCTransaction.lambda$new$0(AbstractJDBCMessageStore.java:1226)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$JDBCTransaction.doPreCommitActions(AbstractJDBCMessageStore.java:1289)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$JDBCTransaction.commitTranAsync(AbstractJDBCMessageStore.java:1278)
at
org.apache.qpid.server.txn.AsyncAutoCommitTransaction.enqueue(AsyncAutoCommitTransaction.java:294)
at org.apache.qpid.server.message.RoutingResult.send(RoutingResult.java:124)
at
org.apache.qpid.server.protocol.v1_0.NodeReceivingDestination.send(NodeReceivingDestination.java:117)
2022-09-30T20:49:12,632Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - Running select from lock table
2022-09-30T20:49:12,644Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - Locks are:
627716294 TABLE IX QPID_MESSAGE_CONTENT Tablelock
GRANT T 2 null
627716294 ROW X QPID_MESSAGE_METADATA (118,8)
GRANT T 1 null
627716294 ROW X QPID_QUEUE_ENTRIES (96,32)
GRANT T 1 null
627716294 TABLE IX QPID_QUEUE_ENTRIES Tablelock
GRANT T 2 null
627716285 TABLE IX QPID_MESSAGE_METADATA Tablelock
GRANT T 2 null
627716294 TABLE IX QPID_MESSAGE_METADATA Tablelock
GRANT T 2 null
627716285 ROW X QPID_MESSAGE_METADATA (150,13)
GRANT T 2 null
627716294 ROW X QPID_MESSAGE_CONTENT (81,85)
GRANT T 1 null
2022-09-30T20:49:12,644Z INFO [RepackTimer]
(o.a.q.s.d.DerbyRepackingMessageStore) - Compressing qpid_message_metadata
2022-09-30T20:49:32,682Z ERROR [IO-/147.18.139.173:44710]
(o.a.q.s.u.ServerScopedRuntimeException) - Exception on enqueuing message
into message store25904045
java.sql.SQLTransactionRollbackException: A lock could not be obtained due
to a deadlock, cycle of locks and waiters is:
Lock : TABLE, QPID_MESSAGE_METADATA, Tablelock
Waiting XID : {627716335, IX} , APP, INSERT INTO QPID_MESSAGE_METADATA(
message_id , meta_data ) values (?, ?)
Granted XID : {627716296, X}
Lock : ROW, SYSCONGLOMERATES, (7,8)
Waiting XID : {627716296, X} , APP, alter table
"APP"."QPID_MESSAGE_METADATA" compress
Granted XID : {627716296, S} , {627716335, S}
. The selected victim is XID : 627716335.
at
org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:100)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:230)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:431)
at
org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:360)
at
org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2405)
at
org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:88)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(EmbedPreparedStatement.java:152)
at
org.apache.derby.impl.jdbc.EmbedPreparedStatement42.<init>(EmbedPreparedStatement42.java:41)
at
org.apache.derby.iapi.jdbc.Driver42.newEmbedPreparedStatement(Driver42.java:56)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1740)
at
org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(EmbedConnection.java:1568)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore.storeMetaData(AbstractJDBCMessageStore.java:981)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore.access$1200(AbstractJDBCMessageStore.java:81)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$StoredJDBCMessage.store(AbstractJDBCMessageStore.java:1635)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$JDBCTransaction.lambda$enqueueMessage$1(AbstractJDBCMessageStore.java:1240)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$JDBCTransaction.doPreCommitActions(AbstractJDBCMessageStore.java:1289)
at
org.apache.qpid.server.store.jdbc.AbstractJDBCMessageStore$JDBCTransaction.commitTranAsync(AbstractJDBCMessageStore.java:1278)
at
org.apache.qpid.server.txn.AsyncAutoCommitTransaction.enqueue(AsyncAutoCommitTransaction.java:294)
at org.apache.qpid.server.message.RoutingResult.send(RoutingResult.java:124)
On Fri, Sep 30, 2022 at 2:46 PM Rick Hillegas <rick.hille...@gmail.com>
wrote:
I don't have any theories yet about what is going on. Can you try
issuing the following statement just before you compress the table:
SELECT * FROM SYSCS_DIAG.LOCK_TABLE;
I don't understand why the INSERT transaction grabs a lock on a
SYSCONGLOMERATES row.
Thanks,
-Rick
On 9/29/22 1:24 PM, Nathan Jensen wrote:
Thanks for the response! To clarify a few things, we're using Derby
10.15.2.0 and Java 11. Our project is sticking with Java 11 for the time
being so I can't upgrade to Derby 10.16 at this time. The version of
Qpid
we're using at present is 7.1.12.
I don't see anything suspicious regarding the INSERT statement, but maybe
you could see something that I don't. I believe the relevant code is
here:
https://github.com/apache/qpid-broker-j/blob/7.1.12/broker-plugins/jdbc-store/src/main/java/org/apache/qpid/server/store/jdbc/AbstractJDBCMessageStore.java#L675
That does not commit the transaction, the transaction is committed
elsewhere in the same file, here:
https://github.com/apache/qpid-broker-j/blob/7.1.12/broker-plugins/jdbc-store/src/main/java/org/apache/qpid/server/store/jdbc/AbstractJDBCMessageStore.java#L1264
I should also note that one time I saw the deadlock happen with a DELETE
statement instead of an INSERT, so I don't think the unexpected row
locking
in SYSCONGLOMERATES is limited to INSERT.
Here is the DDL as produced by Derby's dblook:
-- ----------------------------------------------
-- DDL Statements for tables
-- ----------------------------------------------
CREATE TABLE "APP"."QPID_QUEUE_ENTRIES" ("QUEUE_ID" VARCHAR(36) NOT NULL,
"MESSAGE_ID" BIGINT NOT NULL);
CREATE TABLE "APP"."QPID_MESSAGE_CONTENT" ("MESSAGE_ID" BIGINT NOT NULL,
"CONTENT" BLOB(2147483647));
CREATE TABLE "APP"."QPID_XID_ACTIONS" ("FORMAT" BIGINT NOT NULL,
"GLOBAL_ID" VARCHAR (64) FOR BIT DATA NOT NULL, "BRANCH_ID" VARCHAR (64)
FOR BIT DATA NOT NULL, "ACTION_TYPE" CHAR(1) NOT NULL, "QUEUE_ID"
VARCHAR(36) NOT NULL, "MESSAGE_ID" BIGINT NOT NULL);
CREATE TABLE "APP"."AMQP_1_0_LINKS" ("LINK_KEY" VARCHAR(44) NOT NULL,
"REMOTE_CONTAINER_ID" BLOB(2147483647), "LINK_NAME" BLOB(2147483647),
"LINK_ROLE" INTEGER, "SOURCE" BLOB(2147483647), "TARGET"
BLOB(2147483647));
CREATE TABLE "APP"."QPID_MESSAGE_METADATA" ("MESSAGE_ID" BIGINT NOT NULL,
"META_DATA" BLOB(2147483647));
CREATE TABLE "APP"."QPID_DB_VERSION" ("VERSION" INTEGER NOT NULL);
CREATE TABLE "APP"."QPID_XIDS" ("FORMAT" BIGINT NOT NULL, "GLOBAL_ID"
VARCHAR (64) FOR BIT DATA NOT NULL, "BRANCH_ID" VARCHAR (64) FOR BIT DATA
NOT NULL);
CREATE TABLE "APP"."AMQP_1_0_LINKS_VERSION" ("VERSION" VARCHAR(10) NOT
NULL, "VERSION_TIME" TIMESTAMP);
-- ----------------------------------------------
-- DDL Statements for keys
-- ----------------------------------------------
-- PRIMARY/UNIQUE
ALTER TABLE "APP"."AMQP_1_0_LINKS" ADD CONSTRAINT
"SQL0000000086-b2280141-0183-5b33-aec6-000016c47528" PRIMARY KEY
("LINK_KEY");
ALTER TABLE "APP"."QPID_MESSAGE_METADATA" ADD CONSTRAINT
"SQL0000000082-e333810d-0183-5b33-aec6-000016c47528" PRIMARY KEY
("MESSAGE_ID");
ALTER TABLE "APP"."QPID_QUEUE_ENTRIES" ADD CONSTRAINT
"SQL0000000081-61228105-0183-5b33-aec6-000016c47528" PRIMARY KEY
("QUEUE_ID", "MESSAGE_ID");
ALTER TABLE "APP"."QPID_XID_ACTIONS" ADD CONSTRAINT
"SQL0000000085-69c68125-0183-5b33-aec6-000016c47528" PRIMARY KEY
("FORMAT",
"GLOBAL_ID", "BRANCH_ID", "ACTION_TYPE", "QUEUE_ID", "MESSAGE_ID");
ALTER TABLE "APP"."QPID_XIDS" ADD CONSTRAINT
"SQL0000000084-e785811d-0183-5b33-aec6-000016c47528" PRIMARY KEY
("FORMAT",
"GLOBAL_ID", "BRANCH_ID");
ALTER TABLE "APP"."QPID_MESSAGE_CONTENT" ADD CONSTRAINT
"SQL0000000083-65548115-0183-5b33-aec6-000016c47528" PRIMARY KEY
("MESSAGE_ID");
ALTER TABLE "APP"."AMQP_1_0_LINKS_VERSION" ADD CONSTRAINT
"SQL0000000087-5555c14b-0183-5b33-aec6-000016c47528" PRIMARY KEY
("VERSION");
And just in case I'm doing something stupid, here is the current version
of
my code. conn.getAutoCommit() is false, but I also tried it with an
autocommit connection and without the commit statements that time. The
code is inside a try-catch-finally that is inside a TimerTask.
conn = newConnection();
LOGGER.info("connection.getAutoCommit() is " + conn.getAutoCommit());
LOGGER.info("Compressing qpid_queue_entries");
conn.prepareStatement("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE('APP',
'QPID_QUEUE_ENTRIES', 0)").executeUpdate();
conn.commit();
LOGGER.info("Compressing qpid_message_metadata");
conn.prepareStatement("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE('APP',
'QPID_MESSAGE_METADATA', 0)").executeUpdate();
conn.commit();
LOGGER.info("Compressing qpid_message_content");
conn.prepareStatement("call SYSCS_UTIL.SYSCS_COMPRESS_TABLE('APP',
'QPID_MESSAGE_CONTENT', 0)").executeUpdate();
conn.commit();
Thanks for any help you can provide!
On Thu, Sep 29, 2022 at 1:28 PM Rick Hillegas <rick.hille...@gmail.com>
wrote:
I'm not an expert on the table compression code, but it does need an
overhaul (see https://issues.apache.org/jira/browse/DERBY-3683).
If I'm interpreting the error correctly, the table compressor is blocked
trying to escalate its lock on the SYSCONGLOMERATES row from shared to
exclusive. But it can't do this because the INSERT transaction holds a
shared lock on the SYSCONGLOMERATES row. I don't understand why the
INSERT
transaction would need to lock a SYSCONGLOMERATES row. The following
simple
experiment shows that, by itself, a simple INSERT should not lock any
rows
in SYSCONGLOMERATES:
ij version 10.17
ij> CONNECT 'jdbc:derby:memory:db;create=true';
ij> AUTOCOMMIT OFF;
ij> CREATE TABLE t(a INT);
0 rows inserted/updated/deleted
ij> CREATE INDEX t_idx ON t(a);
0 rows inserted/updated/deleted
ij> CREATE TABLE s(a INT);
0 rows inserted/updated/deleted
ij> INSERT INTO s VALUES (1);
1 row inserted/updated/deleted
ij> COMMIT;
ij> INSERT INTO t SELECT * FROM s;
1 row inserted/updated/deleted
ij> SELECT * FROM SYSCS_DIAG.LOCK_TABLE;
XID |TYPE |MODE|TABLENAME
|LOCKNAME |STATE|TABLETYPE|LOCK&|INDEXNAME
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
186 |TABLE|IX |T
|Tablelock |GRANT|T |2 |NULL
186 |ROW |X |T
|(1,7) |GRANT|T |1 |NULL
2 rows selected
ij> COMMIT;
ij> SELECT * FROM SYSCS_DIAG.LOCK_TABLE;
XID |TYPE |MODE|TABLENAME
|LOCKNAME |STATE|TABLETYPE|LOCK&|INDEXNAME
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
0 rows selected
Is there anything else going on in the INSERT transaction? Can you share
the table DDL with us, including indexes, constraints, auto-generated
columns, etc.?
-Rick
On 9/28/22 2:12 PM, Nathan Jensen wrote:
Hi, we are using Derby as the backing message store for Qpid-Broker-J.
We
have a continuous data flow into Qpid so each message gets persisted to
the
Derby message store as data comes in and then it is deleted from the
Derby
message store as data is picked up and processed. The data flow is
pretty
constant, there are peaks and valleys but basically data is always
coming
in so there are LOTS of inserts and deletes. Over time we found that
the
Derby message store fills up the disk drive until it runs out of space
and
in general the workaround to that has been to stop Qpid and remove the
message store (i.e. the Derby directory), which loses data.
My attempted solution to this was to extend Qpid's DerbyMessageStore
with a
DerbyRepackingMessageStore that executes the
SYSCS_UTIL.SYSCS_COMPRESS_TABLE procedure based on a timer. However,
on a
test system with flowing data, this always has a deadlock exception and
some data (the aborted transaction) is lost. An example is:
Caused by: org.apache.derby.shared.common.error.StandardException: A
lock
could not be obtained due to a deadlock, cycle of locks and waiters is:
Lock : TABLE, QPID_MESSAGE_METADATA, Tablelock
Waiting XID : {501214885, IX} , APP, INSERT INTO
QPID_MESSAGE_METADATA(
message_id , meta_data ) values (?, ?)
Granted XID : {501214829, X}
Lock : ROW, SYSCONGLOMERATES, (7,8)
Waiting XID : {501214829, X} , APP, alter table
"APP"."QPID_MESSAGE_METADATA" compress
Granted XID : {501214829, S} , {501214865, S} , {501214885, S}
. The selected victim is XID : 501214885.
at
org.apache.derby.shared.common.error.StandardException.newException(StandardException.java:300)
at
org.apache.derby.shared.common.error.StandardException.newException(StandardException.java:295)
at
org.apache.derby.impl.services.locks.Deadlock.buildException(Deadlock.java:557)
at
org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(ConcurrentLockSet.java:647)
My understanding of that is that the deadlock is occurring because the
insert has a shared lock on the sysconglomerates row and wants an
exclusive
lock on the qpid_message_metadata table, while the compress has an
exclusive lock on the qpid_message_metadata table and wants an exclusive
lock on the sysconglomerates row, so they block each other.
I found this thread from May of 2009 which had a similar issue:
https://lists.apache.org/thread/b8p7kzcc0clo45o2drs5rttsx5gqq49f I would
expect the compress command to go for the lock(s), wait until it gets
the
lock(s), then block the other threads and do the compress. But it
deadlocks instead.
Based on this ticket, https://issues.apache.org/jira/browse/DERBY-3683,
I
tried using a non-autocommit connection and locking the table
exclusively
before calling compress and then commit, but that got the same errors.
Based on this thread,
https://lists.apache.org/thread/38qg7nkqolssc1jhdkhgnrl7vbkwq0vw, I tried
the in place compress and it succeeds without deadlock. However, it is
significantly slower, too slow to be a workable solution for my use case
and it also doesn't return as much space to the operating system.
Does this look like a Derby bug where the compress command will
deadlock if
there are inserts happening at roughly the same time? Or is this
expected? Do both the inserts and compress need a sysconglomerates row
lock? Is there a way the compress command could get both its locks at
the
same time to avoid the deadlock?
