Issue Details (XML | Word | Printable)

Key: CORE-4627
Type: Bug Bug
Status: Closed Closed
Resolution: Fixed
Priority: Major Major
Assignee: Vlad Khorsun
Reporter: Yurij
Votes: 0
Watchers: 2
Operations

If you were logged in you would be able to see more operations.
Firebird Core

Deadlock with TIP page lock and monitoring lock

Created: 30/Nov/14 02:34 PM   Updated: 23/Sep/15 12:20 PM
Component/s: Engine
Affects Version/s: 2.5.3
Fix Version/s: 2.5.4

Environment: Classic Server or Super Classic

QA Status: Deferred
Test Details:
Have no idea how to encounter new lines in firebird.log.
Perhaps, by launch of 'fbsvcmgr action_get_fb_log' and finding results with timestamp >= test beginning ?..


 Description  « Hide
firebird.log contains messages like

page NNN, page type 3 lock denied (216)


 All   Comments   Change History   Subversion Commits      Sort Order: Ascending order - Click to sort in descending order
Vlad Khorsun added a comment - 30/Nov/14 02:49 PM
1. Locks, involved into deadlock

LOCK BLOCK 635472
    Series: 20, Parent: 18892, State: 2, size: 8 length: 4 data: 0
    Key: 000000, Flags: 0x00, Pending request count: 17
    Hash que (3): forward: 348, backward: 19124
    Requests (18): forward: 567756, backward: 2548960
        Request 567756, Owner: 18744, State: 2 (2), Flags: 0x100
        Request 1364764, Owner: 202332, State: 0 (6), Flags: 0x22
        Request 2036180, Owner: 151336, State: 0 (2), Flags: 0x02
        Request 2737252, Owner: 373352, State: 0 (2), Flags: 0x02
        Request 507392, Owner: 99544, State: 0 (2), Flags: 0x02
        Request 1245748, Owner: 325812, State: 0 (2), Flags: 0x02
        Request 2266028, Owner: 1659348, State: 0 (6), Flags: 0x02
        Request 159120, Owner: 356320, State: 0 (2), Flags: 0x02
        Request 428636, Owner: 296464, State: 0 (2), Flags: 0x02
        Request 1133116, Owner: 386952, State: 0 (2), Flags: 0x02
        Request 159796, Owner: 223160, State: 0 (2), Flags: 0x02
        Request 1572952, Owner: 78720, State: 0 (2), Flags: 0x02
        Request 250868, Owner: 22184, State: 0 (2), Flags: 0x02
        Request 2091768, Owner: 262568, State: 0 (2), Flags: 0x22
        Request 2108520, Owner: 386728, State: 0 (2), Flags: 0x02
        Request 674392, Owner: 127492, State: 0 (2), Flags: 0x02
        Request 1017836, Owner: 167700, State: 0 (2), Flags: 0x02
        Request 2548960, Owner: 384652, State: 0 (2), Flags: 0x02

LOCK BLOCK 557236
    Series: 3, Parent: 18892, State: 3, size: 8 length: 8 data: 0
    Key: 0001:051383, Flags: 0x00, Pending request count: 5
    Hash que (2): forward: 7820, backward: 1526176
    Requests (6): forward: 1495756, backward: 2395716
        Request 1495756, Owner: 262568, State: 3 (3), Flags: 0x00
        Request 2573660, Owner: 153980, State: 0 (6), Flags: 0x22
        Request 1354220, Owner: 214488, State: 0 (3), Flags: 0x02
        Request 1446996, Owner: 386376, State: 0 (6), Flags: 0x02
        Request 564632, Owner: 18744, State: 0 (3), Flags: 0x22
        Request 2395716, Owner: 241504, State: 0 (6), Flags: 0x02



LOCK BLOCK 635472 - this is a monitoring lock
LOCK BLOCK 557236 - this is a page lock

Owner 18744 hold lock 635472 (monitoring lock) and acquires lock 557236 (page lock).
Owner 262568 hold lock 557236 and acquires lock 635472.
This is a deadlock.

Memory dump helps to see what lock owners doing:

OWNER BLOCK 262568
    Owner id: 19275816953374, type: 1, pending: 2091768
    Process id: 4488 (Dead), thread id: 4464
    Flags: 0x04 wait infn
    Requests (326): forward: 615360, backward: 2091768
    Blocks: *empty*

06 fb_inet_server!enqueue+0x51
07 fb_inet_server!LCK_lock+0x8d
08 fb_inet_server!JRD_reschedule+0x140 // monitoring lock acquired here
09 fb_inet_server!EVL_expr+0x4e
0a fb_inet_server!EXE_assignment+0x4f
0b fb_inet_server!EXE_looper+0x1d1
0c fb_inet_server!looper_seh+0x45
0d fb_inet_server!execute_looper+0x89
0e fb_inet_server!EXE_receive+0x2f9
0f fb_inet_server!DPM_scan_pages+0x235
10 fb_inet_server!inventory_page+0x57
11 fb_inet_server!TRA_get_inventory+0xe0 // handoff, lock for page-from is not released
12 fb_inet_server!transaction_start+0x25a
13 fb_inet_server!TRA_start+0x142
14 fb_inet_server!JRD_start_multiple+0x1f1
15 fb_inet_server!jrd8_start_transaction+0x22a


OWNER BLOCK 18744
    Owner id: 19275816954029, type: 1, pending: 564632
    Process id: 4488 (Dead), thread id: 1312
    Flags: 0x04 wait infn
    Requests (32): forward: 2639232, backward: 564632
    Blocks: *empty*

02 fb_inet_server!Jrd::LockManager::LocalCheckout::~LocalCheckout+0x53
03 fb_inet_server!Jrd::LockManager::wait_for_request+0x2c4
04 fb_inet_server!Jrd::LockManager::grant_or_que+0x8c
05 fb_inet_server!Jrd::LockManager::enqueue+0x20b
06 fb_inet_server!enqueue+0x51
07 fb_inet_server!LCK_lock+0x8d
08 fb_inet_server!LCK_lock_opt+0x36
09 fb_inet_server!lock_buffer+0xd5
0a fb_inet_server!CCH_fetch_lock+0xd1
0b fb_inet_server!CCH_fetch+0x2d
0c fb_inet_server!fetch_inventory_page+0x2f
0d fb_inet_server!TRA_get_inventory+0x5d
0e fb_inet_server!cache_transactions+0xce
0f fb_inet_server!TPC_snapshot_state+0x38
10 fb_inet_server!TRA_snapshot_state+0x6f
11 fb_inet_server!VIO_chase_record_version+0x77
12 fb_inet_server!VIO_next_record+0x58
13 fb_inet_server!get_record+0xaa
14 fb_inet_server!RSE_get_record+0x5f
15 fb_inet_server!EXE_looper+0x383
16 fb_inet_server!looper_seh+0x45
17 fb_inet_server!execute_looper+0x89
18 fb_inet_server!EXE_start+0x294
19 fb_inet_server!SCL_init+0x59d
1a fb_inet_server!jrd8_attach_database+0xd0a
1b fb_inet_server!isc_attach_database+0x405
1c fb_inet_server!attach_database2+0x330
1d fb_inet_server!attach_database+0x287

Owner 18744 is attached to the database. It is already initialized its monitoring lock, and run some system queries to complete attachment initialization.
Let look at dbb flags:

 dbb_ast_flags 0x204 // DBB_monitor_off | DBB_assert_locks
 dbb_flags 0x21140 // DBB_gc_cooperative | DBB_lck_init_done | DBB_DB_SQL_dialect_3 | DBB_force_write

It is in a wrong state - DBB_monitor_off should be set only if monitoring lock is released !

Vlad Khorsun added a comment - 30/Nov/14 02:58 PM
Note, database contains ON CONNECT and ON TRANSACTION COMMIT triggers both accessed monitoring tables.
To reproduce bug, trigger ON CONNECT with access of monitoring tables is necessary.

Vlad Khorsun added a comment - 30/Nov/14 03:02 PM
Changed ticket owner by user who supplied lock table and memory dumps.