[MDEV-13736] MariaDB Server 5.5.54 hangs up during shutdown Created: 2017-09-05  Updated: 2018-09-26

Status: Stalled
Project: MariaDB Server
Component/s: Storage Engine - Aria
Affects Version/s: 5.5.54
Fix Version/s: 5.5

Type: Bug Priority: Major
Reporter: Michael Graf Assignee: Oleksandr Byelkin
Resolution: Unresolved Votes: 0
Labels: None
Environment:

Windows Server 2016 Datacenter


Attachments: File HH-VMESX-ZIS01.err     Text File dmp.txt     File my.ini     Zip Archive mysqld_20170904.zip    
Issue Links:
Relates
relates to MDEV-689 LP:619666 - Deadlock with Aria around... Closed
relates to MDEV-13635 MariaDB Server 10.2.6 hangs up during... Open
Sprint: 5.5.59

 Description   

MariaDB was shutdown by service manager and hanged up for more than 12 hours.
Nothing happened anymore.
The process was killed after 12 hours with the tsak manager.
A minidump was created before the process was killed.



 Comments   
Comment by Elena Stepanova [ 2017-09-19 ]

~400 threads doing this

1      [External Code]
 2      mysqld.exe!open_table(THD * thd=0x00000000fffffff0, TABLE_LIST * table_list=0x0000000000000000, st_mem_root * mem_root=0x0000000000000000, Open_table_context * ot_ctx=0x00007ff648298571)
 3      mysqld.exe!open_and_process_table(THD * thd=0x000001e4a9d99600, LEX * lex=0x00000021340fdd50, TABLE_LIST * tables=0x0000000000000000, unsigned int * counter=0x000001e4a5cb9750, unsigned int flags=0, Prelocking_strategy * prelocking_strategy=0x00000021340fdd50, bool has_prelocking_list=false, Open_table_context * ot_ctx=0x00000021340fdb90, st_mem_root * new_frm_mem=0x00000021340fdbc0)
 4      mysqld.exe!open_tables(THD * thd=0x00007ff600000004, TABLE_LIST * * start=0x0000000000000000, unsigned int * counter=0x00000021340fdcb0, unsigned int flags=0, Prelocking_strategy * prelocking_strategy=0x00000021340fdd50)
 5      mysqld.exe!open_and_lock_tables(THD * thd=0x00007ff600000001, TABLE_LIST * tables=0x000001e4a5cb9750, bool derived=false, unsigned int flags=2781582654, Prelocking_strategy * prelocking_strategy=0x00000021340fdd50)
 6      mysqld.exe!mysql_insert(THD * thd=0x000001e4a9d98900, TABLE_LIST * table_list=0x00000021340fe000, List<Item> & fields, List<List<Item> > & values_list, List<Item> & update_fields, List<Item> & update_values, enum_duplicates duplic=DUP_ERROR, bool ignore=false)
 7      mysqld.exe!mysql_execute_command(THD * thd=0x000001e4a9d989b0)
 8      mysqld.exe!mysql_parse(THD * thd=0x000001e4a9d96090, char * rawbuf=0x00000021340feb00, unsigned int length=0, Parser_state * parser_state=0x0624dd2f1a9fbe77)
 9      mysqld.exe!dispatch_command(enum_server_command command=COM_SLEEP, THD * thd=0x000001e400007530, char * packet=0x0000000000000000, unsigned int packet_length=2745315360)
 10     mysqld.exe!do_command(THD * thd=0x0000000000000000)
 11     mysqld.exe!do_handle_one_connection(THD * thd_arg=0x000001e4a9d96090)
 12     mysqld.exe!handle_one_connection(void * arg=0x000001e4c48cf140)
 13     mysqld.exe!pthread_start(void * p=0x0000000000000000)
 14     [External Code]

with some variations, e.g.

1      [External Code]
 2      mysqld.exe!maria_create(const char * name=0x00000000000007b0, data_file_type datafile_type=872403440, unsigned int keys=124, st_maria_keydef * keydefs=0x0000000000000066, unsigned int columns=21, st_maria_columndef * columndef=0x000001e4c6a2e2a0, unsigned int uniques=0, st_maria_unique_def * uniquedefs=0x0000002133ffd120, st_maria_create_info * ci=0x0000002133ffd140, unsigned int flags=4)
 3      mysqld.exe!create_internal_tmp_table(TABLE * table=0x000001e4c4ad86d0, st_key * keyinfo=0x000001e4c4ad86d0, st_maria_columndef * start_recinfo=0x000001e4c6a2e2a0, st_maria_columndef * * recinfo=0x000001e4c4ad8730, unsigned __int64 options=2147752704)
 4      mysqld.exe!create_tmp_table(THD * thd=0x00007ff647f20000, TMP_TABLE_PARAM * param=0x0000000000000014, List<Item> & fields={...}, st_order * group=0x0000000000000002, bool distinct=false, bool save_sum_fields=false, unsigned __int64 select_options=2147752704, unsigned __int64 rows_limit=18446744073709551615, const char * table_alias=0x000001e48dba4510, bool do_not_open=false, bool keep_row_order=true)
 5      mysqld.exe!create_schema_table(THD * thd=0x000001e48dba4518, TABLE_LIST * table_list=0x000001e48dba4518)
 6      mysqld.exe!mysql_schema_table(THD * thd=0x0000000000000000, LEX * lex=0x000001e48dba4518, TABLE_LIST * table_list=0x000001e4c48c9a40)
 7      mysqld.exe!open_and_process_table(THD * thd=0x000001e48dba4500, LEX * lex=0x0000000000000000, TABLE_LIST * tables=0x0000000000000000, unsigned int * counter=0x000001e48dba4518, unsigned int flags=0, Prelocking_strategy * prelocking_strategy=0x0000002133ffdaa0, bool has_prelocking_list=false, Open_table_context * ot_ctx=0x0000002133ffd930, st_mem_root * new_frm_mem=0x0000002133ffd960)
 8      mysqld.exe!open_tables(THD * thd=0x0000737574617473, TABLE_LIST * * start=0x0000000000000000, unsigned int * counter=0x0000002133ffda50, unsigned int flags=0, Prelocking_strategy * prelocking_strategy=0x0000002133ffdaa0)
 9      mysqld.exe!open_and_lock_tables(THD * thd=0x000001e400000000, TABLE_LIST * tables=0x000001e48dba4518, bool derived=32, unsigned int flags=3297550768, Prelocking_strategy * prelocking_strategy=0x0000002133ffdaa0)
 10     mysqld.exe!execute_sqlcom_select(THD * thd=0x000001e48dba4518, TABLE_LIST * all_tables=0x000001e4c48c9a00)
 11     mysqld.exe!mysql_execute_command(THD * thd=0x000001e4c48c9a40)
 12     mysqld.exe!mysql_parse(THD * thd=0x000001e4c48c7120, char * rawbuf=0x0000002133ffeae0, unsigned int length=0, Parser_state * parser_state=0x0624dd2f1a9fbe77)
 13     mysqld.exe!dispatch_command(enum_server_command command=COM_SLEEP, THD * thd=0x000001e400007530, char * packet=0x0000000000000000, unsigned int packet_length=2745321200)
 14     mysqld.exe!do_command(THD * thd=0x0000000000000000)
 15     mysqld.exe!do_handle_one_connection(THD * thd_arg=0x000001e4c48c7120)
 16     mysqld.exe!handle_one_connection(void * arg=0x000001e4c48c7120) [^dmp.txt] 
 17     mysqld.exe!pthread_start(void * p=0x0000000000000000)
 18     [External Code]

And one thread in the usual translog_flush_wait_for_end:

 1      [External Code]
 2      mysqld.exe!pthread_cond_timedwait(pthread_cond_t * cond=0x0000000000000000, _RTL_CRITICAL_SECTION * mutex=0x0000000000000000, const timespec * abstime=0x0000000000000000)
 3      mysqld.exe!translog_flush_wait_for_end(__int64 lsn=13861198974)
 4      mysqld.exe!translog_flush(__int64 lsn=0)
 5      mysqld.exe!pagecache_fwrite(st_pagecache * pagecache=0x000001e169613020, st_pagecache_file * filedesc=0x00000021383f9760, unsigned char * buffer=0x0000000000000001, unsigned __int64 pageno=36, pagecache_page_type type=PAGECACHE_PLAIN_PAGE, int flags=36)
 6      mysqld.exe!flush_cached_blocks(st_pagecache * pagecache=0x0000000000000002, st_pagecache_file * file=0x000001e4c271c1e8, st_pagecache_block_link * * cache=0x0000000000000000, st_pagecache_block_link * * end=0x00007ff6ffffffff, flush_type type=FLUSH_RELEASE, int * first_errno=0x0000000000000000)
 7      mysqld.exe!flush_pagecache_blocks_int(st_pagecache * pagecache=0x00007ff6490d3b80, st_pagecache_file * file=0x0000000000000001, flush_type type=1225603968, pagecache_flush_filter_result(*)(pagecache_page_type, unsigned __int64, __int64, void *) filter=0x0000000000000000, void * filter_arg=0x0000000000000000)
 8      mysqld.exe!flush_pagecache_blocks_with_filter(st_pagecache * pagecache=0x000001e4c271b8c0, st_pagecache_file * file=0x0000000000000000, flush_type type=FLUSH_IGNORE_CHANGED, pagecache_flush_filter_result(*)(pagecache_page_type, unsigned __int64, __int64, void *) filter=0x0000000000000000, void * filter_arg=0x0000000000000000)
 9      mysqld.exe!_ma_once_end_block_record(st_maria_share * share=0x0000000000000002)
 10     mysqld.exe!maria_close(st_maria_handler * info=0x000001e4a5e1ea00)
 11     mysqld.exe!closefrm(TABLE * table=0x000001e4c693e4f0, bool free_share=64)
 12     mysqld.exe!intern_close_table(TABLE * table=0x000001e4c5f7a978)
 13     mysqld.exe!free_cache_entry(TABLE * table=0x000001e4826af36c)
 14     mysqld.exe!open_table(THD * thd=0x0000000000000005, TABLE_LIST * table_list=0x00007ffca9567a88, st_mem_root * mem_root=0x000001e4c1311ee8, Open_table_context * ot_ctx=0x0000000000000000)
 15     mysqld.exe!open_and_process_table(THD * thd=0x000001e4a3d7b700, LEX * lex=0x00000021383fe190, TABLE_LIST * tables=0x0000000000000000, unsigned int * counter=0x000001e4c45b0f30, unsigned int flags=0, Prelocking_strategy * prelocking_strategy=0x00000021383fe190, bool has_prelocking_list=false, Open_table_context * ot_ctx=0x00000021383fdfd0, st_mem_root * new_frm_mem=0x00000021383fe000)
 16     mysqld.exe!open_tables(THD * thd=0x000001e100000004, TABLE_LIST * * start=0x0000002100000000, unsigned int * counter=0x00000021383fe0f0, unsigned int flags=0, Prelocking_strategy * prelocking_strategy=0x00000021383fe190)
 17     mysqld.exe!open_and_lock_tables(THD * thd=0x000001e100000001, TABLE_LIST * tables=0x000001e4c45b0f30, bool derived=false, unsigned int flags=3294301617, Prelocking_strategy * prelocking_strategy=0x00000021383fe190)
 18     mysqld.exe!mysql_insert(THD * thd=0x000001e4a3d7aa00, TABLE_LIST * table_list=0x00000021383fe440, List<Item> & fields, List<List<Item> > & values_list, List<Item> & update_fields, List<Item> & update_values, enum_duplicates duplic=DUP_ERROR, bool ignore=false)
 19     mysqld.exe!mysql_execute_command(THD * thd=0x000001e4a3d7aa50)
 20     mysqld.exe!mysql_parse(THD * thd=0x000001e4a3d78130, char * rawbuf=0x00000021383fef40, unsigned int length=0, Parser_state * parser_state=0x0624dd2f1a9fbe77)
 21     mysqld.exe!dispatch_command(enum_server_command command=COM_SLEEP, THD * thd=0x000001e400007530, char * packet=0x0000000000000000, unsigned int packet_length=2822589376)
 22     mysqld.exe!do_command(THD * thd=0x0000000000000000)
 23     mysqld.exe!do_handle_one_connection(THD * thd_arg=0x000001e4a3d78130)
 24     mysqld.exe!handle_one_connection(void * arg=0x000001e4c742c130)
 25     mysqld.exe!pthread_start(void * p=0x0000000000000000)
 26     [External Code]

But lsn values in translog_flush_wait_for_end and translog_flush frames are weird.

All threads attached as dmp.txt

Comment by Elena Stepanova [ 2017-09-21 ]

>Debug.Print log_descriptor
{pagecache=0x00007ff6490d4540 {mysqld.exe!st_pagecache maria_log_pagecache_var} {mem_size=2097152 min_warm_blocks=...} ...}
    pagecache: 0x00007ff6490d4540 {mysqld.exe!st_pagecache maria_log_pagecache_var} {mem_size=2097152 min_warm_blocks=...}
    flags: 0
    open_flags: 32770
    log_file_max_size: 1073741824
    server_version: 50554
    server_id: 1
    buffer_capacity_chunk_2: 1047552
    half_buffer_capacity_chunk_2: 523776
    page_overhead: 7
    page_capacity_chunk_2: 8184
    directory: 0x00007ff6488bac98 "d:\\leutek\\mariadb\\data\\"
    open_files: {buffer=0x000001e1594c2830 <Error reading characters of string.> elements=1 max_element=10 ...}
    max_file: 3
    min_file: 3
    open_files_lock: {m_rwlock={srwlock={Ptr=0x0000000000000000 } have_exclusive_srwlock=0 lock={DebugInfo=0x0000000000000000 <NULL> ...} ...} ...}
    directory_fd: -1
    buffers: 0x00007ff6488baf98 {{buffer=0x00007ff6488baf98 "ëÐ\x1\x3" last_lsn=0 prev_last_lsn=13861198974 ...}, ...}
    dirty_buffer_mask: 1 '\x1'
    dirty_buffer_mask_lock: {m_mutex={DebugInfo=0xffffffffffffffff {Type=??? CreatorBackTraceIndex=??? CriticalSection=??? ...} ...} ...}
    horizon: 13861198977
    bc: {ptr=0x00007ff6488bcc19 "ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ... ...}
    max_lsn: 13861198974
    flushed: 13861198400
    sent_to_disk: 13861198974
    log_start: 13309691344
    previous_flush_horizon: 13861197911
    in_buffers_only: 13861191680
    sent_to_disk_lock: {m_mutex={DebugInfo=0x000001e4a884d970 {Type=??? CreatorBackTraceIndex=??? CriticalSection=??? ...} ...} ...}
    log_flush_lock: {m_mutex={DebugInfo=0x000001e4c043d3e0 {Type=??? CreatorBackTraceIndex=??? CriticalSection=??? ...} ...} ...}
    log_flush_cond: {m_cond={native_cond={Ptr=0x00000021383f9130 } waiting=943690032 lock_waiting={DebugInfo=0x0000000000000000 <NULL> ...} ...} ...}
    new_goal_cond: {m_cond={native_cond={Ptr=0x0000000000000000 } waiting=0 lock_waiting={DebugInfo=0x0000000000000000 <NULL> ...} ...} ...}
    file_header_lock: {m_mutex={DebugInfo=0xffffffffffffffff {Type=??? CreatorBackTraceIndex=??? CriticalSection=??? ...} ...} ...}
    unfinished_files_lock: {m_mutex={DebugInfo=0xffffffffffffffff {Type=??? CreatorBackTraceIndex=??? CriticalSection=??? ...} ...} ...}
    unfinished_files: {buffer=0x000001e1594c2530 <Error reading characters of string.> elements=0 max_element=10 ...}
    min_need_file: 3
    min_file_number: 3
    purger_lock: {m_mutex={DebugInfo=0xffffffffffffffff {Type=??? CreatorBackTraceIndex=??? CriticalSection=??? ...} ...} ...}
    last_lsn_checked: 0
    is_everything_flushed: 1 '\x1'
    flush_in_progress: 0 '\0'
    flush_no: 1692666
    next_pass_max_lsn: 0
    max_lsn_requester: 8824

Comment by Oleksandr Byelkin [ 2018-01-10 ]

Need debugging by meditation (lack of data and again only windows, probably something windows specific).

Generated at Thu Feb 08 08:07:57 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.