Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Deadlock with TIP page lock and monitoring lock [CORE4627] #4942

Closed
firebird-automations opened this issue Nov 30, 2014 · 9 comments
Closed

Comments

@firebird-automations
Copy link
Collaborator

Submitted by: Yurij (yurij)

firebird.log contains messages like

page NNN, page type 3 lock denied (216)

Commits: 13a364c FirebirdSQL/fbt-repository@8ad859f

====== 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 ?..

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

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 !

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

assignee: Vlad Khorsun [ hvlad ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

Fix Version: 2.5.4 [ 10585 ]

Component: Engine [ 10000 ]

description: firebird.log contains messages like

page NNN, page type 3 lock denied (216)

environment: Classic Server or Super Classic

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

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.

@firebird-automations
Copy link
Collaborator Author

Commented by: @hvlad

Changed ticket owner by user who supplied lock table and memory dumps.

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

reporter: Vlad Khorsun [ hvlad ] => Yurij [ yurij ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @hvlad

status: Open [ 1 ] => Resolved [ 5 ]

resolution: Fixed [ 1 ]

@firebird-automations
Copy link
Collaborator Author

Modified by: @pavel-zotov

status: Resolved [ 5 ] => Resolved [ 5 ]

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 ?..

@firebird-automations
Copy link
Collaborator Author

Modified by: @pcisar

status: Resolved [ 5 ] => Closed [ 6 ]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants