On Wed, Dec 21, 2016 at 06:38:08PM +0100, Václav Ovsík wrote:
>...
> ================================================================
> * default_transaction_isolation = 'serializable'
> - I tried the action many times, but Pg is silent - nothing appears
> in its log file and everything seems normal.
Sorry, this is not true. I did more thorough testing today. I did experiments
on one test ticket and as the history of ticket grows, the probability of the
bug increases. Now it is almost certain the problem will occurs.
Isolation level 'serializable' behaves like 'repeatable read'. So the summary
is:
===========================================================
'commited read': -> deadlock, application outputs error:
Comments added
Could not change owner: Could not update column Owner: Owner could not be
set to 102.
Postgres log:
2016-12-22 13:18:18 CET [26070-1] rt_rt@rt ERROR: deadlock detected
2016-12-22 13:18:18 CET [26070-2] rt_rt@rt DETAIL: Process 26070 waits for
ShareLock on transaction 32889; blocked by process 26097.
Process 26097 waits for ShareLock on transaction 32890; blocked by
process 26070.
Process 26070: UPDATE Tickets SET Owner=$1 WHERE id=$2
Process 26097: INSERT INTO GroupMembers (LastUpdatedBy, Creator,
Created, GroupId, MemberId, LastUpdated) VALUES ($1, $2, $3, $4, $5, $6)
2016-12-22 13:18:18 CET [26070-3] rt_rt@rt HINT: See server log for query
details.
2016-12-22 13:18:18 CET [26070-4] rt_rt@rt CONTEXT: while updating tuple
(4509,284) in relation "tickets"
2016-12-22 13:18:18 CET [26070-5] rt_rt@rt STATEMENT: UPDATE Tickets SET
Owner=$1 WHERE id=$2
===========================================================
'repeatable read'
'serializable': -> application output normal status:
Comments added
Owner changed from eva to zito
Postgres log:
2016-12-22 13:26:36 CET [31696-1] rt_rt@rt ERROR: could not serialize access
due to concurrent update
2016-12-22 13:26:36 CET [31696-2] rt_rt@rt STATEMENT: SELECT * FROM Tickets
WHERE id = $1 FOR UPDATE
2016-12-22 13:26:36 CET [31696-3] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-4] rt_rt@rt STATEMENT: INSERT INTO
Transactions (Type, Creator, ObjectId, NewValue, Field, Data, ObjectType,
NewReference, ReferenceType, Created, OldReference, OldValue) VALUES ($1, $2,
$3, $4, $5, $6, $7, $8, $9, $10, $11, $12)
2016-12-22 13:26:36 CET [31696-5] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-6] rt_rt@rt STATEMENT: SELECT * FROM
Transactions WHERE id = $1
2016-12-22 13:26:36 CET [31696-7] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-8] rt_rt@rt STATEMENT: SELECT * FROM Tickets
WHERE id = $1
2016-12-22 13:26:36 CET [31696-9] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-10] rt_rt@rt STATEMENT: SELECT * FROM
Transactions WHERE id = $1
2016-12-22 13:26:36 CET [31696-11] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-12] rt_rt@rt STATEMENT: SELECT main.* FROM
Scrips main JOIN ObjectScrips ObjectScrips_1 ON ( ObjectScrips_1.Scrip =
main.id ) JOIN ScripConditions ScripConditions_2 ON ( ScripConditions_2.id =
main.ScripCondition ) WHERE (ObjectScrips_1.ObjectId = '0') AND
(ObjectScrips_1.Stage = 'TransactionCreate') AND
(ScripConditions_2.ApplicableTransTypes LIKE '%Comment%' OR
ScripConditions_2.ApplicableTransTypes LIKE '%Any%') AND (main.Disabled = '0')
GROUP BY main.id ORDER BY MIN(ObjectScrips_1.SortOrder) ASC
2016-12-22 13:26:36 CET [31696-13] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-14] rt_rt@rt STATEMENT: SELECT COUNT(DISTINCT
main.id) FROM Scrips main JOIN ObjectScrips ObjectScrips_1 ON (
ObjectScrips_1.Scrip = main.id ) JOIN ScripConditions ScripConditions_2 ON (
ScripConditions_2.id = main.ScripCondition ) WHERE (ObjectScrips_1.ObjectId =
'0') AND (ObjectScrips_1.Stage = 'TransactionCreate') AND
(ScripConditions_2.ApplicableTransTypes LIKE '%Comment%' OR
ScripConditions_2.ApplicableTransTypes LIKE '%Any%') AND (main.Disabled = '0')
2016-12-22 13:26:36 CET [31696-15] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-16] rt_rt@rt STATEMENT: SELECT main.* FROM
Scrips main JOIN ObjectScrips ObjectScrips_1 ON ( ObjectScrips_1.Scrip =
main.id ) JOIN ScripConditions ScripConditions_2 ON ( ScripConditions_2.id =
main.ScripCondition ) WHERE (ObjectScrips_1.ObjectId = '0') AND
(ObjectScrips_1.Stage = 'TransactionCreate') AND
(ScripConditions_2.ApplicableTransTypes LIKE '%Comment%' OR
ScripConditions_2.ApplicableTransTypes LIKE '%Any%') AND (main.Disabled = '0')
GROUP BY main.id ORDER BY MIN(ObjectScrips_1.SortOrder) ASC
2016-12-22 13:26:36 CET [31696-17] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-18] rt_rt@rt STATEMENT: SELECT * FROM Tickets
WHERE id = $1
2016-12-22 13:26:36 CET [31696-19] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-20] rt_rt@rt STATEMENT: SELECT * FROM
Transactions WHERE id = $1
2016-12-22 13:26:36 CET [31696-21] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-22] rt_rt@rt STATEMENT: SELECT * FROM Tickets
WHERE id = $1
2016-12-22 13:26:36 CET [31696-23] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-24] rt_rt@rt STATEMENT: UPDATE Tickets SET
LastUpdated=$1 WHERE id=$2
2016-12-22 13:26:36 CET [31696-25] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-26] rt_rt@rt STATEMENT: UPDATE Tickets SET
LastUpdated=$1 WHERE id=$2
2016-12-22 13:26:36 CET [31696-27] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-28] rt_rt@rt STATEMENT: UPDATE Tickets SET
LastUpdated=$1 WHERE id=$2
2016-12-22 13:26:36 CET [31696-29] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-30] rt_rt@rt STATEMENT: SELECT * FROM Tickets
WHERE id = $1
2016-12-22 13:26:36 CET [31696-31] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-32] rt_rt@rt STATEMENT: SELECT * FROM Users
WHERE id = $1
2016-12-22 13:26:36 CET [31696-33] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-34] rt_rt@rt STATEMENT: SELECT * FROM Users
WHERE id = $1
2016-12-22 13:26:36 CET [31696-35] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-36] rt_rt@rt STATEMENT: SELECT * FROM
Principals WHERE id = $1
2016-12-22 13:26:36 CET [31696-37] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-38] rt_rt@rt STATEMENT: SELECT main.* FROM
Attributes main WHERE (main.ObjectId = 1900) AND (main.ObjectType =
'RT::User') ORDER BY main.id ASC
2016-12-22 13:26:36 CET [31696-39] rt_rt@rt ERROR: current transaction is
aborted, commands ignored until end of transaction block
2016-12-22 13:26:36 CET [31696-40] rt_rt@rt STATEMENT: SELECT main.* FROM
Attributes main WHERE (main.ObjectId = 1900) AND (main.ObjectType =
'RT::User') ORDER BY main.id ASC
It seems to me, that a transaction - comment and owner change is processed
by one RT server process and concurrently runs another web server
process gathering data for ticket history. I have a rather long ticket
history now. I added many comments already. The probability of
transaction collision is very high, so the problem occurs every time.
Are there any changes in RT between 4.2 and 4.4 toward loading web page
asynchronously? Is it possible data are loading from browser while
a modify transaction is in progress yet.
--
Zito
