Emanuel,
I've tried this again with distibution turned on, and the same ordering
occurs, e.g:
Log_id 13625: Transaction_id = 12750, SqlStmt = begin
Log_id 13626: Transaction_id = 12750, SqlStmt = update users set lastlogin =
{ts '2008-06-27 15:42:15.0'} where id = ?
Log_id 13627: Transaction_id = 12754, SqlStmt = begin
Log_id 13628: Transaction_id = 12754, SqlStmt = update users set lastlogin =
{ts '2008-06-27 15:42:15.0'} where id = ?
Log_id 13629: Transaction_id = 12758, SqlStmt = begin
Log_id 13630: Transaction_id = 12758, SqlStmt = update users set lastlogin =
{ts '2008-06-27 15:42:15.0'} where id = ?
Log_id 13631: Transaction_id = 12762, SqlStmt = begin
Log_id 13632: Transaction_id = 12762, SqlStmt = update users set lastlogin =
{ts '2008-06-27 15:42:15.0'} where id = ?
Log_id 13633: Transaction_id = 12750, SqlStmt = commit
Log_id 13634: Transaction_id = 12754, SqlStmt = commit
Log_id 13635: Transaction_id = 12758, SqlStmt = commit
...
Log_id 13638: Transaction_id = 12762, SqlStmt = commit
Here's some log output, this is from a very large log logging virtualdatabase &
recoverylog at a DEBUG level, but I think contains what you want - if you need
more, let me know:
2008-06-27 15:48:35,765 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55395 17813 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,765 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Scheduling distributedRequest 55395 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,765 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55395 17813 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,765 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Executing distributedRequest 55395 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,765 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20221
2008-06-27 15:48:35,765 DEBUG org.continuent.sequoia.controller.recoverylog -
Releasing recovery log connection: [EMAIL PROTECTED] (XID = 53657), (SESSIONID
= 4287), (DATABASE = HA), (DRDAID = null)
2008-06-27 15:48:35,765 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging in recovery log connection
2008-06-27 15:48:35,765 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,765 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20222
2008-06-27 15:48:35,765 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,781 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20222
2008-06-27 15:48:35,781 DEBUG org.continuent.sequoia.controller.recoverylog -
Releasing recovery log connection: [EMAIL PROTECTED] (XID = 53660), (SESSIONID
= 4288), (DATABASE = HA), (DRDAID = null)
2008-06-27 15:48:35,781 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging in recovery log connection
2008-06-27 15:48:35,781 DEBUG org.continuent.sequoia.controller.recoverylog -
c065801d-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55397 17814 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Scheduling distributedRequest 55397 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55397 17814 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Executing distributedRequest 55397 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20223
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
Releasing recovery log connection: [EMAIL PROTECTED] (XID = 53662), (SESSIONID
= 4289), (DATABASE = HA), (DRDAID = null)
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging in recovery log connection
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20224
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55411 17821 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Scheduling distributedRequest 55411 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55411 17821 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Executing distributedRequest 55411 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20225
2008-06-27 15:48:35,796 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55413 17822 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Scheduling distributedRequest 55413 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,796 DEBUG
org.continuent.sequoia.controller.virtualdatabase.VirtualDatabaseWorkerThread.AndyCluster
- Commit command
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20226
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Releasing recovery log connection: [EMAIL PROTECTED] (XID = 53666), (SESSIONID
= 4290), (DATABASE = HA), (DRDAID = null)
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging in recovery log connection
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedStatementExecuteUpdate):
W 55413 17822 update users set lastlogin = {ts '2008-06-27 15:48:35.0'} where
id = ?/<!%I|613|!%>
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
192.168.0.109:6954: Executing distributedRequest 55413 from
Member(address=/192.168.0.109:3127, uid=192.168.0.109:3127)
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedCommit):
Commit transaction 17813
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedCommit):
Commit transaction 17813
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20227
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20228
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20229
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.VirtualDatabaseWorkerThread.AndyCluster
- Commit command
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20229
2008-06-27 15:48:35,812 DEBUG org.continuent.sequoia.controller.recoverylog -
c065801d-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.VirtualDatabaseWorkerThread.AndyCluster
- StatementExecuteQuery command
2008-06-27 15:48:35,812 DEBUG
org.continuent.sequoia.controller.virtualdatabase.VirtualDatabaseWorkerThread.AndyCluster
- StatementExecuteUpdateWithKeys command
2008-06-27 15:48:35,828 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20224
2008-06-27 15:48:35,828 DEBUG org.continuent.sequoia.controller.recoverylog -
Releasing recovery log connection: [EMAIL PROTECTED] (XID = 53672), (SESSIONID
= 4291), (DATABASE = HA), (DRDAID = null)
2008-06-27 15:48:35,828 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging in recovery log connection
2008-06-27 15:48:35,828 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageSingleThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedCommit):
Commit transaction 17814
2008-06-27 15:48:35,828 DEBUG
org.continuent.sequoia.controller.virtualdatabase.AndyCluster -
handleMessageMultiThreaded (class
org.continuent.sequoia.controller.virtualdatabase.protocol.DistributedCommit):
Commit transaction 17814
2008-06-27 15:48:35,828 DEBUG org.continuent.sequoia.controller.recoverylog -
c065801d-011a-ca77-dce2-ffffd8827a3c
2008-06-27 15:48:35,828 DEBUG org.continuent.sequoia.controller.recoverylog -
Logging request 20230
2008-06-27 15:48:35,828 DEBUG org.continuent.sequoia.controller.recoverylog -
2057c01b-011a-ca77-dce2-ffffd8827a3c
Thanks again for the help,
Andy
-----Original Message-----
From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Emmanuel Cecchet
Sent: 27 June 2008 13:55
To: Sequoia general mailing list
Subject: Re: [Sequoia] Deadlock when replaying recovery log
Hi Andrew,
> this is with Sequoia 2.10.10, on a single non-distributed controller
> with 2 backends - both emebedded derby databases.
>
This might be an issue related to the non-distributed code. Could you add a
<Distributed> element to your configuration file and have another run just to
check if the order in the recovery log changes.
If the problem persists, it would be interesting to have a trace of the log
with virtualdatabase and recoverylog loggers set to DEBUG in log4j.properties
to see in what order events occur in your scenario.
Thanks a lot for the feedback,
Emmanuel
> a set of sample recovery log entries are:
>
> Log_id 103: Transaction_id = 146, RequestId = 0, SqlStmt = begin
> Log_id 104: Transaction_id = 146, RequestId = 322, SqlStmt = update users set
> lastlogin = {ts '2008-06-26 17:27:37.0'} where id = ?
> Log_id 105: Transaction_id = 147, RequestId = 0, SqlStmt = begin
> Log_id 106: Transaction_id = 147, RequestId = 326, SqlStmt = update users set
> lastlogin = {ts '2008-06-26 17:27:37.0'} where id = ?
> Log_id 107: Transaction_id = 148, RequestId = 0, SqlStmt = begin
> Log_id 108: Transaction_id = 148, RequestId = 328, SqlStmt = update users set
> lastlogin = {ts '2008-06-26 17:27:37.0'} where id = ?
> Log_id 109: Transaction_id = 149, RequestId = 0, SqlStmt = begin
> Log_id 110: Transaction_id = 149, RequestId = 330, SqlStmt = update users set
> lastlogin = {ts '2008-06-26 17:27:37.0'} where id = ?
> <a few more of these>
> Log_id 123: Transaction_id = 146, RequestId = 0, SqlStmt = commit
> Log_id 124: Transaction_id = 147, RequestId = 0, SqlStmt = commit
> Log_id 125: Transaction_id = 148, RequestId = 0, SqlStmt = commit
> Log_id 126: Transaction_id = 149, RequestId = 0, SqlStmt = commit <a
> few more commits>
>
> Many thanks for any help,
>
> Andy
>
> -----Original Message-----
> From: [EMAIL PROTECTED]
> [mailto:[EMAIL PROTECTED] On Behalf Of
> Emmanuel Cecchet
> Sent: 26 June 2008 16:33
> To: Sequoia general mailing list
> Subject: Re: [Sequoia] Deadlock when replaying recovery log
>
> Hi Andrew,
>
>
>> I'm having problems with replaying recovery logs, where the
>> replay appears to be deadlocking itself. I'm getting the following error:
>>
>> 2008-06-26 09:53:30,103 ERROR
>> org.continuent.sequoia.controller.recoverylog.RecoverThread -
>> Recovery process failed to replay transaction 1110: request
>> StatementExecuteUpdateTask from transaction 1110 (update... )
>> (Backend AndyCluster - BackendWorkerThread for backend 'DB-BACKUP'
>> with RAIDb
>> level:1 failed (A lock could not be obtained within the time requested.
>>
>>
>> As an example, consider the following simplified scenario:
>>
>> I have a table 'test':
>>
>> create table test ( a int , b int )
>> insert into test values ( 1, 1 )
>>
>> we then have two transactions, t1 & t2 each in different threads
>> which do the following:
>>
>> 1) t1: update test set b = 2 where a = 1
>> 2) t2: update test set b = 3 where a = 1
>> 3) t1: commit
>> 4) t2: commit
>>
>> normally, this will work fine, when t2 executes, it is blocked on a
>> lock, but as soon as t1 commits, the lock is freed and t2 then commits.
>>
>> however, if you replay the transaction log, all the statements are
>> executed sequentially, and what I think is happening is that the 2nd
>> statement hangs and eventually has a lock timeout, as t1 will not be
>> commited until after it.
>> This means that you can't recover, as you can't replay the log.
>>
>> Is my understanding correct, and if so, is there anything I can do
>> about this?
>>
> There is something wrong here because the recovery log stores queries in the
> execution order and not in their arrival order.
> This means that the scenario you are describing should not be logged this way
> in the recovery log.
>
> Could you provide a dump of your recovery log content?
> Which version of Sequoia are you using?
> Are all your database backends running the same database engine?
>
> Thanks for your feedback,
> Emmanuel
>
>
--
Emmanuel Cecchet
FTO @ Frog Thinker
Open Source Development & Consulting
--
Web: http://www.frogthinker.org
email: [EMAIL PROTECTED]
Skype: emmanuel_cecchet
_______________________________________________
Sequoia mailing list
[email protected]
https://forge.continuent.org/mailman/listinfo/sequoia
_______________________________________________
Sequoia mailing list
[email protected]
https://forge.continuent.org/mailman/listinfo/sequoia
