[MDEV-7177] Server hangs on shutdown after InnoDB error (main.plugin_loaderr fails in buildbot) - Jira

Elena Stepanova created issue - 2014-11-23 15:29

Elena Stepanova made changes - 2014-11-23 15:29

Field	Original Value	New Value
Link		This issue blocks ~~MDEV-7172~~ [ ~~MDEV-7172~~ ]

Elena Stepanova made changes - 2014-11-26 19:07

Summary

main.plugin_loaderr fails in buildbot

Server hangs on shutdown after InnoDB error (main.plugin_loaderr fails in buildbot)

Elena Stepanova made changes - 2014-11-26 19:07

Component/s

Storage Engine - InnoDB [ 10129 ]

Elena Stepanova made changes - 2014-11-26 19:08

Environment

CentOS 5 32-bit

Elena Stepanova made changes - 2014-11-26 19:13

Description

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/1892/steps/test/logs/stdio

{noformat}
main.plugin_loaderr w2 [ fail ] timeout after 900 seconds
Test ended at 2014-11-23 09:21:08

Test case timeout after 900 seconds

== /dev/shm/var_auto_4rfd/2/log/plugin_loaderr.log ==
call mtr.add_suppression("InnoDB");
SELECT
PLUGIN_NAME,PLUGIN_STATUS,PLUGIN_TYPE,PLUGIN_LIBRARY,PLUGIN_LIBRARY_VERSION,LOAD_OPTION
FROM INFORMATION_SCHEMA.PLUGINS WHERE plugin_name = 'innodb';
PLUGIN_NAME InnoDB
PLUGIN_STATUS DISABLED
PLUGIN_TYPE STORAGE ENGINE
PLUGIN_LIBRARY NULL
PLUGIN_LIBRARY_VERSION NULL
LOAD_OPTION ON
#
# ~~MDEV-6351~~ --plugin=force has no effect for built-in plugins
#

== /dev/shm/var_auto_4rfd/2/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/usr/local/mariadb-10.1.2-linux-i686/mysql-test/var/tmp/2/mysqld.1.sock' (2 "No such file or directory")
{noformat}

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/1892/steps/test/logs/stdio

{noformat}
main.plugin_loaderr w2 [ fail ] timeout after 900 seconds
        Test ended at 2014-11-23 09:21:08

Test case timeout after 900 seconds

...
{noformat}

The problem is reproducible on CentOS 5.9 32-bit, but I am not getting it on Wheezy 32 bit.

What happens there is that the test shuts down the server, then attempts to start it with a wrong set of options, the attempt is expected to fail and abort, and then the server is restarted properly to finish the test.
On CentOS 5 32-bit the "bad" attempt indeed fails, too, but the server hangs upon shutdown.
It can be well enough reproducible by just running the command line
{noformat}
/home/elenst/mariadb-10.1.2-linux-i686/bin/mysqld --basedir=/home/elenst/mariadb-10.1.2-linux-i686 --innodb_read_io_threads=2 --innodb=force --innodb-page-size=6000
{noformat}

The hang does not happen every time, but was happening often enough for me when I was trying it (~9 times out of 10).

Stack trace from the hanging server:
{noformat}
{noformat}
Thread 2 (Thread 0xb73ffb90 (LWP 4091)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e8aa in inline_mysql_cond_timedwait (arg=0x0)
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 timer_handler (arg=0x0)
    at /home/buildbot/buildbot/build/mysys/thr_timer.c:309
#4 0x004cd912 in start_thread () from /lib/libpthread.so.0
#5 0x0031f7ce in clone () from /lib/libc.so.6

Thread 1 (Thread 0xb7f706f0 (LWP 4090)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e5b9 in inline_mysql_cond_timedwait ()
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 end_thr_timer () at /home/buildbot/buildbot/build/mysys/thr_timer.c:123
#4 0x08135146 in clean_up (print_message=true)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2107
#5 0x08135980 in unireg_abort (exit_code=1)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2023
#6 0x0813b61f in init_server_components ()
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5026
#7 0x0813c69a in mysqld_main (argc=6, argv=0xb741a280)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5607
#8 0x081306a2 in main (argc=) at /home/buildbot/buildbot/build/sql/main.cc:25
{noformat}
{noformat}

Elena Stepanova made changes - 2014-11-26 19:13

Description

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/1892/steps/test/logs/stdio

{noformat}
main.plugin_loaderr w2 [ fail ] timeout after 900 seconds
        Test ended at 2014-11-23 09:21:08

Test case timeout after 900 seconds

...
{noformat}

The problem is reproducible on CentOS 5.9 32-bit, but I am not getting it on Wheezy 32 bit.

What happens there is that the test shuts down the server, then attempts to start it with a wrong set of options, the attempt is expected to fail and abort, and then the server is restarted properly to finish the test.
On CentOS 5 32-bit the "bad" attempt indeed fails, too, but the server hangs upon shutdown.
It can be well enough reproducible by just running the command line
{noformat}
/home/elenst/mariadb-10.1.2-linux-i686/bin/mysqld --basedir=/home/elenst/mariadb-10.1.2-linux-i686 --innodb_read_io_threads=2 --innodb=force --innodb-page-size=6000
{noformat}

The hang does not happen every time, but was happening often enough for me when I was trying it (~9 times out of 10).

Stack trace from the hanging server:
{noformat}
{noformat}
Thread 2 (Thread 0xb73ffb90 (LWP 4091)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e8aa in inline_mysql_cond_timedwait (arg=0x0)
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 timer_handler (arg=0x0)
    at /home/buildbot/buildbot/build/mysys/thr_timer.c:309
#4 0x004cd912 in start_thread () from /lib/libpthread.so.0
#5 0x0031f7ce in clone () from /lib/libc.so.6

Thread 1 (Thread 0xb7f706f0 (LWP 4090)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e5b9 in inline_mysql_cond_timedwait ()
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 end_thr_timer () at /home/buildbot/buildbot/build/mysys/thr_timer.c:123
#4 0x08135146 in clean_up (print_message=true)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2107
#5 0x08135980 in unireg_abort (exit_code=1)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2023
#6 0x0813b61f in init_server_components ()
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5026
#7 0x0813c69a in mysqld_main (argc=6, argv=0xb741a280)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5607
#8 0x081306a2 in main (argc=) at /home/buildbot/buildbot/build/sql/main.cc:25
{noformat}
{noformat}

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/1892/steps/test/logs/stdio

{noformat}
main.plugin_loaderr w2 [ fail ] timeout after 900 seconds
        Test ended at 2014-11-23 09:21:08

Test case timeout after 900 seconds

...
{noformat}

The problem is reproducible on CentOS 5.9 32-bit, but I am not getting it on Wheezy 32 bit.

What happens there is that the test shuts down the server, then attempts to start it with a wrong set of options, the attempt is expected to fail and abort, and then the server is restarted properly to finish the test.
On CentOS 5 32-bit the "bad" attempt indeed fails, too, but the server hangs upon shutdown.
It can be well enough reproducible by just running the command line
{noformat}
/home/elenst/mariadb-10.1.2-linux-i686/bin/mysqld --basedir=/home/elenst/mariadb-10.1.2-linux-i686 --innodb_read_io_threads=2 --innodb=force --innodb-page-size=6000
{noformat}

The hang does not happen every time, but was happening often enough for me when I was trying it (~9 times out of 10).

Stack trace from the hanging server:
{noformat}
Thread 2 (Thread 0xb73ffb90 (LWP 4091)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e8aa in inline_mysql_cond_timedwait (arg=0x0)
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 timer_handler (arg=0x0)
    at /home/buildbot/buildbot/build/mysys/thr_timer.c:309
#4 0x004cd912 in start_thread () from /lib/libpthread.so.0
#5 0x0031f7ce in clone () from /lib/libc.so.6

Thread 1 (Thread 0xb7f706f0 (LWP 4090)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e5b9 in inline_mysql_cond_timedwait ()
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 end_thr_timer () at /home/buildbot/buildbot/build/mysys/thr_timer.c:123
#4 0x08135146 in clean_up (print_message=true)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2107
#5 0x08135980 in unireg_abort (exit_code=1)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2023
#6 0x0813b61f in init_server_components ()
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5026
#7 0x0813c69a in mysqld_main (argc=6, argv=0xb741a280)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5607
#8 0x081306a2 in main (argc=) at /home/buildbot/buildbot/build/sql/main.cc:25
{noformat}
{noformat}

Elena Stepanova made changes - 2014-11-26 19:13

Comment

[ {noformat}
Thread 2 (Thread 0xb73ffb90 (LWP 4091)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e8aa in inline_mysql_cond_timedwait (arg=0x0)
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 timer_handler (arg=0x0)
    at /home/buildbot/buildbot/build/mysys/thr_timer.c:309
#4 0x004cd912 in start_thread () from /lib/libpthread.so.0
#5 0x0031f7ce in clone () from /lib/libc.so.6

Thread 1 (Thread 0xb7f706f0 (LWP 4090)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e5b9 in inline_mysql_cond_timedwait ()
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 end_thr_timer () at /home/buildbot/buildbot/build/mysys/thr_timer.c:123
#4 0x08135146 in clean_up (print_message=true)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2107
#5 0x08135980 in unireg_abort (exit_code=1)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2023
#6 0x0813b61f in init_server_components ()
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5026
#7 0x0813c69a in mysqld_main (argc=6, argv=0xb741a280)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5607
#8 0x081306a2 in main (argc=) at /home/buildbot/buildbot/build/sql/main.cc:25
{noformat}
]

Elena Stepanova made changes - 2014-11-26 19:14

Assignee

Elena Stepanova [ elenst ]

Jan Lindström [ jplindst ]

Elena Stepanova made changes - 2014-11-26 19:15

Description

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/1892/steps/test/logs/stdio

{noformat}
main.plugin_loaderr w2 [ fail ] timeout after 900 seconds
        Test ended at 2014-11-23 09:21:08

Test case timeout after 900 seconds

...
{noformat}

The problem is reproducible on CentOS 5.9 32-bit, but I am not getting it on Wheezy 32 bit.

What happens there is that the test shuts down the server, then attempts to start it with a wrong set of options, the attempt is expected to fail and abort, and then the server is restarted properly to finish the test.
On CentOS 5 32-bit the "bad" attempt indeed fails, too, but the server hangs upon shutdown.
It can be well enough reproducible by just running the command line
{noformat}
/home/elenst/mariadb-10.1.2-linux-i686/bin/mysqld --basedir=/home/elenst/mariadb-10.1.2-linux-i686 --innodb_read_io_threads=2 --innodb=force --innodb-page-size=6000
{noformat}

The hang does not happen every time, but was happening often enough for me when I was trying it (~9 times out of 10).

Stack trace from the hanging server:
{noformat}
Thread 2 (Thread 0xb73ffb90 (LWP 4091)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e8aa in inline_mysql_cond_timedwait (arg=0x0)
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 timer_handler (arg=0x0)
    at /home/buildbot/buildbot/build/mysys/thr_timer.c:309
#4 0x004cd912 in start_thread () from /lib/libpthread.so.0
#5 0x0031f7ce in clone () from /lib/libc.so.6

Thread 1 (Thread 0xb7f706f0 (LWP 4090)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e5b9 in inline_mysql_cond_timedwait ()
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 end_thr_timer () at /home/buildbot/buildbot/build/mysys/thr_timer.c:123
#4 0x08135146 in clean_up (print_message=true)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2107
#5 0x08135980 in unireg_abort (exit_code=1)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2023
#6 0x0813b61f in init_server_components ()
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5026
#7 0x0813c69a in mysqld_main (argc=6, argv=0xb741a280)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5607
#8 0x081306a2 in main (argc=) at /home/buildbot/buildbot/build/sql/main.cc:25
{noformat}
{noformat}

http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-x86/builds/1892/steps/test/logs/stdio

{noformat}
main.plugin_loaderr w2 [ fail ] timeout after 900 seconds
        Test ended at 2014-11-23 09:21:08

Test case timeout after 900 seconds

...
{noformat}

The problem is reproducible on CentOS 5.9 32-bit, but I am not getting it on Wheezy 32 bit.

What happens there is that the test shuts down the server, then attempts to start it with a wrong set of options, the attempt is expected to fail and abort, and then the server is restarted properly to finish the test.
On CentOS 5 32-bit the "bad" attempt indeed fails, too, but the server hangs upon shutdown.
It can be well enough reproducible by just running the command line
{noformat}
/home/elenst/mariadb-10.1.2-linux-i686/bin/mysqld --basedir=/home/elenst/mariadb-10.1.2-linux-i686 --innodb_read_io_threads=2 --innodb=force --innodb-page-size=6000
{noformat}

The hang does not happen every time, but was happening often enough for me when I was trying it (~9 times out of 10).

Stack trace from the hanging server:
{noformat}
Thread 2 (Thread 0xb73ffb90 (LWP 4091)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e8aa in inline_mysql_cond_timedwait (arg=0x0)
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 timer_handler (arg=0x0)
    at /home/buildbot/buildbot/build/mysys/thr_timer.c:309
#4 0x004cd912 in start_thread () from /lib/libpthread.so.0
#5 0x0031f7ce in clone () from /lib/libc.so.6

Thread 1 (Thread 0xb7f706f0 (LWP 4090)):
#0 0x00f3d410 in __kernel_vsyscall ()
#1 0x004d1ff2 in pthread_cond_timedwait@@GLIBC_2.3.2 ()
   from /lib/libpthread.so.0
#2 0x0886e5b9 in inline_mysql_cond_timedwait ()
    at /home/buildbot/buildbot/build/include/mysql/psi/mysql_thread.h:1202
#3 end_thr_timer () at /home/buildbot/buildbot/build/mysys/thr_timer.c:123
#4 0x08135146 in clean_up (print_message=true)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2107
#5 0x08135980 in unireg_abort (exit_code=1)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:2023
#6 0x0813b61f in init_server_components ()
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5026
#7 0x0813c69a in mysqld_main (argc=6, argv=0xb741a280)
    at /home/buildbot/buildbot/build/sql/mysqld.cc:5607
#8 0x081306a2 in main (argc=) at /home/buildbot/buildbot/build/sql/main.cc:25
{noformat}

{noformat:title=Stdout}
[elenst@localhost mariadb-10.1.2-linux-i686]$ /home/elenst/mariadb-10.1.2-linux-i686/bin/mysqld --basedir=/home/elenst/mariadb-10.1.2-linux-i686 --innodb_read_io_threads=2 --innodb=force --innodb-page-size=6000
InnoDB: Warning: innodb_page_size has been changed from default value 16384 to 6000d. (###EXPERIMENTAL### operation)
141126 20:13:43 [ERROR] InnoDB: Invalid page size=6000.

141126 20:13:43 [ERROR] Plugin 'InnoDB' init function returned error.
141126 20:13:43 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
141126 20:13:43 [ERROR] Failed to initialize plugins.
141126 20:13:43 [ERROR] Aborting
{noformat}

Jan Lindström (Inactive) added a comment - 2014-11-27 20:21

Both threads are not inside InnoDB/XtraDB, someone with more knowledge on that part of server should have a look of this. Based on stack, InnoDB/XtraDB has already shut down.

Jan Lindström (Inactive) added a comment - 2014-11-27 20:21 Both threads are not inside InnoDB/XtraDB, someone with more knowledge on that part of server should have a look of this. Based on stack, InnoDB/XtraDB has already shut down.

Jan Lindström (Inactive) made changes - 2014-11-27 20:21

Assignee

Jan Lindström [ jplindst ]

Elena Stepanova [ elenst ]

Elena Stepanova made changes - 2014-11-27 22:09

Assignee

Elena Stepanova [ elenst ]

Sergey Vojtovich [ svoj ]

Elena Stepanova added a comment - 2014-11-27 22:09

svoj,
Could you please take a look? If not, please reassign it back to me.

Elena Stepanova added a comment - 2014-11-27 22:09 svoj , Could you please take a look? If not, please reassign it back to me.

Sergei Golubchik made changes - 2015-01-09 21:28

Assignee

Sergey Vojtovich [ svoj ]

Sergei Golubchik [ serg ]

Sergei Golubchik added a comment - 2015-01-10 01:21

Doesn't seem to happen anymore.

Sergei Golubchik added a comment - 2015-01-10 01:21 Doesn't seem to happen anymore.

Sergei Golubchik made changes - 2015-01-10 01:21

Fix Version/s		10.1.3 [ 18000 ]
Fix Version/s	10.1 [ 16100 ]
Resolution		Cannot Reproduce [ 5 ]
Status	Open [ 1 ]	Closed [ 6 ]

Sergey Vojtovich added a comment - 2015-01-14 08:17

Happened again tonight:
http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-amd64/builds/1001/steps/test/logs/stdio

Sergey Vojtovich added a comment - 2015-01-14 08:17 Happened again tonight: http://buildbot.askmonty.org/buildbot/builders/kvm-bintar-centos5-amd64/builds/1001/steps/test/logs/stdio

Sergey Vojtovich made changes - 2015-01-14 08:17

Assignee	Sergei Golubchik [ serg ]	Sergey Vojtovich [ svoj ]
Resolution	Cannot Reproduce [ 5 ]
Status	Closed [ 6 ]	Stalled [ 10000 ]

Sergey Vojtovich added a comment - 2015-02-02 14:06

serg, please review fix for this bug.

Sergey Vojtovich added a comment - 2015-02-02 14:06 serg , please review fix for this bug.

Sergey Vojtovich made changes - 2015-02-02 14:06

Assignee	Sergey Vojtovich [ svoj ]	Sergei Golubchik [ serg ]
Status	Stalled [ 10000 ]	In Review [ 10002 ]

Sergei Golubchik made changes - 2015-02-04 20:59

Assignee	Sergei Golubchik [ serg ]	Sergey Vojtovich [ svoj ]
Status	In Review [ 10002 ]	Stalled [ 10000 ]

Sergey Vojtovich made changes - 2015-02-05 13:43

Remote Link

This issue links to "Github revision (Web Link)" [ 22301 ]

Sergey Vojtovich made changes - 2015-02-05 13:44

Resolution		Fixed [ 1 ]
Status	Stalled [ 10000 ]	Closed [ 6 ]

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:51

Workflow

MariaDB v2 [ 58662 ]

MariaDB v3 [ 65441 ]

Sergei Golubchik made changes - 2021-12-06 21:40

Workflow

MariaDB v3 [ 65441 ]

MariaDB v4 [ 148524 ]

MariaDB Server

Server hangs on shutdown after InnoDB error (main.plugin_loaderr fails in buildbot)

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration