MySQL Bugs: #25484: InnoDB Error Message in Log

Bug #25484	InnoDB Error Message in Log
Submitted:	9 Jan 2007 0:03	Modified:	19 Feb 2007 13:50
Reporter:	Paul Dlug	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.1.14	OS:	Linux (CentOS 4.4 (RedHat))
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
I'm getting this error in the log when I restart the server:

070108 18:55:58  InnoDB: Warning: purge reached the head of the history list,
InnoDB: but its length is still reported as 20948! Make a detailed bug
InnoDB: report, and submit it to http://bugs.mysql.com

Not sure what other information you'd like about this one.

How to repeat:
Restart server process (not sure how to reproduce)

Here are some more complete logs from the server restart, server will hang when importing some tables from another server (via mysqlimport) and require it to be killed hard and restarted:

070109 10:12:16 mysqld started
070109 10:12:17 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...
070109 10:12:18 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 33 1486516344.
InnoDB: Doing recovery: scanned up to log sequence number 33 1486516344
070109 10:12:18 InnoDB: Error: table 'db1/@0023sql2@002d3825@002d6'
InnoDB: in InnoDB data dictionary has tablespace id 1,
InnoDB: but tablespace with that id or name does not exist. Have
InnoDB: you deleted or moved .ibd files?
InnoDB: This may also be a table created with CREATE TEMPORARY TABLE
InnoDB: whose .ibd and .frm files MySQL automatically removed, but the
InnoDB: table still exists in the InnoDB internal data dictionary.
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/innodb-troubleshooting.html
InnoDB: for how to resolve the issue.
InnoDB: Last MySQL binlog file position 0 2887974921, file name ./mysql-bin.000001
070109 10:12:19 InnoDB: Started; log sequence number 33 1486516344
/usr/sbin/mysqld: Table 'slow_log' is marked as crashed and should be repaired
070109 10:12:19 [Note] Recovering after a crash using mysql-bin
070109 10:12:20 InnoDB: Warning: purge reached the head of the history list,
InnoDB: but its length is still reported as 20990! Make a detailed bug
InnoDB: report, and submit it to http://bugs.mysql.com
070109 10:12:53 [Note] Starting crash recovery...
070109 10:12:53 [Note] Crash recovery finished.
070109 10:12:53 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.14-beta-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL)
070109 10:12:53 [Note] SCHEDULER: Loaded 0 events

Thank you for a problem report. Please, send your my.cnf file content and describe your system in more details. Send the results of:

df -k
uname -a
free
getconf GNU_LIBPTHREAD_VERSION

Linux commands also.

I have attached the my.cnf (note that I added innodb_file_per_table after this problem occurred in the hopes that this would get me past the import I needed to do, it did not help).

df -k:
Filesystem           1K-blocks      Used Available Use% Mounted on
/dev/sda3            132725352  75708676  50274600  61% /
/dev/sda1               101086     30849     65018  33% /boot
none                   2019264         0   2019264   0% /dev/shm

uname -a:

Linux mysql3 2.6.9-42.0.3.ELsmp #1 SMP Fri Oct 6 06:28:26 CDT 2006 x86_64 x86_64 x86_64 GNU/Linux

(This host is CentOS 4.4 with all of the latest software updates installed).

free:
             total       used       free     shared    buffers     cached
Mem:       4038528    2182976    1855552          0      21344    1633096
-/+ buffers/cache:     528536    3509992
Swap:      8289532        144    8289388

getconf GNU_LIBPTHREAD_VERSION
NPTL 2.3.4

Paul,

how did mysqld crash the first time?

This may be (benign) data file corruption.

Please post all the .err file you have.

Regards,

Heikki

The original crash was a kill -9 of the process because it just hung up while importing a table locking up the entire server (would not gracefully shut down).

My complete .err file is attached, please keep it confidential.

Paul,

this is suspicious:

"
070108 16:36:09 [Note] /usr/sbin/mysqld: Normal shutdown

A mysqld process already exists at  Mon Jan 8 16:36:45 EST 2007
070108 16:39:03  mysqld started
070108 16:39:04  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...
070108 16:39:05  InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 29 3919166626.
InnoDB: Doing recovery: scanned up to log sequence number 29 3919166626
InnoDB: Transaction 0 184817701 was in the XA prepared state.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 0 row operations to undo
InnoDB: Trx id counter is 0 184818176
"

It says a normal shutdown, but there is no printout about the shutdown being completed.

The next time mysqld starts, InnoDB complains that it was not shut down normally. The corruption may have happened then.

How did you shut down mysqld on January 8th at 4:36 pm?

InnoDB is able to tolerate a crash in a shutdown, but maybe there was something else that happened at the same time?

Regards,

Heikki

Shutdown refused to complete after several attempts so the process had to be killed (kill -9). Nothing else was going on at the same time. This host only runs this database, no other applications.

Paul,

hmm... the shutdown apparently never got to the InnoDB shutdown stage. Normally, it prints:

070105 12:15:12  InnoDB: Starting shutdown...
070105 12:15:25  InnoDB: Shutdown completed; log sequence number 28 3814404691
070105 12:15:25 [Note] /usr/sbin/mysqld: Shutdown complete

But killing mysqld should not result in InnoDB corruption! There at least the following hypotheses:

1) maybe there was some OS/hardware problem that caused mysqld to refuse shutdown, and also corrupted the InnoDB data files,

or

2) there was some MySQL bug that caused mysqld to refuse shutdown AND there was some InnoDB bug that caused data file corruption.

Hard to say which is more probable.

You should run CHECK TABLE ... on various InnoDB tables to check for corruption. Beware, it locks the table and can take hours or days for a big table. If it reports corruption, please post the .err log here.

Though, I guess we will not find out what caused this bug.

Regards,

Heikki

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".