I was about to send the following email asking for help. But then I
"solved" the problem I described below by setting enforceTableLocking
to false. My new question is, is that a reasonable approach? What
are the implications of that choice?
Thanks,
Chris
-------- original email --------
I'm trying to understand a problem I'm seeing in my application. I
don't know if it's something in my code or in how I'm using Sequoia.
I'm getting into a situation where my transactions get hung up and
have trouble completing. I'm hoping it's obvious what's happening by
looking at the logs which follow.
Environment: embedded Sequoia 2.10.8, embedded H2 databases using
MVCC, JGroups 2.5.1 with modification to SEQUENCER layer
(synchronizing down() as in http://jira.jboss.com/jira/browse/
JGRP-607)). One host with one controller with one virtual database
with one backend. RAIDb1_LPRF, WaitForCompletionPolicy.ALL,
enforceTableLocking=true. Calls to sequoia DataSource wrapped by
JGroups RPC layer.
In my test code, I'm spawning two threads that each get a connection,
turn autoCommit off, do an insert, and then try to commit. I never
see the commit on the first thread - my code eventually closes the
connection, which causes the transaction to get rolled back, and only
then do I see the commit from the other thread, which succeeds.
(It's also possible this is a problem with how we're using JGroups
for the RPC wrapping our calls on the Sequoia driver datasource -
maybe we're deadlocking by not being able to send the response to one
message because it's waiting for the other one to send.)
(thread 1) begin transaction 2
insert request (also a 2) broadcast
request removed from total order queue
request put in non-conflicting queue
request put in request queue
request completed
(thread 2) begin transaction 3
insert request 3 broadcast
request 3 waits for lock on table FOO([BAR])
request 3 put in conflicting queue
request 3 put in request queue
sits there until my code closes idle connection
transaction 2 rolled back since connection was closed
request 3 finishes
transaction 3 commits successfully
// next 3 lines from my code
2007-12-08 20:59:10,804 [TRACE] ClusterPartition execute()
partition=PartitionId:1, conn=10.0.1.6:58441:2, sql=insert into foo
(bar) values ( 0)
2007-12-08 20:59:10,805 [TRACE] ClusterPartition execute()
partition=PartitionId:1, conn=10.0.1.6:58441:3, sql=insert into foo
(bar) values ( 1)
2007-12-08 20:59:10,817 [TRACE] JdbcPartitionSource SQL execute()
[conn=10.0.1.6:58441:2] insert into foo (bar) values ( 0)
2007-12-08 20:59:10,818 [DEBUG] Controller Connection accepted for
localhost
2007-12-08 20:59:10,818 [DEBUG] Controller Starting new
ControllerWorkerThread
2007-12-08 20:59:10,818 [DEBUG] Controller Connection from localhost/
127.0.0.1:49577
2007-12-08 20:59:10,818 [DEBUG] Controller Notifying
VirtualDatabaseWorkerThread
2007-12-08 20:59:10,819 [DEBUG] p1 Login accepted for admin from
localhost/127.0.0.1
2007-12-08 20:59:10,819 [DEBUG] p1 Begin command
2007-12-08 20:59:10,820 [DEBUG] scheduler Begin scheduled - current
pending transactions: 1
2007-12-08 20:59:10,820 [DEBUG] scheduler Begin scheduled - current
pending writes: 1
2007-12-08 20:59:10,820 [DEBUG] p1 Begin transaction 2
2007-12-08 20:59:10,820 [DEBUG] scheduler Begin completed, remaining
pending writes: 0
2007-12-08 20:59:10,820 [INFO] p1 B 2
2007-12-08 20:59:10,820 [DEBUG] p1 statementExecute command
2007-12-08 20:59:10,822 [INFO] p1 W 2 2 insert into foo (bar) values
( 0)/
2007-12-08 20:59:10,822 [DEBUG] p1 Broadcasting request insert into
foo (bar) values ( 0)/ transaction 2 to all controllers (Member
(address=/10.0.1.6:58451, uid=SEQUOIA_p1)->[Member(address=/
10.0.1.6:58451, uid=SEQUOIA_p1)])
2007-12-08 20:59:10,839 [DEBUG] p1 handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedSt
atementExecuteUpdate): W 2 2 insert into foo (bar) values ( 0)/
2007-12-08 20:59:10,839 [DEBUG] p1 christopher-ekbergs-computer.local:
25322: Scheduling distributedRequest 2 from Member(address=/
10.0.1.6:58451, uid=SEQUOIA_p1)
2007-12-08 20:59:10,839 [INFO] p1 W 2 2 insert into foo (bar) values
( 0)/
2007-12-08 20:59:10,840 [DEBUG] p1 handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedSt
atementExecuteUpdate): W 2 2 insert into foo (bar) values ( 0)/
2007-12-08 20:59:10,840 [DEBUG] p1 christopher-ekbergs-computer.local:
25322: Executing distributedRequest 2 from Member(address=/
10.0.1.6:58451, uid=SEQUOIA_p1)
2007-12-08 20:59:10,840 [DEBUG] p1 Database schema is dirty,
refreshing it
2007-12-08 20:59:10,841 [DEBUG] p1 Scheduling write request (2):
insert into foo (bar) values ( 0)/
2007-12-08 20:59:10,841 [DEBUG] scheduler Schedule insert into foo
(bar) values ( 0)/ - Current pending writes: 1
2007-12-08 20:59:10,841 [DEBUG] p1 Load balancing write request
(2,2): insert into foo (bar) values ( 0)/
2007-12-08 20:59:10,841 [DEBUG] p1 Logging transaction 2 begin
2007-12-08 20:59:10,841 [DEBUG] loadbalancer Request 2 execute on 1
backends
2007-12-08 20:59:10,841 [DEBUG] loadbalancer Removed insert into foo
(bar) values ( 0)/ from total order queue
2007-12-08 20:59:10,842 [DEBUG] recoverylog Logging request 2
2007-12-08 20:59:10,842 [DEBUG] recoverylog prep412
2007-12-08 20:59:10,843 [DEBUG] recoverylog Logging request 3
2007-12-08 20:59:10,843 [DEBUG] recoverylog prep412
2007-12-08 20:59:10,843 [DEBUG] local Scheduling request insert into
foo (bar) values ( 0)/ in non conflicting queue
2007-12-08 20:59:10,843 [DEBUG] local Adding task
StatementExecuteUpdateTask from transaction 2 (insert into foo (bar)
values ( 0)/) to pending request queue
2007-12-08 20:59:10,843 [DEBUG] local Executing task
StatementExecuteUpdateTask from transaction 2 (insert into foo (bar)
values ( 0)/)
2007-12-08 20:59:10,844 [DEBUG] local Task StatementExecuteUpdateTask
from transaction 2 (insert into foo (bar) values ( 0)/) completed
2007-12-08 20:59:10,844 [DEBUG] scheduler Write completed, remaining
pending writes: 0
2007-12-08 20:59:10,846 [DEBUG] recoverylog Logging request 3
2007-12-08 20:59:10,846 [DEBUG] recoverylog prep421
2007-12-08 20:59:10,861 [DEBUG] p1 Request insert into foo (bar)
values ( 0)/ completed.
2007-12-08 20:59:10,861 [DEBUG] p1 Request 2 completed successfully.
// next line is from my code
2007-12-08 20:59:10,863 [TRACE] JdbcPartitionSource SQL execute()
[conn=10.0.1.6:58441:3] insert into foo (bar) values ( 1)
2007-12-08 20:59:10,863 [DEBUG] Controller Connection accepted for
localhost
2007-12-08 20:59:10,863 [DEBUG] Controller Connection from localhost/
127.0.0.1:49578
2007-12-08 20:59:10,864 [DEBUG] Controller Starting new
VirtualDatabaseWorkerThread
2007-12-08 20:59:10,864 [DEBUG] p1 Login accepted for admin from
localhost/127.0.0.1
2007-12-08 20:59:10,864 [DEBUG] p1 Begin command
2007-12-08 20:59:10,864 [DEBUG] scheduler Begin scheduled - current
pending transactions: 2
2007-12-08 20:59:10,865 [DEBUG] scheduler Begin scheduled - current
pending writes: 1
2007-12-08 20:59:10,865 [DEBUG] p1 Begin transaction 3
2007-12-08 20:59:10,865 [DEBUG] scheduler Begin completed, remaining
pending writes: 0
2007-12-08 20:59:10,865 [INFO] p1 B 3
2007-12-08 20:59:10,865 [DEBUG] p1 statementExecute command
2007-12-08 20:59:10,865 [INFO] p1 W 3 3 insert into foo (bar) values
( 1)/
2007-12-08 20:59:10,865 [DEBUG] p1 Broadcasting request insert into
foo (bar) values ( 1)/ transaction 3 to all controllers (Member
(address=/10.0.1.6:58451, uid=SEQUOIA_p1)->[Member(address=/
10.0.1.6:58451, uid=SEQUOIA_p1)])
// next line is from my code
2007-12-08 20:59:10,873 [TRACE] ClusterPartition txCommit()
partition=PartitionId:1, conn=10.0.1.6:58441:2
2007-12-08 20:59:10,881 [DEBUG] p1 handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedSt
atementExecuteUpdate): W 3 3 insert into foo (bar) values ( 1)/
2007-12-08 20:59:10,881 [DEBUG] p1 christopher-ekbergs-computer.local:
25322: Scheduling distributedRequest 3 from Member(address=/
10.0.1.6:58451, uid=SEQUOIA_p1)
2007-12-08 20:59:10,881 [INFO] p1 W 3 3 insert into foo (bar) values
( 1)/
2007-12-08 20:59:10,881 [DEBUG] p1 handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedSt
atementExecuteUpdate): W 3 3 insert into foo (bar) values ( 1)/
2007-12-08 20:59:10,881 [DEBUG] p1 christopher-ekbergs-computer.local:
25322: Executing distributedRequest 3 from Member(address=/
10.0.1.6:58451, uid=SEQUOIA_p1)
2007-12-08 20:59:10,882 [DEBUG] p1 Scheduling write request (3):
insert into foo (bar) values ( 1)/
2007-12-08 20:59:10,882 [DEBUG] scheduler Schedule insert into foo
(bar) values ( 1)/ - Current pending writes: 1
2007-12-08 20:59:10,882 [DEBUG] p1 Load balancing write request
(3,3): insert into foo (bar) values ( 1)/
2007-12-08 20:59:10,882 [DEBUG] p1 Logging transaction 3 begin
2007-12-08 20:59:10,882 [DEBUG] loadbalancer Request 3 execute on 1
backends
2007-12-08 20:59:10,882 [DEBUG] loadbalancer Removed insert into foo
(bar) values ( 1)/ from total order queue
2007-12-08 20:59:10,882 [DEBUG] recoverylog Logging request 4
2007-12-08 20:59:10,882 [DEBUG] recoverylog prep412
2007-12-08 20:59:10,883 [DEBUG] recoverylog Logging request 5
2007-12-08 20:59:10,883 [DEBUG] recoverylog prep412
2007-12-08 20:59:10,883 [DEBUG] local Request insert into foo (bar)
values ( 1)/ waits for lock on table FOO([BAR])
2007-12-08 20:59:10,883 [DEBUG] local Scheduling request insert into
foo (bar) values ( 1)/ in conflicting queue
2007-12-08 20:59:10,883 [DEBUG] local Adding task
StatementExecuteUpdateTask from transaction 3 (insert into foo (bar)
values ( 1)/) to pending request queue
2007-12-08 20:59:11,491 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:11,491 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:12,492 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:12,492 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:13,492 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:13,492 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:14,492 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:14,492 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:15,493 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:15,493 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:16,493 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:16,493 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:17,493 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:17,493 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:18,494 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:18,494 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:19,494 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:19,494 [DEBUG] Controller Response to ping sent to /
127.0.0.1
2007-12-08 20:59:20,494 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:20,494 [DEBUG] Controller Response to ping sent to /
127.0.0.1
// next line is from my code
2007-12-08 20:59:20,862 [INFO] JdbcConnectionTable Closing idle
connection: 10.0.1.6:58441:2
2007-12-08 20:59:20,862 [DEBUG] p1 Reset command
2007-12-08 20:59:20,862 [DEBUG] p1 Aborting transaction 2
2007-12-08 20:59:20,865 [DEBUG] p1 Broadcasting request abort
transaction 2 to all controllers (Member(address=/10.0.1.6:58451,
uid=SEQUOIA_p1)->[Member(address=/10.0.1.6:58451, uid=SEQUOIA_p1)])
2007-12-08 20:59:20,883 [DEBUG] p1 handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedAb
ort): Abort transaction 2
2007-12-08 20:59:20,883 [INFO] p1 Abort transaction 2
2007-12-08 20:59:20,884 [DEBUG] p1 handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedAb
ort): Abort transaction 2
2007-12-08 20:59:20,884 [DEBUG] scheduler Rollback scheduled -
current pending writes: 2
2007-12-08 20:59:20,884 [DEBUG] p1 Aborting transaction 2
2007-12-08 20:59:20,885 [DEBUG] loadbalancer Request abort 2 execute
on 1 backends
2007-12-08 20:59:20,885 [DEBUG] loadbalancer Request rollback 2
execute on 1 backends
2007-12-08 20:59:20,885 [DEBUG] recoverylog Logging request 6
2007-12-08 20:59:20,885 [DEBUG] recoverylog prep412
2007-12-08 20:59:20,886 [DEBUG] loadbalancer Removed Rollback
transaction 2 from total order queue
2007-12-08 20:59:20,886 [DEBUG] local Adding task RollbackTask (2) to
pending request queue
2007-12-08 20:59:20,887 [DEBUG] local Executing task RollbackTask (2)
2007-12-08 20:59:20,887 [DEBUG] local Priority inversion for request
insert into foo (bar) values ( 1)/
2007-12-08 20:59:20,887 [DEBUG] local Moving
StatementExecuteUpdateTask from transaction 3 (insert into foo (bar)
values ( 1)/) to non conflicting queue
2007-12-08 20:59:20,887 [DEBUG] local Task RollbackTask (2) completed
2007-12-08 20:59:20,887 [DEBUG] recoverylog Logging request 6
2007-12-08 20:59:20,887 [DEBUG] recoverylog prep421
2007-12-08 20:59:20,887 [DEBUG] scheduler Rollback completed,
remaining pending transactions: 1
2007-12-08 20:59:20,887 [DEBUG] scheduler Rollback completed,
remaining pending writes: 1
2007-12-08 20:59:20,887 [DEBUG] p1 Transaction 2 aborted
2007-12-08 20:59:20,887 [DEBUG] local Executing task
StatementExecuteUpdateTask from transaction 3 (insert into foo (bar)
values ( 1)/)
2007-12-08 20:59:20,888 [DEBUG] local Task StatementExecuteUpdateTask
from transaction 3 (insert into foo (bar) values ( 1)/) completed
2007-12-08 20:59:20,888 [DEBUG] scheduler Write completed, remaining
pending writes: 0
2007-12-08 20:59:20,891 [DEBUG] recoverylog Logging request 5
2007-12-08 20:59:20,891 [DEBUG] recoverylog prep421
2007-12-08 20:59:20,904 [DEBUG] p1 Request insert into foo (bar)
values ( 1)/ completed.
2007-12-08 20:59:20,904 [DEBUG] p1 Request 3 completed successfully.
2007-12-08 20:59:20,905 [DEBUG] p1 Request abort completed.
2007-12-08 20:59:20,905 [DEBUG] p1 Abort of transaction 2 completed.
2007-12-08 20:59:20,905 [INFO] p1 R 2
2007-12-08 20:59:20,917 [TRACE] ClusterPartition txCommit()
partition=PartitionId:1, conn=10.0.1.6:58441:3
2007-12-08 20:59:20,917 [TRACE] JGroupsConnector partitionTxCommit()
partition=PartitionId:1 node=10.0.1.6:58450
2007-12-08 20:59:20,918 [TRACE] ClusterPartition closeConnection()
partition=PartitionId:1, conn=10.0.1.6:58441:2
2007-12-08 20:59:20,918 [TRACE] JGroupsConnector
partitionCloseConnection() partition=PartitionId:1 node=10.0.1.6:58450
// next line is from my code
2007-12-08 20:59:20,930 [TRACE] JdbcPartitionSource SQL txCommit()
[conn=10.0.1.6:58441:3]
2007-12-08 20:59:20,931 [DEBUG] p1 Commit command
2007-12-08 20:59:20,931 [INFO] p1 C 3
2007-12-08 20:59:20,931 [DEBUG] p1 Broadcasting request commit
transaction 3 to all controllers (Member(address=/10.0.1.6:58451,
uid=SEQUOIA_p1)->[Member(address=/10.0.1.6:58451, uid=SEQUOIA_p1)])
2007-12-08 20:59:20,949 [DEBUG] p1 handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedCo
mmit): Commit transaction 3
2007-12-08 20:59:20,949 [INFO] p1 Commit transaction 3
2007-12-08 20:59:20,949 [DEBUG] p1 handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedCo
mmit): Commit transaction 3
2007-12-08 20:59:20,949 [DEBUG] scheduler Commit scheduled - current
pending writes: 1
2007-12-08 20:59:20,949 [DEBUG] p1 Commit transaction 3
2007-12-08 20:59:20,951 [DEBUG] loadbalancer Request commit 3 execute
on 1 backends
2007-12-08 20:59:20,951 [DEBUG] recoverylog Logging request 7
2007-12-08 20:59:20,951 [DEBUG] recoverylog prep412
2007-12-08 20:59:20,951 [DEBUG] loadbalancer Removed Commit
transaction 3 from total order queue
2007-12-08 20:59:20,951 [DEBUG] local Adding task CommitTask (3) to
pending request queue
2007-12-08 20:59:20,952 [DEBUG] local Executing task CommitTask (3)
2007-12-08 20:59:20,952 [DEBUG] local Task CommitTask (3) completed
2007-12-08 20:59:20,952 [DEBUG] recoverylog Logging request 7
2007-12-08 20:59:20,952 [DEBUG] recoverylog prep421
2007-12-08 20:59:20,952 [DEBUG] scheduler Commit completed, remaining
pending transactions: 0
2007-12-08 20:59:20,952 [DEBUG] scheduler Commit completed, remaining
pending writes: 0
2007-12-08 20:59:20,967 [DEBUG] p1 Request commit completed.
2007-12-08 20:59:20,967 [DEBUG] p1 Commit of transaction 3 completed.
// next line is from my code
2007-12-08 20:59:20,994 [TRACE] JdbcPartitionSource SQL
closeConnection() [conn=10.0.1.6:58441:3]
2007-12-08 20:59:20,994 [DEBUG] p1 Reset command
2007-12-08 20:59:21,495 [DEBUG] Controller Received ping data from /
127.0.0.1
2007-12-08 20:59:21,495 [DEBUG] Controller Response to ping sent to /
127.0.0.1
_______________________________________________
Sequoia mailing list
[email protected]
https://forge.continuent.org/mailman/listinfo/sequoia
