[#CORE-2000] Lock manager reported false deadlocks under high load

Firebird Core

Lock manager reported false deadlocks under high load

Created: 17/Jul/08 08:02 AM Updated: 25/Sep/09 04:15 AM

Component/s:

Engine

Affects Version/s:

1.0.3, 2.0.0, 1.5.4, 2.0.1, 2.0.2, 2.0.3, 1.5.5, 2.5 Initial, 2.1.0, 2.0.4

Fix Version/s:

2.0.5, 2.1.2, 2.5 Beta 1

Time Tracking:

Not Specified

Environment:

Classic Server

Issue Links:

Depend

This issue block progress on:

CORE-2611 CLONE -Lock conversion denied (215) error may occurs

~~CORE-1970~~ Lock conversion denied (215) error may occurs

Relate

This issue relate to:

~~CORE-2640~~ A regular deadlock may not be detected by the lock manager under some conditions, thus resulting in a hang

Planning Status:

Unspecified

All

Comments

Work Log

Change History

Version Control

FishEye

Sort Order:

[ Permalink | « Hide ]

Vlad Khorsun added a comment - 17/Jul/08 08:21 AM

Below is typical picture at false deadlock detection time

a) Owners, participating in deadlock (backtrace, head of chain marked by 0) :
1 deadlock chain: OWNER BLOCK 377540 Process id: 2968 Flags: 0x04
2 deadlock chain: OWNER BLOCK 396488 Process id: 2748 Flags: 0x04
1 deadlock chain: OWNER BLOCK 377540 Process id: 2968 Flags: 0x04
0 deadlock chain: OWNER BLOCK 401656 Process id: 3024 Flags: 0x04

b) Two locks on which owners are waiting :

LOCK BLOCK 948936
Series: 3, Parent: 346628, State: 6, size: 8 length: 8 data: 0
Key: 0001:009782, Flags: 0x00, Pending request count: 5
Hash que (3): forward: 1006312, backward: 366144
Requests (6): forward: 1375776, backward: 1109580
2 Request 1375776, Owner: 396488, State: 6 (6), Flags: 0x00

Request 876536, Owner: 532236, State: 0 (6), Flags: 0x02
Request 1117016, Owner: 677976, State: 0 (6), Flags: 0x02
Request 1400188, Owner: 544104, State: 0 (6), Flags: 0x02
1 Request 1366912, Owner: 377540, State: 0 (6), Flags: 0x22
Request 1109580, Owner: 508804, State: 0 (6), Flags: 0x02

LOCK BLOCK 364744
Series: 3, Parent: 346628, State: 3, size: 8 length: 8 data: 0
Key: 0001:007839, Flags: 0x00, Pending request count: 4
Hash que (5): forward: 998428, backward: 6564
Requests (9): forward: 1409704, backward: 1230128
1 Request 1409704, Owner: 377540, State: 3 (3), Flags: 0x100
Request 1391660, Owner: 532236, State: 3 (3), Flags: 0x100
Request 1175112, Owner: 677976, State: 3 (3), Flags: 0x100
Request 1339992, Owner: 544104, State: 3 (3), Flags: 0x100
Request 875028, Owner: 508804, State: 3 (3), Flags: 0x100

Request 1403776, Owner: 588040, State: 0 (6), Flags: 0x02
Request 1399668, Owner: 486280, State: 0 (3), Flags: 0x02
Request 1114520, Owner: 627348, State: 0 (6), Flags: 0x02
2 Request 1230128, Owner: 396488, State: 0 (6), Flags: 0x22

As you may see request 1375776 (of owner 396488) just granted a lock 948936. This request blocked some other requests, one of them by owner 377540. Note, request 1375776 have flags 0, i.e. it was not marked as blocking and not seen blocking notification. Therefore it have no chance to release the lock to break circle in wait-for graph.

LOCK\post_pending() routine wake up owner of first blocked request. If another process run deadlock scan before blocked owner awakens (and calls post_blockage) it reports false deadlock.

[ Show » ]

Vlad Khorsun added a comment - 17/Jul/08 08:21 AM Below is typical picture at false deadlock detection time a) Owners, participating in deadlock (backtrace, head of chain marked by 0) : 1 deadlock chain: OWNER BLOCK 377540 Process id: 2968 Flags: 0x04 2 deadlock chain: OWNER BLOCK 396488 Process id: 2748 Flags: 0x04 1 deadlock chain: OWNER BLOCK 377540 Process id: 2968 Flags: 0x04 0 deadlock chain: OWNER BLOCK 401656 Process id: 3024 Flags: 0x04 b) Two locks on which owners are waiting : LOCK BLOCK 948936 Series: 3, Parent: 346628, State: 6, size: 8 length: 8 data: 0 Key: 0001:009782, Flags: 0x00, Pending request count: 5 Hash que (3): forward: 1006312, backward: 366144 Requests (6): forward: 1375776, backward: 1109580 2 Request 1375776, Owner: 396488, State: 6 (6), Flags: 0x00 Request 876536, Owner: 532236, State: 0 (6), Flags: 0x02 Request 1117016, Owner: 677976, State: 0 (6), Flags: 0x02 Request 1400188, Owner: 544104, State: 0 (6), Flags: 0x02 1 Request 1366912, Owner: 377540, State: 0 (6), Flags: 0x22 Request 1109580, Owner: 508804, State: 0 (6), Flags: 0x02 LOCK BLOCK 364744 Series: 3, Parent: 346628, State: 3, size: 8 length: 8 data: 0 Key: 0001:007839, Flags: 0x00, Pending request count: 4 Hash que (5): forward: 998428, backward: 6564 Requests (9): forward: 1409704, backward: 1230128 1 Request 1409704, Owner: 377540, State: 3 (3), Flags: 0x100 Request 1391660, Owner: 532236, State: 3 (3), Flags: 0x100 Request 1175112, Owner: 677976, State: 3 (3), Flags: 0x100 Request 1339992, Owner: 544104, State: 3 (3), Flags: 0x100 Request 875028, Owner: 508804, State: 3 (3), Flags: 0x100 Request 1403776, Owner: 588040, State: 0 (6), Flags: 0x02 Request 1399668, Owner: 486280, State: 0 (3), Flags: 0x02 Request 1114520, Owner: 627348, State: 0 (6), Flags: 0x02 2 Request 1230128, Owner: 396488, State: 0 (6), Flags: 0x22 As you may see request 1375776 (of owner 396488) just granted a lock 948936. This request blocked some other requests, one of them by owner 377540. Note, request 1375776 have flags 0, i.e. it was not marked as blocking and not seen blocking notification. Therefore it have no chance to release the lock to break circle in wait-for graph. LOCK\post_pending() routine wake up owner of first blocked request. If another process run deadlock scan before blocked owner awakens (and calls post_blockage) it reports false deadlock.