[MDEV-11689] Server shuts down in unclean fashion after failing to start with a wrong value of innodb_undo_tablespaces Created: 2016-12-30  Updated: 2017-01-31  Resolved: 2017-01-29

Status: Closed
Project: MariaDB Server
Component/s: Plugins, Storage Engine - InnoDB
Affects Version/s: 10.2.3
Fix Version/s: 10.2.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Problem/Incident
is caused by MDEV-11710 thd_destructor_proxy() hangs on shutd... Closed

 Description   

Note: I'm not sure it's actually an InnoDB problem, please change the category and re-assign if needed.

To reproduce,

  • create a datadir with the default innodb_undo_tablespaces=0,
  • start the server with another value, e.g. --innodb_undo_tablespaces=2.

The error is expected in this case, but what happens after it appears to be wrong.

On 10.2:

2016-12-30 13:08:15 139840456656768 [Note] InnoDB: Created tablespace for space 4294967280 name innodb_redo_log key_id 0 encryption 0
 
2016-12-30 13:08:15 139840456656768 [ERROR] InnoDB: Expected to open 2 undo tablespaces but was able to find only 0 undo tablespaces. Set the innodb_undo_tablespaces parameter to the correct value and retry. Suggested value is 0
 
2016-12-30 13:08:15 139840456656768 [ERROR] InnoDB: Plugin initialization aborted at srv0start.cc[2112] with error Generic error
 
2016-12-30 13:08:15 139840456656768 [ERROR] Plugin 'InnoDB' init function returned error.
 
2016-12-30 13:08:15 139840456656768 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2016-12-30 13:08:15 139840456656768 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-12-30 13:08:15 139840456656768 [ERROR] Unknown/unsupported storage engine: InnoDB
 
2016-12-30 13:08:15 139840456656768 [ERROR] Aborting
 
 
 
2016-12-30 13:08:15 139840456656768 [ERROR] Plugin 'MyISAM' has ref_count=1 after shutdown.
 
Error in my_thread_global_end(): 1 threads didn't exit
 
mysqld: /data/src/10.2/sql/mysqld.cc:2154: void mysqld_exit(int): Assertion `global_status_var.global_memory_used == 0' failed.
 
161230 13:08:21 [ERROR] mysqld got signal 6 ;
 
...

On 10.1, there is no assertion failure or ref_count problem, but it seems that the process just disappears without proper shut down:

2016-12-30 13:11:38 140051651819392 [Note] InnoDB: Created tablespace for space 0 name ./ibdata1 key_id 1 encryption 0.
 
2016-12-30 13:11:38 140051651819392 [Note] InnoDB: Created tablespace for space 4294967280 name ./ib_logfile0 key_id 0 encryption 0.
 
2016-12-30 13:11:38 140051651819392 [Note] InnoDB: Created tablespace for space 4294967281 name arch_log_space key_id 0 encryption 0.
 
2016-12-30 13:11:38 7f6050f4f780 InnoDB: Expected to open 2 undo tablespaces but was able
 
2016-12-30 13:11:38 7f6050f4f780 InnoDB: to find only 0 undo tablespaces.
 
2016-12-30 13:11:38 7f6050f4f780 InnoDB: Set the innodb_undo_tablespaces parameter to the
 
2016-12-30 13:11:38 7f6050f4f780 InnoDB: correct value and retry. Suggested value is 0
 
2016-12-30 13:11:38 140051651819392 [ERROR] Plugin 'InnoDB' init function returned error.
 
2016-12-30 13:11:38 140051651819392 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
2016-12-30 13:11:38 140051651819392 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-12-30 13:11:38 140051651819392 [ERROR] Unknown/unsupported storage engine: InnoDB
 
2016-12-30 13:11:38 140051651819392 [ERROR] Aborting

MySQL 5.6, 5.7, MariaDB 5.5, 10.0 perform the shutdown, e.g. on 10.0:

2016-12-30 13:11:02 7f9fc17a6780 InnoDB: Expected to open 2 undo tablespaces but was able
 
2016-12-30 13:11:02 7f9fc17a6780 InnoDB: to find only 0 undo tablespaces.
 
2016-12-30 13:11:02 7f9fc17a6780 InnoDB: Set the innodb_undo_tablespaces parameter to the
 
2016-12-30 13:11:02 7f9fc17a6780 InnoDB: correct value and retry. Suggested value is 0
 
161230 13:11:02 [ERROR] Plugin 'InnoDB' init function returned error.
 
161230 13:11:02 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
161230 13:11:02 [ERROR] Unknown/unsupported storage engine: InnoDB
 
161230 13:11:02 [ERROR] Aborting
 
 
 
161230 13:11:02 [Note] /data/bld/10.0/bin/mysqld: Shutdown complete



 Comments   
Comment by Marko Mäkelä [ 2017-01-03 ]

I suspect that this does not affect 10.1 at all, but only 10.2. I will compile&test 10.1.

Comment by Marko Mäkelä [ 2017-01-03 ]

I was unable to repeat this in 10.1 with the following test:

--source include/have_innodb.inc
 
let $restart_parameters= --innodb-undo-tablespaces=2;
 
--source include/restart_mysqld.inc

This resulted in an aborted InnoDB startup as follows:

2017-01-03 13:38:04 7fca82302740 InnoDB: Expected to open 2 undo tablespaces but was able
 
2017-01-03 13:38:04 7fca82302740 InnoDB: to find only 0 undo tablespaces.
 
2017-01-03 13:38:04 7fca82302740 InnoDB: Set the innodb_undo_tablespaces parameter to the
 
2017-01-03 13:38:04 7fca82302740 InnoDB: correct value and retry. Suggested value is 0
 
2017-01-03 13:38:04 140507744315200 [ERROR] Plugin 'InnoDB' init function returned error.
 
2017-01-03 13:38:04 140507744315200 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
 
…
 
2017-01-03 13:38:04 140507744315200 [Note] Server socket created on IP: '127.0.0.1'.
 
2017-01-03 13:38:04 140507744315200 [Note] /dev/shm/t/sql/mysqld: ready for connections.
 
Version: '10.1.21-MariaDB-debug'  socket: '/dev/shm/t/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution

I reran the test under --manual-gdb (appending --innodb-undo-tablespaces=2 to the arguments when restarting mysqld), and I did not observe any problem in th 10.1.21 shutdown:

2017-01-03 13:40:56 140737225456384 [Note] /dev/shm/t/sql/mysqld: Normal shutdown
 
 
 
2017-01-03 13:40:56 140737225456384 [Note] Event Scheduler: Purging the queue. 0 events
 
[Thread 0x7ffff0591b00 (LWP 18670) exited]
 
[Thread 0x7fffebfff700 (LWP 18662) exited]
 
[Thread 0x7ffff2248700 (LWP 18661) exited]
 
2017-01-03 13:40:56 140737225456384 [Note] Debug sync points hit:                   167
 
2017-01-03 13:40:56 140737225456384 [Note] Debug sync points executed:              0
 
2017-01-03 13:40:56 140737225456384 [Note] Debug sync points max active per thread: 0
 
2017-01-03 13:40:56 140737225456384 [Note] /dev/shm/t/sql/mysqld: Shutdown complete

Comment by Elena Stepanova [ 2017-01-03 ]

To reproduce the missing "mysqld: Shutdown complete" on 10.1, one needs to have InnoDB as a default storage engine. MTR sets it to MyISAM, so you need to run the test with --mysqld=--default-storage-engine=InnoDB.

Comment by Marko Mäkelä [ 2017-01-27 ]

When this is fixed, the workarounds in the test innodb.log_file_size should be removed. (Add --core-file and remove all ,134 to repeat the problem.)
That test does not repeat the problem in 10.0 or 10.1.

Comment by Marko Mäkelä [ 2017-01-27 ]

In 10.2, also the test innodb.log_file needed workarounds for this bug, so please uncomment the core_file and remove all ,134 when fixing this bug.
Curiously, innodb.log_corruption (which is trying to start up InnoDB with various corrupted redo log files) appears to be unaffected by this problem.

Comment by Sergei Golubchik [ 2017-01-29 ]

Fixed in 30ba3100579

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