Bug #41159 Maria: deadlock between checkpoint and maria_write() when extending data file
Submitted: 1 Dec 2008 21:01 Modified: 9 Jan 2009 15:00
Reporter: Guilhem Bichot Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Maria storage engine Severity:S3 (Non-critical)
Version:5.1-maria OS:Any
Assigned to: Guilhem Bichot CPU Architecture:Any

[1 Dec 2008 21:01] Guilhem Bichot
Description:
1) Checkpoint thread is doing checkpoint, in collect_tables(): takes intern_lock
2) other thread is doing INSERT, which creates new page, so calls _ma_set_share_data_file_length() which wants intern_lock, so blocks on 1)
3) checkpoint thread wants to flush bitmap, which is _ma_bitmap_flush_all(), which has to wait for bitmap to be flushable
4) but bitmap is not flushable because thread in 2) has marked it as non-flushable when it started the write
5) so both threads are waiting for each other.

A detail: in the test, a third thread is blocked in _ma_trnman_end_trans_hook() trying to get intern_lock, so holding LOCK_trn_list, so the entire Maria stalls.

How to repeat:
seen in pushbuild2 for the first time today
[1 Dec 2008 21:02] Guilhem Bichot
Stack trace of checkpoint:
Thread 9 (process 592335    ):
#0  0xff040094 in __lwp_park () from /lib/libc.so.1
#1  0xff03a010 in cond_sleep_queue () from /lib/libc.so.1
#2  0xff03a12c in cond_wait_queue () from /lib/libc.so.1
#3  0xff03a6ac in cond_wait () from /lib/libc.so.1
#4  0xff03a6e8 in pthread_cond_wait () from /lib/libc.so.1
#5  0x007ae728 in safe_cond_wait (cond=0x329cec0, mp=0x329ce78,
    file=0xa74198 "ma_bitmap.c", line=356) at thr_mutex.c:249
#6  0x006f98b0 in _ma_bitmap_flush_all (share=0x329c910) at ma_bitmap.c:356
#7  0x00751124 in collect_tables (str=0xfe7fbddc,
    checkpoint_start_log_horizon=4416589630) at ma_checkpoint.c:1048
#8  0x0074ef04 in really_execute_checkpoint () at ma_checkpoint.c:195
#9  0x0074ec8c in ma_checkpoint_execute (level=CHECKPOINT_MEDIUM,
    no_wait=1 '\001') at ma_checkpoint.c:132
#10 0x0074ff30 in ma_checkpoint_background (arg=0x1e) at ma_checkpoint.c:618

and of maria_write():
Thread 21 (process 1771983    ):
#0  0xff040094 in __lwp_park () from /lib/libc.so.1
#1  0xff0385ec in mutex_lock_queue () from /lib/libc.so.1
#2  0x007ae0fc in safe_mutex_lock (mp=0x329cd90, try_lock=0 '\0',
    file=0xa71bf0 "ma_state.c", line=561) at thr_mutex.c:153
#3  0x006d44cc in _ma_set_share_data_file_length (share=0x329c910,
    new_length=212992) at ma_state.c:561
#4  0x006ec070 in write_block_record (info=0x3555b18, old_record=0x0,
    record=0x32d6170 "\001", row=0x3555b68, bitmap_blocks=0x3555b68,
    head_block_is_read=0 '\0', row_pos=0xfe46e3f0, undo_lsn=1,
    old_record_checksum=0) at ma_blockrec.c:3018
#5  0x006ed290 in allocate_and_write_block_record (info=0x3555b18,
    record=0x32d6170 "\001", row=0x3555b68, undo_lsn=1) at ma_blockrec.c:3396
#6  0x006ed4dc in _ma_write_init_block_record (info=0x3555b18,
    record=0x32d6170 "\001") at ma_blockrec.c:3439
#7  0x007015c8 in maria_write (info=0x3555b18, record=0x32d6170 "\001")
    at ma_write.c:151
#8  0x006a8b98 in ha_maria::write_row (this=0x32d6040, buf=0x32d6170 "\001")
    at ha_maria.cc:968
#9  0x003c9550 in handler::ha_write_row (this=0x32d6040, buf=0x32d6170 "\001")
    at handler.cc:4572
#10 0x00307e08 in write_record (thd=0x32f1068, table=0x3138498, info=0x3287730)
    at sql_insert.cc:1570
#11 0x0030f7f0 in select_insert::send_data (this=0x3287708, values=@0x32f24b0)
    at sql_insert.cc:3093
#12 0x002e7ec0 in end_send (join=0x3287788, join_tab=0x35af4c0,
    end_of_records=false) at sql_select.cc:12111
#13 0x002e290c in evaluate_join_record (join=0x3287788, join_tab=0x35af330,
    error=0) at sql_select.cc:11371
#14 0x002e2f1c in sub_select (join=0x3287788, join_tab=0x35af330,
    end_of_records=false) at sql_select.cc:11256
#15 0x002e34e0 in do_select (join=0x3287788, fields=0x32f24b0, table=0x0,
    procedure=0x0) at sql_select.cc:11012
#16 0x00303db8 in JOIN::exec (this=0x3287788) at sql_select.cc:2205
#17 0x00304374 in mysql_select (thd=0x32f1068, rref_pointer_array=0x32f2514,
    tables=0x3287510, wild_num=1, fields=@0x32f24b0, conds=0x0, og_num=0,
    order=0x0, group=0x0, having=0x0, proc_param=0x0,
    select_options=3489942016, result=0x3287708, unit=0x32f2198,
    select_lex=0x32f2418) at sql_select.cc:2384
#18 0x00304788 in handle_select (thd=0x32f1068, lex=0x32f2138,
    result=0x3287708, setup_tables_done_option=1073741824) at sql_select.cc:279
#19 0x00253968 in mysql_execute_command (thd=0x32f1068) at sql_parse.cc:3144
#20 0x0025b2ac in mysql_parse (thd=0x32f1068,
    inBuf=0x32871b0 "INSERT INTO h SELECT * FROM d", length=29,
    found_semicolon=0xfe46fdb4) at sql_parse.cc:5811
#21 0x0025c008 in dispatch_command (command=COM_QUERY, thd=0x32f1068,
    packet=0x33d3e19 "INSERT INTO h SELECT * FROM d", packet_length=29)
    at sql_parse.cc:1208
[5 Dec 2008 15:46] Guilhem Bichot
http://lists.mysql.com/maria/341
[5 Dec 2008 22:27] Guilhem Bichot
better patch: http://lists.mysql.com/maria/347
[9 Dec 2008 10:10] Guilhem Bichot
queued to 5.1-maria
[15 Dec 2008 10:08] Bugs System
Pushed into 6.0.9-alpha  (revid:guilhem@mysql.com-20081209095602-s386roozg9nz0sua) (version source revid:guilhem@mysql.com-20081213204800-0nubni3t4ihn4hv9) (pib:5)
[9 Jan 2009 15:00] MC Brown
Internal only. No documentation needed.