| Bug #76262 | 5.7.6 crash when running mysql_upgrade after binary upgrade | ||
|---|---|---|---|
| Submitted: | 11 Mar 2015 13:21 | Modified: | 17 Mar 2015 22:46 |
| Reporter: | Simon Mudd (OCA) | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S2 (Serious) |
| Version: | 5.7.6 | OS: | Any |
| Assigned to: | Marko Mäkelä | CPU Architecture: | Any |
| Tags: | 5.7.6, crash, mysql_upgrade | ||
[11 Mar 2015 13:21]
Simon Mudd
[11 Mar 2015 13:32]
Simon Mudd
I missed some logging: ... Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (7fa904004860): is an invalid pointer Connection ID (thread ID): 3326 Status: NOT_KILLED 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. 150311 12:38:45 mysqld_safe Number of processes running now: 0 150311 12:38:45 mysqld_safe mysqld restarted 2015-03-11T11:38:46.650963Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2015-03-11T11:38:46.656725Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.6-m16-log) starting as process 43243 ... 2015-03-11T11:38:46.891487Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2015-03-11T11:38:46.891630Z 0 [Note] InnoDB: Uses event mutexes 2015-03-11T11:38:46.891673Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier 2015-03-11T11:38:46.891705Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3 2015-03-11T11:38:46.891735Z 0 [Note] InnoDB: Using Linux native AIO 2015-03-11T11:38:46.895971Z 0 [Note] InnoDB: Number of pools: 1 2015-03-11T11:38:46.896273Z 0 [Note] InnoDB: Using CPU crc32 instructions 2015-03-11T11:38:46.907189Z 0 [Note] InnoDB: Initializing buffer pool, total size = 76G, instances = 38, chunk size = 128M 2015-03-11T11:38:57.717219Z 0 [Note] InnoDB: Completed initialization of buffer pool 2015-03-11T11:38:58.783350Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2015-03-11T11:38:58.802946Z 0 [ERROR] InnoDB: Checksum mismatch in datafile: ./ibdata1, Space ID:0, Flags: 0. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue. 2015-03-11T11:38:58.803091Z 0 [ERROR] InnoDB: Corrupted page [page id: space=0, page number=0] of datafile './ibdata1' could not be found in the doublewrite buffer. 2015-03-11T11:38:59.403702Z 0 [ERROR] Plugin 'InnoDB' init function returned error. 2015-03-11T11:38:59.403804Z 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed. 2015-03-11T11:38:59.403857Z 0 [ERROR] Failed to initialize plugins. 2015-03-11T11:38:59.403896Z 0 [ERROR] Aborting 2015-03-11T11:38:59.403945Z 0 [Note] Binlog end 2015-03-11T11:38:59.404059Z 0 [Note] Shutting down plugin 'MyISAM' 2015-03-11T11:38:59.417995Z 0 [Note] /usr/sbin/mysqld: Shutdown complete 150311 12:38:59 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
[11 Mar 2015 22:31]
Sunny Bains
Simon, thanks for the bug report, we will investigate and hopefully have something sensible to say about this soon.
[12 Mar 2015 7:01]
MySQL Verification Team
The resolved stack trace. --------------------------- my_print_stacktrace at ./mysql-5.7.6-m16/mysys/stacktrace.c:225 handle_fatal_signal at ./mysql-5.7.6-m16/sql/signal_handler.cc:150 ut_print_timestamp(_IO_FILE*) at ./mysql-5.7.6-m16/storage/innobase/ut/ut0ut.cc:218 ~fatal at ./mysql-5.7.6-m16/storage/innobase/ut/ut0ut.cc:906 buf_dblwr_assert_on_corrupt_block at ./mysql-5.7.6-m16/storage/innobase/buf/buf0dblwr.cc:717 (inlined by) buf_dblwr_check_block at ./mysql-5.7.6-m16/storage/innobase/buf/buf0dblwr.cc:808 buf_dblwr_flush_buffered_writes() at ./mysql-5.7.6-m16/storage/innobase/buf/buf0dblwr.cc:940 buf_flush_do_batch at ./mysql-5.7.6-m16/storage/innobase/buf/buf0flu.cc:1943 buf_flush_lists at ./mysql-5.7.6-m16/storage/innobase/buf/buf0flu.cc:2075 log_preflush_pool_modified_pages at ./mysql-5.7.6-m16/storage/innobase/log/log0log.cc:1439 (inlined by) log_make_checkpoint_at at ./mysql-5.7.6-m16/storage/innobase/log/log0log.cc:1877 row_merge_build_indexes at ./mysql-5.7.6-m16/storage/innobase/row/row0merge.cc:4502 ha_innobase::inplace_alter_table at ./mysql-5.7.6-m16/storage/innobase/handler/handler0alter.cc:4628 mysql_inplace_alter_table at ./mysql-5.7.6-m16/sql/sql_table.cc:6955 (inlined by) mysql_alter_table at ./mysql-5.7.6-m16/sql/sql_table.cc:8882 Sql_cmd_alter_table::execute at ./mysql-5.7.6-m16/sql/sql_alter.cc:316 mysql_execute_command at ./mysql-5.7.6-m16/sql/sql_parse.cc:4452 mysql_parse at ./mysql-5.7.6-m16/sql/sql_parse.cc:5161 Parser_state::reset at ./mysql-5.7.6-m16/sql/sql_lex.h:3489 (inlined by) dispatch_command at ./mysql-5.7.6-m16/sql/sql_parse.cc:1326 handle_connection at ./mysql-5.7.6-m16/sql/conn_handler/connection_handler_per_thread.cc:298 pfs_spawn_thread at ./mysql-5.7.6-m16/storage/perfschema/pfs.cc:2150
[12 Mar 2015 9:10]
Marko Mäkelä
This issue caused by InnoDB having been really sloppy before MySQL 5.1, and being more strict in MySQL 5.7.
Old versions of InnoDB did not initialize all fields when creating buffer pages. We would only initialize page[FIL_PAGE_TYPE]=FIL_PAGE_INDEX on B-tree index pages. On other types of pages, the field FIL_PAGE_TYPE could be anything, including FIL_PAGE_INDEX.
In the log, we see that page 0 in the system tablespace happened to have 0 in the FIL_PAGE_TYPE field. MySQL 5.7 is initializing all unknown page types to 13 to avoid trouble in the future (in case some future version of MySQL is going to introduce more page types).
The crash occurs, because page 32768 in the system tablespace, which must be an allocation bitmap page, is carrying the page type FIL_PAGE_INDEX. What probably happened was that when this page was originally created before MySQL 5.1, a buffer pool page frame that once belonged to a freed index page (after DROP TABLE?) got reused when the tablespace was extended beyond 32767 pages (512MiB).
When InnoDB is writing back an index page from the buffer pool to the datafile, it is performing a consistency check. This consistency check detects that the bitmap page does not look like a valid index page.
The reason why earlier versions of MySQL do not have trouble with this data file is that we had an extra flag to control the flush-time check.
8821 Marko Makela 2014-09-11
Bug#17332603 REMOVE BUF_BLOCK_T::CHECK_INDEX_PAGE_AT_FLUSH
Bug#17345513 CHECKING FIL_PAGE_TYPE BREAKS COMPATIBILITY WITH OLD
INNODB DATA FILES
The field block->check_index_page_at_flush was needed in the bad old
days when InnoDB did not initialize FIL_PAGE_TYPE when creating a
page. It would only initialize this field to FIL_PAGE_INDEX when it
was about to flush a B-tree page. For other page types, InnoDB would
leave garbage in the field. That garbage could also be FIL_PAGE_INDEX
by chance. There was no problem with this in the past, because we
would only invoke the B-tree validation functions when
block->check_index_page_at_flush had been set by some B-tree operation
while the page was in the buffer pool.
Since MySQL 5.1, InnoDB initializes the FIL_PAGE_TYPE for every
page. But, there could be some old data files that contain garbage
FIL_PAGE_TYPE values in some pages. This garbage must be reset when
flushing the page.
buf_block_t: Remove check_index_page_at_flush.
buf_dblwr_check_block(): Reset unknown FIL_PAGE_TYPE values to
FIL_PAGE_TYPE_UNKNOWN if the tablespace flags are 0.
For newer tablespaces, the flags never are 0, and we will complain
about a corrupted page.
FIL_PAGE_TYPE_UNKNOWN: New constant (13) for FIL_PAGE_TYPE.
i_s_page_type[]: Map I_S_PAGE_TYPE_UNKNOWN to FIL_PAGE_TYPE_UNKNOWN.
Both will be reported as "UNKNOWN".
I_S_PAGE_TYPE_BITS: A new macro, to make compile-time checks more
localized.
With this fix, it is possible that some non-index page that happens
to be tagged as FIL_PAGE_INDEX or FIL_PAGE_RTREE will start to trigger
failures in page_simple_validate_new() or page_simple_validate_old().
This situation can be handled by manually patching the data file to
replace
the FIL_PAGE_TYPE on that page with FIL_PAGE_UNKNOWN. The error
message will identify the tablespace ID and page number.
rb#6604 approved by Vasil Dimov
Unfortunately, it is not only the InnoDB system tablespace and not only the bitmap pages that are affected by the garbage FIL_PAGE_TYPE. Also *.ibd files can be affected. Support for innodb_file_per_table was introduced already in MySQL 4.1, and the FIL_PAGE_TYPE on BLOB pages will be garbage (may be FIL_PAGE_INDEX by accident). Only the undo tablespaces created by MySQL 5.6 should have reliable FIL_PAGE_TYPE. Likewise, tablespaces using innodb_page_size other than the default 16k will be reliable, because this feature was introduced in MySQL 5.6.
I do not remember that this consistency check has failed recently. Close to 10 years ago, it once seemed to catch faulty RAM. I think that serious users should use ECC RAM, and we can make this consistency check debug-only in MySQL 5.7. That should be enough to catch any bugs during the development of new features.
[12 Mar 2015 11:15]
Simon Mudd
Thanks for the long and descriptive answer. However, I don't understand the last paragraph. I am not a serious user? My servers don't run ECC ram? Certainly that is not the case. What seems clear is that people like myself who do an inline binary upgrade obviously have brought forward "issues from 5.1" into the current 5.7 release. That's not expected as I've always run mysql_upgrade, at least when running major version changes, so any special magic that's required to keep thing clean and correct "should have been done". Shouldn't mysql_upgrade should deal with this if needed? Can this not be resolved in the background on a 5.6 box to clean up these "ill-defined pages"? Can this not be resolved by a special job/program to check the ibdataX or .ibd files with MySQL down to correct this? Looking forward to seeing how this will be resolved.
[13 Mar 2015 3:39]
Sunny Bains
Simon, we will basically revert this change, make it a debug change.
[13 Mar 2015 13:54]
Marko Mäkelä
Simon, I was giving reasons why we could make the flush-time change a debug-only check. I am glad to hear that my assumption about you using ECC RAM was correct. Basically, the flush-time check would only make sense for those users who do not use ECC RAM. And because the check is rather lightweight, it might be blind to many cases of memory corruption. That said, based on reviewer feedback, I tried to see if we can keep the flush-time check. It turns out that all MySQL/InnoDB versions initialized the FIL_PAGE_TYPE on b-tree and undo log pages. I started writing an alternative patch that would reset the page type to valid values on other types of pages. Old BLOB pages and other pages that are never modified would continue to contain garbage in FIL_PAGE_TYPE. Whichever fix we choose, I plan to write a test case that modifies existing data files to contain FIL_PAGE_INDEX in every page except pages tagged FIL_PAGE_UNDO, and then executes heavy R/W workload on the dataset.
[13 Mar 2015 14:05]
Marko Mäkelä
A note on the mysql_upgrade: Unfortunately, InnoDB never had proper file format version tagging from the start. For some class of files, we do cannot know if they contain garbage or not. The mysql_upgrade is supposed to be a fast metadata-only operation. Because we do not have the metadata to say whether the data contains garbage that should be made valid, I think that we should do the cleanup in a lazy fashion. The case of having uninitialized garbage in data pages is a very nasty one. If we choose my bigger fix, it would essentially become the "background task" that you suggest, running in the 5.7 server. But it would only touch the pages that are modified. Garbage could survive in old read-mostly data files. The metadata situation can change with the Global Data Dictionary, which we are working on (not for the MySQL 5.7 series). With that, we could properly tag old datafiles as "may contain garbage" and deal with them. But, I guess that if we implement anything along those lines, it should be made optional, so that users who originally created their data files with a newer server could avoid the clean-up operation.
[17 Mar 2015 12:10]
Marko Mäkelä
Posted by developer: My fix implements the more comprehensive fix while keeping the consistency check in the doublewrite buffer code. The new test innodb.file_format_upgrade_16k is setting misleading FIL_PAGE_TYPE on the first few pages of an *.ibd file and checking the outcome.
[17 Mar 2015 22:46]
Daniel Price
Posted by developer: Fixed as of the upcoming 5.7.8, 5.8.0 releases, and here's the changelog entry: Running "mysql_upgrade" after a binary upgrade to MySQL 5.7.6 caused a server exit on a system with data files that were originally created with MySQL 5.0 or earlier. Thank you for the bug report.
[23 Mar 2015 6:48]
Marko Mäkelä
Posted by developer: There is another problem in the code that shipped with MySQL 5.7.6. All implementations of InnoDB page checksums include the FIL_PAGE_TYPE field in the checksum. When we reset the FIL_PAGE_TYPE field to 13 in buf0dblwr.cc, we would fail to recompute the page checksum, making the page look corrupted for subsequent server startup attempts. This situation could be rectified by using the innochecksum tool. With the bug fix, we never write the updated FIL_PAGE_TYPE to files before recomputing the page checksum.
[26 Mar 2015 11:20]
Daniel Price
Posted by developer: The previously noted changelog entry has been revised as follows: Running "mysql_upgrade" after a binary upgrade to MySQL 5.7.6 caused a server exit on a system with tablespace data files that were created in MySQL 5.0 or earlier. The fix for Bug #17345513 in MySQL 5.7.6 failed to address all instances of garbage "FIL_PAGE_TYPE" values in tablespace data files created in MySQL 5.0 or earlier. With this patch, the manual process described in the MySQL 5.7.6 release notes entry for Bug #17345513 for repairing non-index pages that contain invalid "FIL_PAGE_TYPE" values is no longer necessary. The patch for Bug #17345513 also failed to recompute page checksums after resetting invalid "FIL_PAGE_TYPE" values. Upon restarting the server, a failure would occur due to an apparent page corruption. The page checksum is now recomputed before the new "FIL_PAGE_TYPE" value is written to the data file. Thank you for the bug report.
[26 Mar 2015 12:22]
Daniel Price
Posted by developer: The fix for this bug is in MySQL 5.7.7. The Release Note will now appear in the 5.7.7 Release Notes document.
