| Bug #97243 | mysql always Unexpected crash and restart | ||
|---|---|---|---|
| Submitted: | 16 Oct 2019 5:47 | Modified: | 17 Oct 2019 2:03 |
| Reporter: | dongyang pan | Email Updates: | |
| Status: | Can't repeat | Impact on me: | |
| Category: | MySQL Server | Severity: | S1 (Critical) |
| Version: | 5.7.22 | OS: | Red Hat (6.7) |
| Assigned to: | CPU Architecture: | x86 | |
| Tags: | A long semaphore wait | ||
[16 Oct 2019 5:47]
dongyang pan
[16 Oct 2019 5:49]
dongyang pan
mysql-error
Attachment: mysql-error.rar (application/octet-stream, text), 1.02 MiB.
[16 Oct 2019 7:47]
MySQL Verification Team
Not enough information was provided for us to be able to handle this bug. Please re-read the instructions at http://bugs.mysql.com/how-to-report.php If you can provide more information, feel free to add it to this bug commenting it. Thank you for your interest in MySQL.
[17 Oct 2019 2:03]
dongyang pan
Description: mysql always Unexpected restart，and the error report a long semaphore wait。 when I check the error log,I found many insert due to a long semaphore timeout. last night,the mysql hang again.I execute pstack log to a file.please see it in attachment SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 5714507 --Thread 139510713825024 has waited at row0ins.cc line 2493 for 639.00 seconds the semaphore: S-lock on RW-latch at 0x7efcc967a018 created in file buf0buf.cc line 1460 a writer (thread id 139510695188224) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row0ins.cc line 2493 Last time write locked in file /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/storage/innobase/include/mtr0mtr.ic line 153 --Thread 139527699023616 has waited at row0ins.cc line 2493 for 639.00 seconds the semaphore: S-lock on RW-latch at 0x7efcc967a018 created in file buf0buf.cc line 1460 a writer (thread id 139510695188224) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row0ins.cc line 2493 Last time write locked in file /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/storage/innobase/include/mtr0mtr.ic line 153 --Thread 139526137444096 has waited at buf0flu.cc line 1209 for 571.00 seconds the semaphore: SX-lock on RW-latch at 0x7ef647449630 created in file buf0buf.cc line 1460 a writer (thread id 139510952974080) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file row0sel.cc line 3758 Last time write locked in file /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/storage/innobase/btr/btr0cur.cc line 315
[17 Oct 2019 2:19]
dongyang pan
pstack
Attachment: 114.log (application/octet-stream, text), 976.28 KiB.
[17 Oct 2019 3:47]
耀 赵
HI : When we analyze pstack , a possible reason is MySQLD cant't allocate a free block ? Thanks！！ detail as follow: ###1、a background worker thread for cleaner is hang for calloc when free page as : ``` Thread 620 (Thread 0x7ef5635fe700 (LWP 1221)): #0 0x000000356d2f80ce in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x000000356d27d265 in _L_lock_9671 () from /lib64/libc.so.6 #2 0x000000356d27a7f3 in calloc () from /lib64/libc.so.6 #3 0x0000000000f8efc8 in ut_allocator<unsigned char>::allocate(unsigned long, unsigned char const*, char const*, bool, bool) () #4 0x000000000113e3db in buf_LRU_free_page(buf_page_t*, bool) () #5 0x00000000011389c3 in buf_flush_do_batch(buf_pool_t*, buf_flush_t, unsigned long, unsigned long, unsigned long*) () #6 0x0000000001139858 in pc_flush_slot() () #7 0x000000000113b5b5 in buf_flush_page_cleaner_worker () #8 0x000000356d607a51 in start_thread () from /lib64/libpthread.so.0 #9 0x000000356d2e896d in clone () from /lib64/libc.so.6 ``` ###2、a lot of Thread wait detail as，can't get block ``` Thread 246 (Thread 0x7ef5c6cf4700 (LWP 1731)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x00000000010a3c92 in rw_lock_x_lock_func(rw_lock_t*, unsigned long, char const*, unsigned long) () #4 0x0000000001125ec9 in buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, bool) () #5 0x0000000001108680 in btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned long, mtr_t*) () Thread 282 (Thread 0x7ef5c7618700 (LWP 1693)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x00000000010a33e6 in rw_lock_s_lock_spin(rw_lock_t*, unsigned long, char const*, unsigned long) () #4 0x0000000001125e06 in buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, bool) () #5 0x0000000001108680 in btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned long, mtr_t*) () Thread 279 (Thread 0x7ef5c7555700 (LWP 1696)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x0000000000f8c1c4 in TTASEventMutex<GenericPolicy>::wait(char const*, unsigned int, unsigned int) () #4 0x0000000000f8c33b in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter(unsigned int, unsigned int, char const*, unsigned int) () #5 0x000000000113c3a8 in buf_LRU_buf_pool_running_out() () #6 0x000000000103ad33 in row_ins_sec_index_entry_low(unsigned long, unsigned long, dict_index_t*, mem_block_info_t*, mem_block_info_t*, dtuple_t*, unsigned long, que_thr_t*, bool) () ``` ###3、but some thread wait is diff as，some thread can't get free block: ``` Thread 45 (Thread 0x7ef52851a700 (LWP 17541)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x0000000000f8c1c4 in TTASEventMutex<GenericPolicy>::wait(char const*, unsigned int, unsigned int) () #4 0x0000000000f8c33b in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter(unsigned int, unsigned int, char const*, unsigned int) () #5 0x00000000011405a5 in buf_LRU_get_free_block(buf_pool_t*) () Thread 210 (Thread 0x7ef52b1ff700 (LWP 1777)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x0000000000f8c1c4 in TTASEventMutex<GenericPolicy>::wait(char const*, unsigned int, unsigned int) () #4 0x0000000000f8c33b in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter(unsigned int, unsigned int, char const*, unsigned int) () #5 0x00000000011405a5 in buf_LRU_get_free_block(buf_pool_t*) () #6 0x00000000011256c1 in buf_page_get_gen(page_id_t const&, page_size_t const&, unsigned long, buf_block_t*, unsigned long, char const*, unsigned long, mtr_t*, bool) () #7 0x0000000001108680 in btr_cur_search_to_nth_level(dict_index_t*, unsigned long, dtuple_t const*, page_cur_mode_t, unsigned long, btr_cur_t*, unsigned long, char const*, unsigned long, mtr_t*) () Thread 169 (Thread 0x7ef52a796700 (LWP 2056)): #0 0x000000356d2f80ce in __lll_lock_wait_private () from /lib64/libc.so.6 #1 0x000000356d27cf7e in _L_lock_5746 () from /lib64/libc.so.6 #2 0x000000356d278a8b in _int_free () from /lib64/libc.so.6 #3 0x0000000001190af6 in fil_space_extend(fil_space_t*, unsigned long) () #4 0x00000000007c05f8 in fsp_try_extend_data_file(fil_space_t*, unsigned char*, mtr_t*) () #5 0x0000000001197251 in fsp_reserve_free_extents(unsigned long*, unsigned long, unsigned long, fsp_reserve_t, mtr_t*, unsigned long) () #6 0x000000000111984e in PageBulk::init() () Thread 145 (Thread 0x7ef52a17e700 (LWP 13853)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x0000000000f8c1c4 in TTASEventMutex<GenericPolicy>::wait(char const*, unsigned int, unsigned int) () #4 0x0000000000f8c33b in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter(unsigned int, unsigned int, char const*, unsigned int) () #5 0x000000000111d6b3 in buf_page_make_young(buf_page_t*) () #6 0x0000000000fbb268 in ibuf_update_free_bits_zip(buf_block_t*, mtr_t*) () Thread 61 (Thread 0x7ef52892a700 (LWP 17525)): #0 0x000000356d60b63c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0 #1 0x0000000000ffb03b in os_event::wait_low(long) () #2 0x00000000010a0ce9 in sync_array_wait_event(sync_array_t*, sync_cell_t*&) () #3 0x0000000000f8c1c4 in TTASEventMutex<GenericPolicy>::wait(char const*, unsigned int, unsigned int) () #4 0x0000000000f8c33b in PolicyMutex<TTASEventMutex<GenericPolicy> >::enter(unsigned int, unsigned int, char const*, unsigned int) () #5 0x0000000001122792 in buf_page_init_for_read(dberr_t*, unsigned long, page_id_t const&, page_size_t const&, unsigned long) () #6 0x000000000114298b in buf_read_page_low(dberr_t*, bool, unsigned long, unsigned long, page_id_t const&, page_size_t const&, bool) () ```
