Bug #58975 Possible infinite loop during shutdown, waiting for page cleaner thread
Submitted: 16 Dec 2010 14:14 Modified: 11 Jan 2011 1:45
Reporter: Vasil Dimov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.6 OS:Any
Assigned to: Inaam Rana CPU Architecture:Any

[16 Dec 2010 14:14] Vasil Dimov 
Description:
Random tests timeout on PB2 in mysql-trunk-innodb, see
http://pb2.norway.sun.com/?template=show_pushes&branch=mysql-trunk-innodb-pb2

the timeouts from Solaris provide the following backtraces:

current thread: t@1
  [1] __lwp_kill(0x0, 0x6, 0xffffffff7e648240, 0xffffffff7e6476b4, 0xffffffff7f400200, 0x4), at 0xffffffff7e4daf1c 
=>[2] my_write_core(sig = 6), line 423 in "stacktrace.c"
  [3] signal_handler(sig = 6), line 8161 in "mysqltest.cc"
  [4] __sighndlr(0x6, 0x0, 0xffffffff7fffbb00, 0x1001ec8c8, 0x0, 0x0), at 0xffffffff7e4d6fdc 
  ---- called from signal handler with signal 6 (SIGABRT) ------
  [5] __pollsys(0x4, 0x0, 0xffffffff7fffc000, 0x0, 0x0, 0x0), at 0xffffffff7e4daaf8 
  [6] _pollsys(0xffffffff7fffbf40, 0x0, 0xffffffff7fffc000, 0x0, 0x0, 0x0), at 0xffffffff7e4c98c4 
  [7] _pselect(0x0, 0xffffffff7fffbf40, 0xffffffff7e6448c8, 0xffffffff7e6448c8, 0xffffffff7fffc000, 0x0), at 0xffffffff7e4748d4 
  [8] _select(0x0, 0x0, 0x0, 0x0, 0xffffffff7fffc0c8, 0x0), at 0xffffffff7e474c78 
  [9] os_thread_sleep(tm = 100000U), line 274 in "os0thread.c"
  [10] logs_empty_and_mark_files_at_shutdown(), line 3250 in "log0log.c"
  [11] innobase_shutdown_for_mysql(), line 2119 in "srv0start.c"
  [12] innobase_end(hton = 0x102819380, type = HA_PANIC_CLOSE), line 2751 in "ha_innodb.cc"
  [13] ha_finalize_handlerton(plugin = 0x102815348), line 420 in "handler.cc"
  [14] plugin_deinitialize(plugin = 0x102815348, ref_check = true), line 885 in "sql_plugin.cc"
  [15] reap_plugins(), line 960 in "sql_plugin.cc"
  [16] plugin_shutdown(), line 1602 in "sql_plugin.cc"
  [17] clean_up(print_message = false), line 1455 in "mysqld.cc"
  [18] end_embedded_server(), line 608 in "lib_sql.cc"
  [19] mysql_server_end(), line 203 in "libmysql.c"
  [20] free_used_memory(), line 1292 in "mysqltest.cc"
  [21] cleanup_and_exit(exit_code = 0), line 1301 in "mysqltest.cc"
  [22] main(argc = 18, argv = 0xffffffff7fffd0f8), line 8864 in "mysqltest.cc"
current thread: t@1
  [1] __lwp_kill(0x0, 0x6, 0xffffffff7e648240, 0xffffffff7e6476b4, 0xffffffff7f400200, 0x4), at 0xffffffff7e4daf1c 
=>[2] my_write_core(sig = 6), line 423 in "stacktrace.c"
  [3] signal_handler(sig = 6), line 8161 in "mysqltest.cc"
  [4] __sighndlr(0x6, 0x0, 0xffffffff7fffbb00, 0x1001ec8c8, 0x0, 0x0), at 0xffffffff7e4d6fdc 
  ---- called from signal handler with signal 6 (SIGABRT) ------
  [5] __pollsys(0x4, 0x0, 0xffffffff7fffc000, 0x0, 0x0, 0x0), at 0xffffffff7e4daaf8 
  [6] _pollsys(0xffffffff7fffbf40, 0x0, 0xffffffff7fffc000, 0x0, 0x0, 0x0), at 0xffffffff7e4c98c4 
  [7] _pselect(0x0, 0xffffffff7fffbf40, 0xffffffff7e6448c8, 0xffffffff7e6448c8, 0xffffffff7fffc000, 0x0), at 0xffffffff7e4748d4 
  [8] _select(0x0, 0x0, 0x0, 0x0, 0xffffffff7fffc0c8, 0x0), at 0xffffffff7e474c78 
  [9] os_thread_sleep(tm = 100000U), line 274 in "os0thread.c"
  [10] logs_empty_and_mark_files_at_shutdown(), line 3250 in "log0log.c"
  [11] innobase_shutdown_for_mysql(), line 2119 in "srv0start.c"
  [12] innobase_end(hton = 0x102819380, type = HA_PANIC_CLOSE), line 2751 in "ha_innodb.cc"
  [13] ha_finalize_handlerton(plugin = 0x102815348), line 420 in "handler.cc"
  [14] plugin_deinitialize(plugin = 0x102815348, ref_check = true), line 885 in "sql_plugin.cc"
  [15] reap_plugins(), line 960 in "sql_plugin.cc"
  [16] plugin_shutdown(), line 1602 in "sql_plugin.cc"
  [17] clean_up(print_message = false), line 1455 in "mysqld.cc"
  [18] end_embedded_server(), line 608 in "lib_sql.cc"
  [19] mysql_server_end(), line 203 in "libmysql.c"
  [20] free_used_memory(), line 1292 in "mysqltest.cc"
  [21] cleanup_and_exit(exit_code = 0), line 1301 in "mysqltest.cc"
  [22] main(argc = 18, argv = 0xffffffff7fffd0f8), line 8864 in "mysqltest.cc"
current thread: t@2
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f400a00), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102ce6898, 0x102ce6858, 0x0, 0x4, 0x16bbcc, 0xffffffff7df0fd40), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102ce6898, 0x102ce6858, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102ce6898, 0x102ce6858, 0x0, 0x10030343c, 0x0, 0x0), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102ce6898, 0x102ce6858, 0xffffffff7e648240, 0x102ce6844, 0xffffffff7f400a00, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102ce6898, mp = 0x102ce6840, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102ce6898, mutex = 0x102ce6840), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102ce6840, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] os_aio_simulated_handle(global_segment = 0, message1 = 0xffffffff7d3fbe58, message2 = 0xffffffff7d3fbe50, type = 0xffffffff7d3fbe48), line 4944 in "os0file.c"
  [10] fil_aio_wait(segment = 0), line 4544 in "fil0fil.c"
  [11] io_handler_thread(arg = 0x10266d2d8), line 483 in "srv0start.c"
current thread: t@3
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f401200), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102ce6928, 0x102ce68e8, 0x0, 0x4, 0x16bbcc, 0xffffffff7df0f0c0), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102ce6928, 0x102ce68e8, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102ce6928, 0x102ce68e8, 0x0, 0x0, 0x0, 0x1000000), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102ce6928, 0x102ce68e8, 0xffffffff7e648240, 0x102ce68d4, 0xffffffff7f401200, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102ce6928, mp = 0x102ce68d0, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102ce6928, mutex = 0x102ce68d0), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102ce68d0, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] os_aio_simulated_handle(global_segment = 1U, message1 = 0xffffffff7d1fbe58, message2 = 0xffffffff7d1fbe50, type = 0xffffffff7d1fbe48), line 4944 in "os0file.c"
  [10] fil_aio_wait(segment = 1U), line 4544 in "fil0fil.c"
  [11] io_handler_thread(arg = 0x10266d2e0), line 483 in "srv0start.c"
current thread: t@4
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f401a00), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102ce69b8, 0x102ce6978, 0x0, 0x4, 0x16bbcc, 0xffffffff7df0f440), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102ce69b8, 0x102ce6978, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102ce69b8, 0x102ce6978, 0x0, 0x0, 0x0, 0xffffffff7f401a00), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102ce69b8, 0x102ce6978, 0xffffffff7e648240, 0x102ce6964, 0xffffffff7f401a00, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102ce69b8, mp = 0x102ce6960, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102ce69b8, mutex = 0x102ce6960), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102ce6960, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] os_aio_simulated_handle(global_segment = 2U, message1 = 0xffffffff7cffbe58, message2 = 0xffffffff7cffbe50, type = 0xffffffff7cffbe48), line 4944 in "os0file.c"
  [10] fil_aio_wait(segment = 2U), line 4544 in "fil0fil.c"
  [11] io_handler_thread(arg = 0x10266d2e8), line 483 in "srv0start.c"
...

How to repeat:
...
current thread: t@5
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f402200), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102ce6a48, 0x102ce6a08, 0x0, 0x4, 0x16bbcc, 0xffffffff7df0ebc0), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102ce6a48, 0x102ce6a08, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102ce6a48, 0x102ce6a08, 0x0, 0x0, 0x0, 0xffffffff7f402200), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102ce6a48, 0x102ce6a08, 0xffffffff7e648240, 0x102ce69f4, 0xffffffff7f402200, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102ce6a48, mp = 0x102ce69f0, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102ce6a48, mutex = 0x102ce69f0), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102ce69f0, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] os_aio_simulated_handle(global_segment = 3U, message1 = 0xffffffff7cdfbe58, message2 = 0xffffffff7cdfbe50, type = 0xffffffff7cdfbe48), line 4944 in "os0file.c"
  [10] fil_aio_wait(segment = 3U), line 4544 in "fil0fil.c"
  [11] io_handler_thread(arg = 0x10266d2f0), line 483 in "srv0start.c"
current thread: t@6
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f402a00), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102ce6ad8, 0x102ce6a98, 0x0, 0x4, 0x16bbcc, 0xffffffff7df0ef40), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102ce6ad8, 0x102ce6a98, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102ce6ad8, 0x102ce6a98, 0x0, 0x0, 0x0, 0xffffffff7f402a00), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102ce6ad8, 0x102ce6a98, 0xffffffff7e648240, 0x102ce6a84, 0xffffffff7f402a00, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102ce6ad8, mp = 0x102ce6a80, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102ce6ad8, mutex = 0x102ce6a80), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102ce6a80, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] os_aio_simulated_handle(global_segment = 4U, message1 = 0xffffffff7cbfbe58, message2 = 0xffffffff7cbfbe50, type = 0xffffffff7cbfbe48), line 4944 in "os0file.c"
  [10] fil_aio_wait(segment = 4U), line 4544 in "fil0fil.c"
  [11] io_handler_thread(arg = 0x10266d2f8), line 483 in "srv0start.c"
current thread: t@7
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f403200), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102ce6b68, 0x102ce6b28, 0x0, 0x4, 0x16bbcc, 0xffffffff7df0e2c0), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102ce6b68, 0x102ce6b28, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102ce6b68, 0x102ce6b28, 0x0, 0x0, 0x0, 0xffffffff7f403200), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102ce6b68, 0x102ce6b28, 0xffffffff7e648240, 0x102ce6b14, 0xffffffff7f403200, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102ce6b68, mp = 0x102ce6b10, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102ce6b68, mutex = 0x102ce6b10), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102ce6b10, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] os_aio_simulated_handle(global_segment = 5U, message1 = 0xffffffff7c9fbe58, message2 = 0xffffffff7c9fbe50, type = 0xffffffff7c9fbe48), line 4944 in "os0file.c"
  [10] fil_aio_wait(segment = 5U), line 4544 in "fil0fil.c"
  [11] io_handler_thread(arg = 0x10266d300), line 483 in "srv0start.c"
current thread: t@12
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f405200), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x10281a1a8, 0x10281a168, 0x0, 0x4, 0x16bbcc, 0xffffffff7df08bc0), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x10281a1a8, 0x10281a168, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x10281a1a8, 0x10281a168, 0x0, 0x0, 0x0, 0x1000000), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x10281a1a8, 0x10281a168, 0xffffffff7e648240, 0x10281a154, 0xffffffff7f405200, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x10281a1a8, mp = 0x10281a150, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x10281a1a8, mutex = 0x10281a150), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x10281a150, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] srv_master_thread(arg = (nil)), line 2556 in "srv0srv.c"
current thread: t@13
=>[1] __lwp_park(0x4, 0x0, 0x0, 0x1, 0x0, 0xffffffff7f405a00), at 0xffffffff7e4d6f54 
  [2] cond_sleep_queue(0x102d48bf8, 0x102d48bb8, 0x0, 0x4, 0x16bbcc, 0xffffffff7df08dc0), at 0xffffffff7e4d0550 
  [3] cond_wait_queue(0x102d48bf8, 0x102d48bb8, 0x0, 0x0, 0xffffffff7e649fc8, 0x0), at 0xffffffff7e4d073c 
  [4] cond_wait(0x102d48bf8, 0x102d48bb8, 0x0, 0x0, 0x0, 0x1), at 0xffffffff7e4d0cc0 
  [5] _pthread_cond_wait(0x102d48bf8, 0x102d48bb8, 0xffffffff7e648240, 0x102d48ba4, 0xffffffff7f405a00, 0x0), at 0xffffffff7e4d0cfc 
  [6] safe_cond_wait(cond = 0x102d48bf8, mp = 0x102d48ba0, file = 0x102061450 "/tmp/pb2/build/sb_1-2668940-1292428909.09/mysql-5.6.1-m5/storage/innobase/os/os0sync.c", line = 207U), line 240 in "thr_mutex.c"
  [7] os_cond_wait(cond = 0x102d48bf8, mutex = 0x102d48ba0), line 207 in "os0sync.c"
  [8] os_event_wait_low(event = 0x102d48ba0, reset_sig_count = 0), line 634 in "os0sync.c"
  [9] buf_flush_wait_batch_end(buf_pool = (nil), type = BUF_FLUSH_LIST), line 1878 in "buf0flu.c"
  [10] buf_flush_page_cleaner_thread(arg = (nil)), line 2434 in "buf0flu.c"
[16 Dec 2010 14:58] Bugs System 
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/127088

3392 Inaam Rana	2010-12-16
      bug#58975
      Make sure that buf_flush_list() is called at least once in the
      page_cleaner code path before we wait on buf_flush_wait_batch_end().
      This ensures that buf_pool->no_flush[BUF_FLUSH_LIST] event will be
      set and the page_cleaner will not end up in infinite wait.
      This fix does that by changing the SRV_SHUTDOWN_CLEANUP while loop to
      a do..while loop.
      
      approved by: Marko
[22 Dec 2010 21:30] Bugs System 
Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101222212842-y0t3ibtd32wd9qaw) (version source revid:alexander.nozdrin@oracle.com-20101222212842-y0t3ibtd32wd9qaw) (merge vers: 5.6.1) (pib:24)
[29 Jan 2014 20:21] MySQL Verification Team 
i hit this today on 5.6.17, will file a new bug if I hit it again.

Version: '5.5.37'  socket: ''  port: 3307  MySQL Community Server (GPL)
140129 22:18:06 [Note] mysqld: Normal shutdown

140129 22:18:08 [Warning] mysqld: Forcing close of thread 8  user: 'root'

140129 22:18:08  InnoDB: Starting shutdown...
140129 22:19:08  InnoDB: Waiting for master thread to be suspended
140129 22:20:11  InnoDB: Waiting for master thread to be suspended
140129 22:21:11  InnoDB: Waiting for master thread to be suspended

KERNELBASE!SleepEx+0xab
mysqld!logs_empty_and_mark_files_at_shutdown+0x5a [d:\build\mysql-5.5\storage\innobase\log\log0log.c @ 3207]
mysqld!innobase_shutdown_for_mysql+0x58 [d:\build\mysql-5.5\storage\innobase\srv\srv0start.c @ 2143]
mysqld!innobase_end+0x46 [d:\build\mysql-5.5\storage\innobase\handler\ha_innodb.cc @ 2624]
mysqld!ha_finalize_handlerton+0x54 [d:\build\mysql-5.5\sql\handler.cc @ 491]
mysqld!plugin_deinitialize+0x47 [d:\build\mysql-5.5\sql\sql_plugin.cc @ 922]
mysqld!reap_plugins+0x10a [d:\build\mysql-5.5\sql\sql_plugin.cc @ 997]
mysqld!plugin_shutdown+0xdf [d:\build\mysql-5.5\sql\sql_plugin.cc @ 1645]
mysqld!clean_up+0xba [d:\build\mysql-5.5\sql\mysqld.cc @ 1492]
mysqld!unireg_end+0xb [d:\build\mysql-5.5\sql\mysqld.cc @ 1403]
mysqld!kill_server+0xb9 [d:\build\mysql-5.5\sql\mysqld.cc @ 1334]
mysqld!handle_shutdown+0x44 [d:\build\mysql-5.5\sql\mysqld.cc @ 2873]
mysqld!pthread_start+0x1e [d:\build\mysql-5.5\mysys\my_winthread.c @ 63]
mysqld!_callthreadstartex+0x17 [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c @ 314]
mysqld!_threadstartex+0x7f [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\threadex.c @ 292]