innodb_data_file_path is not checked for duplicate file names | Percona Server 5.6.22-72.0 failed to start

[chrisjob1021]

Server shut down normally without error. Upon restart, I encountered this error--

2015-03-04 05:49:13 2b054eea2cf0 InnoDB: Error: tablespace size stored in header is 147013632 pages, but
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: the sum of data file sizes is only 147003840 pages

I did not modify 'innodb_data_file_path' in any way. Data files were in tact and no known corruption. Checked XFS file system and found nothing. Was planning on restoring from backup when I decided to mess with 'innodb_data_file_path'--

Original:
innodb_data_file_path = /ssd/data/ibdata1:806578M;/mysql3/inno_db/data/ibdata2:390354M;/mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:50M:autoextend

Made a typo and got the server online with this statement:
innodb_data_file_path = /ssd/data/ibdata1:806578M;/mysql3/inno_db/data/ibdata2:390354M;/mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M;/mysql5/inno_db/data/ibdata4:153M:autoextend

Works consistently, although fallout is unclear. Tables all seem to be in tact without corruption. I'm envisioning problems will crop up eventually.

I cannot modify that line really in any way, though. For example, adding additional files results in the error returning.

[Valerii Kravchuk (valerii-kravchuk)]

Please, send the entire error log from this MySQL server and the output of:

ls -l /mysql5/inno_db/data

[chrisjob1021 (chris-obrien-1021)]

2015-03-04 05:49:06 0 [Warning] options --log-slow-admin-statements, --log-queries-not-using-indexes and --log-slow-slave-statements have no effect if --slow-query-log is not set
2015-03-04 05:49:06 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-03-04 05:49:06 60863 [Warning] Buffered warning: Could not increase number of max_open_files to more than 1009999 (request: 1068587)
2015-03-04 05:49:06 60863 [Warning] Buffered warning: Changed limits: table_cache: 494994 (requested 524288)
2015-03-04 05:49:06 60863 [Note] Plugin 'FEDERATED' is disabled.
2015-03-04 05:49:06 60863 [Note] InnoDB: Using atomics to ref count buffer pool pages
2015-03-04 05:49:06 60863 [Note] InnoDB: The InnoDB memory heap is disabled
2015-03-04 05:49:06 60863 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2015-03-04 05:49:06 60863 [Note] InnoDB: Memory barrier is not used
2015-03-04 05:49:06 60863 [Note] InnoDB: Compressed tables use zlib 1.2.3
2015-03-04 05:49:06 60863 [Note] InnoDB: Using Linux native AIO
2015-03-04 05:49:06 60863 [Note] InnoDB: Using CPU crc32 instructions
2015-03-04 05:49:06 60863 [ERROR] InnoDB: Linux Native AIO not supported. You can either move tmpdir to a file system that supports native AIO or you can set innodb_use_native_aio to FALSE to avoid this message.
2015-03-04 05:49:06 60863 [ERROR] InnoDB: Linux Native AIO check on tmpdir returned error[22]
2015-03-04 05:49:06 60863 [Warning] InnoDB: Linux Native AIO disabled.
2015-03-04 05:49:06 60863 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2015-03-04 05:49:06 60863 [Note] InnoDB: Completed initialization of buffer pool
2015-03-04 05:49:06 60863 [Note] InnoDB: Highest supported file format is Barracuda.
2015-03-04 05:49:06 60863 [Note] InnoDB: The log sequence numbers 85296094955072 and 85296094955072 in ibdata files do not match the log sequence number 85296110999966 in the ib_logfiles!
2015-03-04 05:49:06 60863 [Note] InnoDB: Database was not shutdown normally!
2015-03-04 05:49:06 60863 [Note] InnoDB: Starting crash recovery.
2015-03-04 05:49:06 60863 [Note] InnoDB: Reading tablespace information from the .ibd files...
2015-03-04 05:49:06 60863 [Note] InnoDB: Restoring possible half-written data pages
2015-03-04 05:49:06 60863 [Note] InnoDB: from the doublewrite buffer...
2015-03-04 05:49:13 60863 [Note] InnoDB: 128 rollback segment(s) are active.
2015-03-04 05:49:13 60863 [Note] InnoDB: Waiting for purge to start
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: Error: tablespace size stored in header is 147013632 pages, but
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: the sum of data file sizes is only 147003840 pages
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: Cannot start InnoDB. The tail of the system tablespace is
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: missing. Have you edited innodb_data_file_path in my.cnf in an
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: inappropriate way, removing ibdata files from there?
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: You can set innodb_force_recovery=1 in my.cnf to force
2015-03-04 05:49:13 2b054eea2cf0 InnoDB: a startup if you are t...

[Nilnandan Joshi (nilnandan-joshi)]

Hi,

First error in log,

2015-03-04 05:49:06 60863 [ERROR] InnoDB: Linux Native AIO not supported. You can either move tmpdir to a file system that supports native AIO or you can set innodb_use_native_aio to FALSE to avoid this message.
2015-03-04 05:49:06 60863 [ERROR] InnoDB: Linux Native AIO check on tmpdir returned error[22]

you should not put tmpdir into memfs to avoid this error.

"Made a typo and got the server online with this statement:
innodb_data_file_path = /ssd/data/ibdata1:806578M;/mysql3/inno_db/data/ibdata2:390354M;/mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M;/mysql5/inno_db/data/ibdata4:153M:autoextend"

Here, I can see ibdata4 twice, was it intentionally set? you mean with this, you were able to start server?

Can you please provide my.cnf and what is the current page size you are using for InnoDB? (by default, it is 16K)

[chrisjob1021 (chris-obrien-1021)]

Hi,

"Here, I can see ibdata4 twice, was it intentionally set? you mean with this, you were able to start server?"

It was unintentionally set, but only way I could get it online.

We are using default page size for InnoDB.

my.cnf--

[mysqlclient]
socket=/tmp/mysql.sock

[mysql]
socket=/tmp/mysql.sock
secure-auth=0

[mysqladmin]
socket=/tmp/mysql.sock

[mysqld]
datadir=/mysql4/data/
socket=/tmp/mysql.sock
tmpdir=/dev/shm/tmp/mysql/
slave-load-tmpdir=/ssd/temp/
back_log=4096
port=3306
skip-external-locking
max_allowed_packet = 128M
max_heap_table_size = 67108864
max_user_connections=0
max_connections = 20000
group_concat_max_len = 2500
table_open_cache = 524288
table_definition_cache = 524288
tmp_table_size = 67108864
sort_buffer_size = 262144
read_buffer_size = 1M
read_rnd_buffer_size = 16777216
join_buffer_size = 16777216
query_cache_type = 0
query_cache_size = 0
max_connect_errors = 1000000
wait_timeout = 1
connect_timeout = 2
interactive_timeout = 1
skip-external-locking
log-error
slow_query_log = 0
min_examined_row_limit = 1000
log_queries_not_using_indexes = 1
long_query_time = 2
log_slow_sp_statements = 0
skip-name-resolve
thread_cache_size = 16384
user=root
log-warnings
innodb_data_home_dir =
innodb_data_file_path = /ssd/data/ibdata1:806578M;/mysql3/inno_db/data/ibdata2:390354M;/mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M;/mysql5/inno_db/data/ibdata4:153M:autoextend
innodb_log_group_home_dir = /mysql4/inno_db/logs
innodb_buffer_pool_size=528G
innodb_log_file_size=3G
innodb_flush_log_at_trx_commit=2
innodb_log_buffer_size=8M
innodb_max_dirty_pages_pct=75
innodb_log_files_in_group=2
innodb_old_blocks_pct=37
innodb_max_purge_lag=0
innodb_max_purge_lag_delay=0
innodb_table_locks=0
innodb_thread_concurrency=0
innodb_flush_method=O_DIRECT
innodb_adaptive_hash_index_partitions=1
innodb_io_capacity=2000
innodb_io_capacity_max=4000
innodb_write_io_threads=64
innodb_read_io_threads=64
innodb_log_block_size=512
innodb_buffer_pool_instances=64
binlog-format=ROW
transaction-isolation=READ-COMMITTED
innodb_autoinc_lock_mode=2
innodb_thread_sleep_delay = 10000
innodb_adaptive_max_sleep_delay = 150000
innodb_concurrency_tickets = 5000
slave_exec_mode = IDEMPOTENT
slave-skip-errors=126,1062,1535,1146,1677
slave_transaction_retries=50
log-slave-updates
expire_logs_days=26
log-bin=/mysql1/binlogs/mysql-bin
max_relay_log_size = 1G
max_binlog_size = 1G
relay-log=/mysql1/relaybinlogs/coredb2-relay-bin
binlog_cache_size = 33554432
binlog_stmt_cache_size = 33554432
server-id = 1
auto_increment_increment=2
max_sp_recursion_depth=255
innodb_file_per_table=0
table_open_cache_instances=16
metadata_locks_hash_instances=8
innodb_sync_array_size=16
innodb_purge_threads=32

innodb_buffer_pool_dump_at_shutdown=1
innodb_buffer_pool_load_at_startup=0
innodb_buffer_pool_filename="/mysql1/ib_buffer_pool"

binlog_checksum=CRC32
relay_log_info_repository=TABLE
slave_sql_verify_checksum=1
master_verify_checksum=1
relay_log_recovery=1
master_info_repository=TABLE
key_buffer_size=0
innodb_old_blocks_time=0
innodb_autoextend_increment=64
innodb_checksum_algorithm=crc32

log_warnings=1

innodb_adaptive_flushing_lwm=10
innodb_max_dirty_pages_...

[Nilnandan Joshi (nilnandan-joshi)]

Hi,

Thanks for the details. I can see that all datafiles are stored in different partitions. Are they using same file system?

innodb_data_file_path = /ssd/data/ibdata1:806578M;
/mysql3/inno_db/data/ibdata2:390354M;
/mysql4/inno_db/data/ibdata3:729522M;
/mysql5/inno_db/data/ibdata4:370481M;
/mysql5/inno_db/data/ibdata4:153M:autoextend

Also the size of ibdata4 file is,

-rw-rw---- 1 mysql mysql 388477485056 Mar 5 17:58 ibdata4

388477485056 = 379372544K = 370481M

Can you try to set below path and check if it works?

innodb_data_file_path = /ssd/data/ibdata1:806578M; /mysql3/inno_db/data/ibdata2:390354M; /mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M:autoextend

OR

innodb_data_file_path = /ssd/data/ibdata1:806578M; /mysql3/inno_db/data/ibdata2:390354M; /mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:388477485056:autoextend

If you still see the issue then please provide /var/log/messages related to that disk. Waiting for your feedback.

[chrisjob1021 (chris-obrien-1021)]

Each partition is on distinct RAID array and all use XFS file system.

I have tried this line and it did not result in the server coming online. It spit out the error I described initially.

"innodb_data_file_path = /ssd/data/ibdata1:806578M; /mysql3/inno_db/data/ibdata2:390354M; /mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M:autoextend"

I have not tried the second line yet. Please advise if you think it would make a difference.

We do not see any issues related to the disk in /var/log/messages or associated logs. An xfs_check did not reveal any errors.

[Valerii Kravchuk (valerii-kravchuk)]

There are two problem here:

1. How you ended up with tablespace size stored in header being exactly 153M bigger than total size of all ibdata* files when you had it set as:

innodb_data_file_path = /ssd/data/ibdata1:806578M;/mysql3/inno_db/data/ibdata2:390354M;/mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:50M:autoextend

To find this out I asked for the entire error log, while you sent me last part for the startup attemp, but nothing before that. This is why we later asked for /var/log/messages etc... Probably the file was extending when some crash or unplanned restart happened, and error log should show that.

2. Why you can start it with adding the same file twice into innodb_data_filke_path, once for the real size and second time for 153M and autoextend:

innodb_data_file_path = /ssd/data/ibdata1:806578M;/mysql3/inno_db/data/ibdata2:390354M;/mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M;/mysql5/inno_db/data/ibdata4:153M:autoextend

but can not start with just:

innodb_data_file_path = /ssd/data/ibdata1:806578M; /mysql3/inno_db/data/ibdata2:390354M; /mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370481M:autoextend

It would be nice to get error log content for this attemp as well (or, again, entire error log, with everything you've tried and what happened before).

For the second problem, in the source code (storage/innobase/srv/srv0start.cc, current 5.6) we clearly see:

...
   2769 sum_of_data_file_sizes = 0;
   2770
   2771 for (i = 0; i < srv_n_data_files; i++) {
   2772 sum_of_data_file_sizes += srv_data_file_sizes[i];
   2773 }

...
   2821 if (!srv_read_only_mode
   2822 && srv_auto_extend_last_data_file
   2823 && sum_of_data_file_sizes < tablespace_size_in_header) {
   2824
   2825 ut_print_timestamp(stderr);
   2826 fprintf(stderr,
   2827 " InnoDB: Error: tablespace size stored in header"
   2828 " is %lu pages, but\n",
   2829 (ulong) tablespace_size_in_header);
   2830 ut_print_timestamp(stderr);
   2831 fprintf(stderr,
   2832 " InnoDB: the sum of data file sizes"
   2833 " is only %lu pages\n",
   2834 (ulong) sum_of_data_file_sizes);
   2835
   2836 if (srv_force_recovery == 0) {
   2837
   2838 ut_print_timestamp(stderr);
   2839 fprintf(stderr,
   2840 " InnoDB: Cannot start InnoDB. The tail of"
...

and from that it's clear that only total size from all entries in innodb_data_file_path and having autoextend for the last one matter for further startup. Nobody seems to try to check for duplicate file entries.

So, if there is some other value to try for startup, it's this one:

innodb_data_file_path = /ssd/data/ibdata1:806578M; /mysql3/inno_db/data/ibdata2:390354M; /mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370634M:autoextend

I've added 153M of "missing" size accor...

[chrisjob1021 (chris-obrien-1021)]

I tried the line as you described--

innodb_data_file_path = /ssd/data/ibdata1:806578M; /mysql3/inno_db/data/ibdata2:390354M; /mysql4/inno_db/data/ibdata3:729522M;/mysql5/inno_db/data/ibdata4:370634M:autoextend

And it still resulted in failure to start.

Let me get you full log from the entire event.

[chrisjob1021 (chris-obrien-1021)]

The complete log file from the event is attached. Please let me know what else you need.

[Laurynas Biveinis (laurynas-biveinis)]

Validating innodb_data_file_path against duplicate entries would be a reasonable upstream feature request

[Valerii Kravchuk (valerii-kravchuk)]

Basically, I am able to reproduce something similar (not exactly the same) with a very simple text case. Look:

[root@centos ~]# mysql -uroot test
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.6.23-72.1-log Percona Server (GPL), Release 72.1, Revision 0503478

Copyright (c) 2009-2015 Percona LLC and/or its affiliates
Copyright (c) 2000, 2015, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select @@datadir, @@innodb_data_file_path;
+-----------------+------------------------------------+
| @@datadir | @@innodb_data_file_path |
+-----------------+------------------------------------+
| /var/lib/mysql/ | ibdata1:18M;ibdata2:12M:autoextend |
+-----------------+------------------------------------+
1 row in set (0.00 sec)

mysql> exit
Bye
[root@centos ~]# vi /etc/my.cnf
[root@centos ~]# service mysql restart
Shutting down MySQL (Percona Server)................. SUCCESS!
Starting MySQL (Percona Server)...... SUCCESS!
[root@centos ~]# ls -lh /var/lib/mysql/ibdata*
-rw-rw----. 1 mysql mysql 18M Mar 16 20:17 /var/lib/mysql/ibdata1
-rw-rw----. 1 mysql mysql 12M Mar 16 20:17 /var/lib/mysql/ibdata2

So, it was a very basic setup of Percona Server with 2 data files. One was 18M at the moment when I started this test, then I've added another one, 12M in size and auto extending. So far it's OK.

Now, I planned to add another one, 13M in size (for whatever reason), ibdata3, but made a typo and added ibdata2 for a second time 9buth with different size 13M):

[root@centos ~]# grep innodb_data_file /etc/my.cnf
innodb_data_file_path=ibdata1:18M;ibdata2:12M;ibdata2:13M:autoextend
[root@centos ~]# service mysql restart
Shutting down MySQL (Percona Server).................. SUCCESS!
Starting MySQL (Percona Server)..................... ERROR! The server quit without updating PID file (/var/lib/mysql/centos.pid).
[root@centos ~]# ps aux | grep mysqld
root 4539 0.0 0.0 103244 868 pts/0 S+ 20:19 0:00 grep mysqld

So, we had got an error and in the error log we see:

[root@centos ~]# tail -80 /var/log/mysqld.log

150316 20:18:54 mysqld_safe mysqld from pid file /var/lib/mysql/centos.pid ended
150316 20:18:58 mysqld_safe Transparent huge pages are already set to: never.
150316 20:18:58 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2015-03-16 20:19:00 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2015-03-16 20:19:00 4337 [Warning] No argument was provided to --log-bin, and --log-bin-index was not used; so replication may break when this MySQL server acts as a master and has his hostname changed!! Please use '--log-bin=centos-bin' to avoid this problem.
2015-03-16 20:19:00 4337 [Note] Plugi...

[chrisjob1021 (chris-obrien-1021)]

Good info!

However, I will say that I did not touch 'innodb_data_file_path' until after the server had shut down properly and it wouldn't start back up with the error I described to you. It was only then did I start modifying the variable. I stumbled onto the issue relating to duplication of ibdata names as a typo.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-879