MySQL Bugs: #45522: InnoDB continuously restarts after hard power off

Bug #45522	InnoDB continuously restarts after hard power off
Submitted:	16 Jun 2009 10:57	Modified:	6 Jul 2010 21:23
Reporter:	Matthew Hird	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.0.67	OS:	Linux (RHEL4u4)
Assigned to:		CPU Architecture:	Any
Tags:	innodb rhel4 crash restart power

Description:
I'm using MySQL 5.0.67 Community Edition on RHEL4u4. I am doing some database failover testing and so I pulled the plug on a server running MySQL. The problem I'm having is that the MySQL server just continuously restarts itself and never becomes available for connections.

My my.cnf:

# The following options will be passed to all MySQL clients
[client]
#password = your_password
port = 3306
socket = /var/lib/mysql/mysql.sock

# Here follows entries for some specific programs

# The MySQL server
[mysqld]
port = 3306
socket = /var/lib/mysql/mysql.sock
memlock
sql-mode=ANSI
skip-locking
key_buffer = 8M
max_allowed_packet = 1M
max_connections = 50
table_cache = 512
sort_buffer_size = 1M
read_buffer_size = 1M
read_rnd_buffer_size = 4M
myisam_sort_buffer_size = 4M
thread_cache_size = 32
query_cache_size= 1M
query_cache_limit = 2M
log-slow-queries
long_query_time = 1
# Try number of CPU's*2 for thread_concurrency
thread_concurrency = 8
#increase timeout so that dbmsconnect doesn't disconnect. this should make the timeout a year.
wait_timeout=31536000

# Don't listen on a TCP/IP port at all. This can be a security enhancement,
# if all processes that need to connect to mysqld run on the same host.
# All interaction with mysqld must be made via Unix sockets or named pipes.
# Note that using this option without enabling named pipes on Windows
# (via the "enable-named-pipe" option) will render mysqld useless!
#
#skip-networking

# Replication Master Server (default)
# binary logging is required for replication
#log-bin=mysql-bin

# required unique id between 1 and 2^32 - 1
# defaults to 1 if master-host is not set
# but will not function as a master if omitted
server-id = 1

# Point the following paths to different dedicated disks
#tmpdir = /tmp/
#log-update = /path-to-dedicated-directory/hostname

# Uncomment the following if you are using BDB tables
#bdb_cache_size = 64M
#bdb_max_lock = 100000

# Uncomment the following if you are using InnoDB tables
innodb_data_home_dir = /var/lib/mysql/
innodb_data_file_path = ibdata1:10M:autoextend
innodb_log_group_home_dir = /var/lib/mysql/
innodb_log_arch_dir = /var/lib/mysql/
# You can set .._buffer_pool_size up to 50 - 80 %
# of RAM but beware of setting memory usage too high
innodb_buffer_pool_size = 8M
innodb_additional_mem_pool_size = 2M
# Set .._log_file_size to 25 % of buffer pool size
innodb_log_file_size = 2M
innodb_log_buffer_size = 1M
innodb_flush_log_at_trx_commit = 2
innodb_lock_wait_timeout = 50
innodb_thread_concurrency = 6
innodb_flush_method=O_DIRECT
innodb_file_per_table

[mysqldump]
quick
max_allowed_packet = 2M

[mysql]
no-auto-rehash
# Remove the next comment character if you are not familiar with SQL
#safe-updates

[isamchk]
key_buffer = 8M
sort_buffer_size = 1M
read_buffer = 2M
write_buffer = 2M

[myisamchk]
key_buffer = 8M
sort_buffer_size = 1M
read_buffer = 2M
write_buffer = 2M

[mysqlhotcopy]
interactive-timeout

and the log I'm producing is :

090615 15:43:32 mysqld started
InnoDB: Log scan progressed past the checkpoint lsn 0 2715744844
090615 15:43:34 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 0 2715771742
090615 15:43:36 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
090615 15:43:37 InnoDB: Started; log sequence number 0 2715771742

Number of processes running now: 0
090615 15:43:37 mysqld restarted
InnoDB: Log scan progressed past the checkpoint lsn 0 2715744844
090615 15:43:37 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 0 2715771742
090615 15:43:38 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
090615 15:43:38 InnoDB: Started; log sequence number 0 2715771742

Number of processes running now: 0
090615 15:43:38 mysqld restarted
InnoDB: Log scan progressed past the checkpoint lsn 0 2715744844
090615 15:43:39 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 0 2715771742
090615 15:43:39 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
090615 15:43:39 InnoDB: Started; log sequence number 0 2715771742

Number of processes running now: 0
090615 15:43:39 mysqld restarted
InnoDB: Log scan progressed past the checkpoint lsn 0 2715744844
090615 15:43:39 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 0 2715771742
090615 15:43:40 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
090615 15:43:40 InnoDB: Started; log sequence number 0 2715771742

and round and round it goes. after about 35 seconds I see a parallel process kick in and that causes further problems with 2 processes trying to access the same file.

How to repeat:
Has happened only once so far.

Suggested fix:
Delete database files and all innodb log files and recreate.

Thank you for the report.

Have you tried Forcing InnoDB Recovery (http://dev.mysql.com/doc/refman/5.0/en/forcing-recovery.html)?

I didn't try to force recovery, no. sorry!

I had to get the system back up and running quickly and so wiped everything and restored from a backup.

Is the my.cnf file sensible? I wondered if I was running MySQL within tight constraints?

Thank you for the feedback.

If you hard power off your box it is expected what MySQL could not do automatic correct shutdown and you need to use recovery techniques to get system run smoothly again. So I close the report as "Not a Bug".

Regarding to settings you should test in your environment yourself. This is why they are tunable. This bug database for handling bugs in MySQL products and not for answer usage questions. Support on using our products is available both free in our forums at http://forums.mysql.com/ and for a reasonable fee direct from our skilled support engineers at http://www.mysql.com/support/

I disagree that it's not a bug, MySQL should have restarted. To continuously restart and never become available is not acceptable behaviour in an enterprise system.

are you saying that manual intervention is always required to recover from a hard power off?

Thank you for the feedback.

> I disagree that it's not a bug, MySQL should have restarted.

MySQL will restart if you use --skip-innodb option. But you should check and repair if needed tables which use other storage engines anyway.

> are you saying that manual intervention is always required to recover from a hard power
off?

Not always: everything is your luck in this case.

I thought MySQL was supposed to be an Enterprise class database?

Thank you for the feedback.

We discussed this case internally and decided this can be restore bug.

But at the same time error log shows:

090615 15:43:39 InnoDB: Started; log sequence number 0 2715771742

Number of processes running now: 0
090615 15:43:39 mysqld restarted

This can show same error as in bug #41908: if pid file is not created in time mysqld_safe just restarts server and recovery happens forever.

So I currently close this bug as duplicate of bug #41908. If same loop happens another time please keep broken ib* files, upload them to our FTP server, so we can examine them for case when bug in recovery exists.