[MDEV-14080] InnoDB shutdown sometimes hangs Created: 2017-10-16  Updated: 2018-05-24  Resolved: 2017-12-01

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.2, 10.3
Fix Version/s: 10.2.12, 10.3.3

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-5800 indexes on virtual (not materialized)... Closed
relates to MDEV-11499 mysqltest, Windows : improve diagnost... Closed
relates to MDEV-11802 innodb.innodb_bug14676111 fails in bu... Closed
relates to MDEV-12700 Allow innodb_read_only startup withou... Closed
relates to MDEV-13472 rpl.rpl_semi_sync_wait_point crashes ... Closed
relates to MDEV-13603 innodb_fast_shutdown=0 may fail to pu... Closed
relates to MDEV-15554 InnoDB page_cleaner shutdown sometime... Closed
relates to MDEV-14486 InnoDB hang on shutdown Confirmed

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-deb-xenial-amd64/builds/2169/steps/mtr/logs/stdio

innodb.row_format_redundant 'innodb'     w1 [ fail ]
 
        Test ended at 2017-10-13 18:14:11
 
 
 
CURRENT_TEST: innodb.row_format_redundant
 
mysqltest: At line 74: query 'SELECT COUNT(*) FROM t1' failed: 1286: Unknown storage engine 'InnoDB'
 
 
 
The result from queries just before the failure was:
 
< snip >
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
insert into t1 select * from t1;
 
SET GLOBAL innodb_file_per_table=OFF;
 
create table t2 (a int not null, d varchar(15) not null, b
 
varchar(198) not null, c char(156), fulltext ftsic(c)) engine=InnoDB
 
row_format=redundant;
 
insert into t2 select * from t1;
 
create table t3 (a int not null, d varchar(15) not null, b varchar(198),
 
c varchar(150), index k1(c(99), b(56)), index k2(b(5), c(10))) engine=InnoDB
 
row_format=redundant;
 
insert into t3 values(444, 'dddd', 'bbbbb', 'aaaaa');
 
insert into t3 values(555, 'eeee', 'ccccc', 'aaaaa');
 
SET GLOBAL innodb_fast_shutdown=0;
 
SELECT COUNT(*) FROM t1;
 
 
 
Retrying test innodb.row_format_redundant, attempt(2/3)...
 
 
 
worker[1] > Restart  - not started
 
***Warnings generated in error logs during shutdown after running tests: innodb.row_format_redundant
 
 
 
Attempting backtrace. You can use the following information to find out
 
2017-10-13 18:14:10 0 [Warning] InnoDB: innodb_read_only prevents crash recovery
 
2017-10-13 18:14:10 0 [ERROR] InnoDB: Plugin initialization aborted with error Read only transaction
 
2017-10-13 18:14:10 0 [ERROR] Plugin 'InnoDB' init function returned error.
 
2017-10-13 18:14:10 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.



 Comments   
Comment by Marko Mäkelä [ 2017-11-30 ]

This is the problematic section of the test:

# read-only restart requires the change buffer to be empty; therefore we
 
# do a slow shutdown.
 
SET GLOBAL innodb_fast_shutdown=0;
 
--let $restart_parameters= $d --innodb-read-only
 
--source include/restart_mysqld.inc
 
 
 
SELECT COUNT(*) FROM t1;

I would guess that the slow shutdown somehow failed, and the --innodb-read-only startup was refused because the redo log or the change buffer are not empty. (MDEV-12700 should lift this limitation, and also remove the need for a slow shutdown in this test.)

From the mysqld.1.err of another failure on 10.3, we see that there was a crash (outside InnoDB) during the slow shutdown. I wish we’d soon report these failed shutdowns, as suggested in MDEV-11499:

2017-11-30  9:38:49 0 [Note] /usr/local/mariadb-10.3.3-linux-i686/bin/mysqld (root[root] @ localhost []): Normal shutdown
 
 
 
2017-11-30  9:38:49 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2017-11-30  9:38:49 0 [Note] InnoDB: FTS optimize thread exiting.
 
171130  9:39:49 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.3.3-MariaDB-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=2
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61882 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x49000
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(my_print_stacktrace+0x2d)[0xb7157b0d]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(handle_fatal_signal+0x54a)[0xb6ba89ba]
 
[0xb664c400]
 
[0xb664c424]
 
/lib/i386-linux-gnu/libpthread.so.0(pthread_cond_wait+0xdb)[0xb65e696b]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(_Z11mysqld_mainiPPc+0x2cfc)[0xb692d7ac]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(main+0x27)[0xb69045d7]
 
/lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0xb63354d3]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(+0x2b1e2d)[0xb6920e2d]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file

So, instead of performing the requested slow shutdown, the server crashed, and InnoDB expectedly refuses to start up in read-only mode:

2017-11-30  9:39:51 0 [Note] /usr/local/mariadb-10.3.3-linux-i686/bin/mysqld (mysqld 10.3.3-MariaDB-log) starting as process 16729 ...
 
2017-11-30  9:39:51 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
2017-11-30  9:39:51 0 [Note] Plugin 'partition' is disabled.
 
2017-11-30  9:39:51 0 [Note] InnoDB: Started in read only mode
 
2017-11-30  9:39:51 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-11-30  9:39:51 0 [Note] InnoDB: Uses event mutexes
 
2017-11-30  9:39:51 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2017-11-30  9:39:51 0 [Note] InnoDB: Using Linux native AIO
 
2017-11-30  9:39:51 0 [Note] InnoDB: Number of pools: 1
 
2017-11-30  9:39:51 0 [Note] InnoDB: Using generic crc32 instructions
 
2017-11-30  9:39:51 0 [Note] InnoDB: Disabling background log and ibuf IO write threads.
 
2017-11-30  9:39:51 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
 
2017-11-30  9:39:51 0 [Note] InnoDB: Completed initialization of buffer pool
 
2017-11-30  9:39:51 0 [Warning] InnoDB: innodb_read_only prevents crash recovery

Comment by Elena Stepanova [ 2017-11-30 ]

The problem is repeatable by running innodb.row_format_redundant --mem --repeat=N. N has to be big, though.

Here a resolved stack trace (from a different occasion), there isn't much in there.

10.3 7cb3520c0632ad912b309489ad86a90f9fc9bd0b non-debug bintar

 
Thread 1 (Thread 0xb62f5700 (LWP 24287)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65e0aa2 in pthread_kill () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb7150a0b in my_write_core (sig=6) at /home/buildbot/buildbot/build/mysys/stacktrace.c:481
 
#3  0xb6ba1907 in handle_fatal_signal (sig=6) at /home/buildbot/buildbot/build/sql/signal_handler.cc:303
 
#4  <signal handler called>
 
#5  0xb6645416 in __kernel_vsyscall ()
 
#6  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#7  0xb69267ac in inline_mysql_cond_wait (src_line=6156, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1138
 
#8  mysqld_main (argc=149, argv=0xb9b1c944) at /home/buildbot/buildbot/build/sql/mysqld.cc:6156
 
#9  0xb68fd5d7 in main (argc=27, argv=0xbf85c674) at /home/buildbot/buildbot/build/sql/main.cc:25

Error log

 
2017-11-30 16:59:42 0 [Note] /usr/local/mariadb-10.3.3-linux-i686/bin/mysqld (root[root] @ localhost []): Normal shutdown
 
 
 
2017-11-30 16:59:42 0 [Note] Event Scheduler: Purging the queue. 0 events
 
2017-11-30 16:59:42 0 [Note] InnoDB: FTS optimize thread exiting.
 
171130 17:00:42 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.3.3-MariaDB-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=1
 
max_threads=153
 
thread_count=3
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 61882 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x49000
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(my_print_stacktrace+0x2d)[0xb7150b0d]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(handle_fatal_signal+0x54a)[0xb6ba19ba]
 
[0xb6645400]
 
[0xb6645416]
 
/lib/i386-linux-gnu/libpthread.so.0(pthread_cond_wait+0xdb)[0xb65df96b]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(_Z11mysqld_mainiPPc+0x2cfc)[0xb69267ac]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(main+0x27)[0xb68fd5d7]
 
/lib/i386-linux-gnu/libc.so.6(__libc_start_main+0xf3)[0xb632e4d3]
 
/usr/local/mariadb-10.3.3-linux-i686/bin/mysqld(+0x2b1e2d)[0xb6919e2d]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file

All threads

 
Thread 22 (Thread 0xaebdab40 (LWP 24291)):
 
#0  0xb663b55a in ?? () from /lib/i386-linux-gnu/libaio.so.1
 
#1  0xb663b5bf in io_getevents () from /lib/i386-linux-gnu/libaio.so.1
 
#2  0xb6df2c71 in LinuxAIOHandler::collect (this=this@entry=0xaebda1a0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:1893
 
#3  0xb6df32da in LinuxAIOHandler::poll (this=this@entry=0xaebda1a0, m1=m1@entry=0xaebda218, m2=m2@entry=0xaebda21c, request=request@entry=0xaebda220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2038
 
#4  0xb6dfb97d in os_aio_linux_handler (request=0xaebda220, m2=0xaebda21c, m1=0xaebda218, global_segment=1) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2092
 
#5  os_aio_handler (segment=1, m1=0xaebda218, m2=0xaebda21c, request=0xaebda220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:5720
 
#6  0xb6fad29d in fil_aio_wait (segment=1) at /home/buildbot/buildbot/build/storage/innobase/fil/fil0fil.cc:5317
 
#7  0xb6e9dbb0 in io_handler_thread (arg=0xb7900564 <n+4>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0start.cc:340
 
#8  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#9  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 21 (Thread 0xaa7f8b40 (LWP 24299)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65dfd13 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfc5d9 in os_event::timed_wait (this=this@entry=0xb9d19888, abstime=abstime@entry=0xaa7f8258) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:286
 
#3  0xb6dfc851 in os_event::wait_time_low (this=0xb9d19888, time_in_usec=5000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:413
 
#4  0xb6e97cec in srv_monitor_thread () at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:1722
 
#5  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#6  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 20 (Thread 0xa71fcb40 (LWP 24305)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfcd57 in wait (this=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:166
 
#3  wait_low (reset_sig_count=<optimized out>, this=0xb9d197c8) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:336
 
#4  os_event_wait_low (event=0xb9d197c8, reset_sig_count=0) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:535
 
#5  0xb6e9a6c6 in srv_resume_thread (wait=true, slot=0xb78471c4 <srv_sys+196>, sig_count=<optimized out>, timeout_usec=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:918
 
#6  srv_worker_thread (arg=0x0) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:2625
 
#7  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#8  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 19 (Thread 0xa61fab40 (LWP 24307)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfcd57 in wait (this=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:166
 
#3  wait_low (reset_sig_count=<optimized out>, this=0xb9d198e8) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:336
 
#4  os_event_wait_low (event=0xb9d198e8, reset_sig_count=0) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:535
 
#5  0xb6f43780 in buf_dump_thread () at /home/buildbot/buildbot/build/storage/innobase/buf/buf0dump.cc:777
 
#6  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#7  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 18 (Thread 0xab7fab40 (LWP 24297)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65dfd13 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfc5d9 in os_event::timed_wait (this=this@entry=0xb9e5aa98, abstime=abstime@entry=0xab7fa208) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:286
 
#3  0xb6dfc851 in os_event::wait_time_low (this=0xb9e5aa98, time_in_usec=1000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:413
 
#4  0xb6dcd3f6 in lock_wait_timeout_thread () at /home/buildbot/buildbot/build/storage/innobase/lock/lock0wait.cc:529
 
#5  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#6  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 17 (Thread 0xaaff9b40 (LWP 24298)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65dfd13 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfc5d9 in os_event::timed_wait (this=this@entry=0xb9d19828, abstime=abstime@entry=0xaaff91b8) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:286
 
#3  0xb6dfc851 in os_event::wait_time_low (this=0xb9d19828, time_in_usec=1000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:413
 
#4  0xb6e9839a in srv_error_monitor_thread () at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:1947
 
#5  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#6  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 16 (Thread 0xabb8ab40 (LWP 24315)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6921787 in inline_mysql_cond_wait (src_line=1824, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1138
 
#3  close_connections () at /home/buildbot/buildbot/build/sql/mysqld.cc:1824
 
#4  kill_server (sig_ptr=0x0) at /home/buildbot/buildbot/build/sql/mysqld.cc:2007
 
#5  0xb69217fc in kill_server_thread (arg=arg@entry=0xaf5dc1f0) at /home/buildbot/buildbot/build/sql/mysqld.cc:2039
 
#6  0xb6d4e8fb in pfs_spawn_thread (arg=0xb1800958) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1863
 
#7  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#8  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 15 (Thread 0xac3d5b40 (LWP 24296)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65dfd13 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfc5d9 in os_event::timed_wait (this=this@entry=0xb9d19948, abstime=abstime@entry=0xac3d50b8) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:286
 
#3  0xb6dfc851 in os_event::wait_time_low (this=0xb9d19948, time_in_usec=1000000, reset_sig_count=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:413
 
#4  0xb6f4d92d in pc_sleep_if_needed (sig_count=4, next_loop_time=225554583) at /home/buildbot/buildbot/build/storage/innobase/buf/buf0flu.cc:2710
 
#5  buf_flush_page_cleaner_coordinator () at /home/buildbot/buildbot/build/storage/innobase/buf/buf0flu.cc:3207
 
#6  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#7  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 14 (Thread 0xa59f9b40 (LWP 24308)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65e31f6 in nanosleep () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfd098 in os_thread_sleep (tm=1000000) at /home/buildbot/buildbot/build/storage/innobase/os/os0thread.cc:230
 
#3  0xb6f2a7ec in btr_defragment_thread () at /home/buildbot/buildbot/build/storage/innobase/btr/btr0defragment.cc:772
 
#4  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#5  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 13 (Thread 0xa8bffb40 (LWP 24302)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65e31f6 in nanosleep () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfd098 in os_thread_sleep (tm=1000000) at /home/buildbot/buildbot/build/storage/innobase/os/os0thread.cc:230
 
#3  0xb6e99a28 in srv_master_sleep () at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:2436
 
#4  srv_master_thread (arg=0x0) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:2481
 
#5  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#6  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 12 (Thread 0xacbd6b40 (LWP 24295)):
 
#0  0xb663b55a in ?? () from /lib/i386-linux-gnu/libaio.so.1
 
#1  0xb663b5bf in io_getevents () from /lib/i386-linux-gnu/libaio.so.1
 
#2  0xb6df2c71 in LinuxAIOHandler::collect (this=this@entry=0xacbd61a0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:1893
 
#3  0xb6df32da in LinuxAIOHandler::poll (this=this@entry=0xacbd61a0, m1=m1@entry=0xacbd6218, m2=m2@entry=0xacbd621c, request=request@entry=0xacbd6220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2038
 
#4  0xb6dfb97d in os_aio_linux_handler (request=0xacbd6220, m2=0xacbd621c, m1=0xacbd6218, global_segment=5) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2092
 
#5  os_aio_handler (segment=5, m1=0xacbd6218, m2=0xacbd621c, request=0xacbd6220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:5720
 
#6  0xb6fad29d in fil_aio_wait (segment=5) at /home/buildbot/buildbot/build/storage/innobase/fil/fil0fil.cc:5317
 
#7  0xb6e9dbb0 in io_handler_thread (arg=0xb7900574 <n+20>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0start.cc:340
 
#8  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#9  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 11 (Thread 0xaf5dcb40 (LWP 24311)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65e3be1 in do_sigwait () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb65e3c75 in sigwait () from /lib/i386-linux-gnu/libpthread.so.0
 
#3  0xb691ce94 in signal_hand (arg=arg@entry=0x0) at /home/buildbot/buildbot/build/sql/mysqld.cc:3519
 
#4  0xb6d4e8fb in pfs_spawn_thread (arg=0xb9c79e18) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1863
 
#5  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#6  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 10 (Thread 0xad3d7b40 (LWP 24294)):
 
#0  0xb663b55a in ?? () from /lib/i386-linux-gnu/libaio.so.1
 
#1  0xb663b5bf in io_getevents () from /lib/i386-linux-gnu/libaio.so.1
 
#2  0xb6df2c71 in LinuxAIOHandler::collect (this=this@entry=0xad3d71a0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:1893
 
#3  0xb6df32da in LinuxAIOHandler::poll (this=this@entry=0xad3d71a0, m1=m1@entry=0xad3d7218, m2=m2@entry=0xad3d721c, request=request@entry=0xad3d7220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2038
 
#4  0xb6dfb97d in os_aio_linux_handler (request=0xad3d7220, m2=0xad3d721c, m1=0xad3d7218, global_segment=4) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2092
 
#5  os_aio_handler (segment=4, m1=0xad3d7218, m2=0xad3d721c, request=0xad3d7220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:5720
 
#6  0xb6fad29d in fil_aio_wait (segment=4) at /home/buildbot/buildbot/build/storage/innobase/fil/fil0fil.cc:5317
 
#7  0xb6e9dbb0 in io_handler_thread (arg=0xb7900570 <n+16>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0start.cc:340
 
#8  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#9  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 9 (Thread 0xadbd8b40 (LWP 24293)):
 
#0  0xb663b55a in ?? () from /lib/i386-linux-gnu/libaio.so.1
 
#1  0xb663b5bf in io_getevents () from /lib/i386-linux-gnu/libaio.so.1
 
#2  0xb6df2c71 in LinuxAIOHandler::collect (this=this@entry=0xadbd81a0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:1893
 
#3  0xb6df32da in LinuxAIOHandler::poll (this=this@entry=0xadbd81a0, m1=m1@entry=0xadbd8218, m2=m2@entry=0xadbd821c, request=request@entry=0xadbd8220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2038
 
#4  0xb6dfb97d in os_aio_linux_handler (request=0xadbd8220, m2=0xadbd821c, m1=0xadbd8218, global_segment=3) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2092
 
#5  os_aio_handler (segment=3, m1=0xadbd8218, m2=0xadbd821c, request=0xadbd8220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:5720
 
#6  0xb6fad29d in fil_aio_wait (segment=3) at /home/buildbot/buildbot/build/storage/innobase/fil/fil0fil.cc:5317
 
#7  0xb6e9dbb0 in io_handler_thread (arg=0xb790056c <n+12>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0start.cc:340
 
#8  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#9  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 8 (Thread 0xae3d9b40 (LWP 24292)):
 
#0  0xb663b55a in ?? () from /lib/i386-linux-gnu/libaio.so.1
 
#1  0xb663b5bf in io_getevents () from /lib/i386-linux-gnu/libaio.so.1
 
#2  0xb6df2c71 in LinuxAIOHandler::collect (this=this@entry=0xae3d91a0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:1893
 
#3  0xb6df32da in LinuxAIOHandler::poll (this=this@entry=0xae3d91a0, m1=m1@entry=0xae3d9218, m2=m2@entry=0xae3d921c, request=request@entry=0xae3d9220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2038
 
#4  0xb6dfb97d in os_aio_linux_handler (request=0xae3d9220, m2=0xae3d921c, m1=0xae3d9218, global_segment=2) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2092
 
#5  os_aio_handler (segment=2, m1=0xae3d9218, m2=0xae3d921c, request=0xae3d9220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:5720
 
#6  0xb6fad29d in fil_aio_wait (segment=2) at /home/buildbot/buildbot/build/storage/innobase/fil/fil0fil.cc:5317
 
#7  0xb6e9dbb0 in io_handler_thread (arg=0xb7900568 <n+8>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0start.cc:340
 
#8  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#9  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 7 (Thread 0xaf3dbb40 (LWP 24290)):
 
#0  0xb663b55a in ?? () from /lib/i386-linux-gnu/libaio.so.1
 
#1  0xb663b5bf in io_getevents () from /lib/i386-linux-gnu/libaio.so.1
 
#2  0xb6df2c71 in LinuxAIOHandler::collect (this=this@entry=0xaf3db1a0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:1893
 
#3  0xb6df32da in LinuxAIOHandler::poll (this=this@entry=0xaf3db1a0, m1=m1@entry=0xaf3db218, m2=m2@entry=0xaf3db21c, request=request@entry=0xaf3db220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2038
 
#4  0xb6dfb97d in os_aio_linux_handler (request=0xaf3db220, m2=0xaf3db21c, m1=0xaf3db218, global_segment=0) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:2092
 
#5  os_aio_handler (segment=0, m1=0xaf3db218, m2=0xaf3db21c, request=0xaf3db220) at /home/buildbot/buildbot/build/storage/innobase/os/os0file.cc:5720
 
#6  0xb6fad29d in fil_aio_wait (segment=0) at /home/buildbot/buildbot/build/storage/innobase/fil/fil0fil.cc:5317
 
#7  0xb6e9dbb0 in io_handler_thread (arg=0xb7900560 <n>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0start.cc:340
 
#8  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#9  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 6 (Thread 0xb2177b40 (LWP 24288)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65dfd13 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb7155520 in inline_mysql_cond_timedwait (abstime=0xb2177294, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>, src_line=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1175
 
#3  timer_handler (arg=arg@entry=0x0) at /home/buildbot/buildbot/build/mysys/thr_timer.c:292
 
#4  0xb6d4e8fb in pfs_spawn_thread (arg=0xb9c1d048) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1863
 
#5  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#6  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 5 (Thread 0xa69fbb40 (LWP 24306)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfcd57 in wait (this=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:166
 
#3  wait_low (reset_sig_count=<optimized out>, this=0xb9d19708) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:336
 
#4  os_event_wait_low (event=0xb9d19708, reset_sig_count=0) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:535
 
#5  0xb6e9a6c6 in srv_resume_thread (wait=true, slot=0xb784718c <srv_sys+140>, sig_count=<optimized out>, timeout_usec=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:918
 
#6  srv_worker_thread (arg=0x0) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:2625
 
#7  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#8  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 4 (Thread 0xa51f8b40 (LWP 24309)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfcd57 in wait (this=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:166
 
#3  wait_low (reset_sig_count=<optimized out>, this=0xb9d199a8) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:336
 
#4  os_event_wait_low (event=0xb9d199a8, reset_sig_count=0) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:535
 
#5  0xb6f3a85c in buf_resize_thread () at /home/buildbot/buildbot/build/storage/innobase/buf/buf0buf.cc:3076
 
#6  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#7  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 3 (Thread 0xa7bfdb40 (LWP 24304)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb6dfcd57 in wait (this=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:166
 
#3  wait_low (reset_sig_count=<optimized out>, this=0xb9d19768) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:336
 
#4  os_event_wait_low (event=0xb9d19768, reset_sig_count=0) at /home/buildbot/buildbot/build/storage/innobase/os/os0event.cc:535
 
#5  0xb6e9a6c6 in srv_resume_thread (wait=true, slot=0xb78471a8 <srv_sys+168>, sig_count=<optimized out>, timeout_usec=<optimized out>) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:918
 
#6  srv_worker_thread (arg=0x0) at /home/buildbot/buildbot/build/storage/innobase/srv/srv0srv.cc:2625
 
#7  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#8  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 2 (Thread 0xb0d1bb40 (LWP 24289)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65dfd13 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb70676c4 in inline_mysql_cond_timedwait (abstime=0xb0d1b204, mutex=0xb810e1c0 <LOCK_checkpoint>, that=0xb810e1e0 <COND_checkpoint>, src_file=<optimized out>, src_line=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1175
 
#3  my_service_thread_sleep (control=control@entry=0xb7848204 <checkpoint_control>, sleep_time=30000000000) at /home/buildbot/buildbot/build/storage/maria/ma_servicethread.c:115
 
#4  0xb705e586 in ma_checkpoint_background (arg=arg@entry=0x1e) at /home/buildbot/buildbot/build/storage/maria/ma_checkpoint.c:709
 
#5  0xb6d4e8fb in pfs_spawn_thread (arg=0xb9c7df88) at /home/buildbot/buildbot/build/storage/perfschema/pfs.cc:1863
 
#6  0xb65dbd4c in start_thread () from /lib/i386-linux-gnu/libpthread.so.0
 
#7  0xb6403d3e in clone () from /lib/i386-linux-gnu/libc.so.6
 
 
 
Thread 1 (Thread 0xb62f5700 (LWP 24287)):
 
#0  0xb6645416 in __kernel_vsyscall ()
 
#1  0xb65e0aa2 in pthread_kill () from /lib/i386-linux-gnu/libpthread.so.0
 
#2  0xb7150a0b in my_write_core (sig=6) at /home/buildbot/buildbot/build/mysys/stacktrace.c:481
 
#3  0xb6ba1907 in handle_fatal_signal (sig=6) at /home/buildbot/buildbot/build/sql/signal_handler.cc:303
 
#4  <signal handler called>
 
#5  0xb6645416 in __kernel_vsyscall ()
 
#6  0xb65df96b in pthread_cond_wait@@GLIBC_2.3.2 () from /lib/i386-linux-gnu/libpthread.so.0
 
#7  0xb69267ac in inline_mysql_cond_wait (src_line=6156, that=<optimized out>, mutex=<optimized out>, src_file=<optimized out>) at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1138
 
#8  mysqld_main (argc=149, argv=0xb9b1c944) at /home/buildbot/buildbot/build/sql/mysqld.cc:6156
 
#9  0xb68fd5d7 in main (argc=27, argv=0xbf85c674) at /home/buildbot/buildbot/build/sql/main.cc:25

Comment by Marko Mäkelä [ 2017-11-30 ]

First of all, it looks like the SIGABRT must have been sent externally by the shutdown_server statement, whose default timeout is 60 seconds.
This "poor man’s MDEV-11499" was implemented in 10.3.

Now, why did the shutdown take so long? We can see that some srv_worker_thread are idle, even though srv_purge_coordinator_thread has terminated.
Could this share a root cause with MDEV-11802 and MDEV-13603?

Curiously, I do not see the InnoDB main shutdown thread either. I see that the thd_destructor_proxy has terminated, but I see that some InnoDB I/O threads, buf_flush_page_cleaner_coordinator, and the srv_master_thread exist, along with some InnoDB background threads.

Based on the following variables (thanks, elenst) it looks like innodb_shutdown() was not invoked at all, even though thd_destructor_proxy() did terminate:

gdb

 
(gdb) p srv_running
 
$1 = (volatile st_my_thread_var *) 0x0
 
(gdb) p srv_undo_sources
 
$2 = false
 
(gdb) p srv_shutdown_state
 
$3 = SRV_SHUTDOWN_NONE

A possible reason is that srv_purge_wakeup() failed to wake up all purge worker threads after srv_undo_sources were closed. Maybe there should be some polling around srv_purge_wakeup() in thd_destructor_proxy().

Comment by Marko Mäkelä [ 2017-11-30 ]

It seems to me that the logic in thd_destructor_proxy is somehow incorrect when srv_fast_shutdown=0 (innodb_fast_shutdown=0).
The logic was last updated by serg in August 11, 2017, both as part of MDEV-13472 (commit 2) and by something related (commit 1).

Comment by Marko Mäkelä [ 2017-11-30 ]

The problem appears to be that srv_purge_wakeup() is not reliably waking up and terminating all purge threads.
I believe that the hang could be caused as follows:

  1. thd_destructor_proxy() invokes srv_purge_wakeup(), which fails to wake up some purge threads.
  2. These purge threads hold THD objects due to some undo log records that were left by previous tests (on MDEV-5800 indexed virtual columns).
  3. Due to the continued existence of the THD objects, the server never calls innobase_end().

For non-slow InnoDB shutdown, there is a second attempt of shutting down the purge threads, in the first loop in logs_empty_and_mark_files_at_shutdown(). This second attempt would be unnecessary if the first attempt always worked. For fixing the first attempt, I would propose the following patch, or maybe we should do it as part of srv_shutdown_bg_undo_sources():

diff --git a/storage/innobase/srv/srv0srv.cc b/storage/innobase/srv/srv0srv.cc
 
index e3a4eb05010..5d43563dffb 100644
 
--- a/storage/innobase/srv/srv0srv.cc
 
+++ b/storage/innobase/srv/srv0srv.cc
 
@@ -2958,8 +2958,11 @@ srv_purge_wakeup()
 
 {
 
 	ut_ad(!srv_read_only_mode);
 
 
-	if (srv_force_recovery < SRV_FORCE_NO_BACKGROUND) {
 
+	if (srv_force_recovery >= SRV_FORCE_NO_BACKGROUND) {
 
+		return;
 
+	}
 
 
+	do {
 
 		srv_release_threads(SRV_PURGE, 1);
 
 
 		if (srv_n_purge_threads > 1) {
 
@@ -2967,7 +2970,9 @@ srv_purge_wakeup()
 
 
 			srv_release_threads(SRV_WORKER, n_workers);
 
 		}
 
-	}
 
+	} while (!srv_running
 
+		 && (srv_sys.n_threads_active[SRV_WORKER]
 
+		     || srv_sys.n_threads_active[SRV_PURGE]));
 
 }
 
 
 /** Check if tablespace is being truncated.

Comment by Elena Stepanova [ 2017-12-01 ]

marko wrote:

You could try adding a sleep before `srv_suspend_thread(slot)` in `srv_worker_thread()` to improve the chances.

With the suggested sleep, the hang reproduces reliably on 10.3 (happens on every restart in innodb.row_format_redundant), and the patch above seems to fix it.

Without the sleep, however, it reproduces on the baseline 10.3 less reliably than it initially seemed. I got it once with repeat=100, twice with repeat=1000 within the first 500 repetitions, and twice all 1000 runs went successfully.

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