XtraDB changed page tracking is broken when innodb_data_home_dir and datadir are different

[Dimitriy]

When enabling innodb_track_changed_pages option in my.cnf, the changed page tracking creates files of different content in two directories:

data:
-rw-rw---- 1 user group 56 May 27 16:58 auto.cnf
-rw-rw---- 1 user group 4096 May 27 16:58 ib_modified_log_1_0.xdb
-rw-rw---- 1 user group 4096 May 27 17:34 ib_modified_log_2_1625987.xdb
-rw-rw---- 1 user group 4376 May 27 17:49 innodb_status.12624
drwxrwx--- 2 user group 4096 May 27 16:58 mysql
drwxrwx--- 2 user group 4096 May 27 16:58 performance_schema
-r-------- 1 user group 1675 May 7 16:29 private_key.pem
-r--r--r-- 1 user group 451 May 7 16:29 public_key.pem

ibdata:
-rw-rw---- 1 user group 962 May 27 17:32 ib_buffer_pool
-rw-rw---- 1 user group 12582912 May 27 17:34 ibdata1
-rw-rw---- 1 user group 32768 May 27 16:58 ib_modified_log_1_0.xdb
-rw-rw---- 1 user group 4096 May 27 16:58 ib_modified_log_2_1625987.xdb

I suspect that XtraDB changed page tracking is incorrectly implemented and using two variables (datadir and innodb_data_home_dir) for deciding where to write files.

Sample my.cnf values:
datadir=/some_path/data
innodb_data_home_dir=/some_path/ibdata

[Laurynas Biveinis (laurynas-biveinis)]

The bitmap directory is setup using srv_data_home source code variable, which in turn is innodb_data_home_dir if that one is set, or datadir if the former is not set.

[Muhammad Irfan (muhammad-irfan)]

I didn't able to reproduce it on PS 5.6.17-65.0, PS 5.5.37-35.0-35.0 & PS 5.1.73-14.11

mysql> SHOW VARIABLES LIKE '%version%';
+-------------------------+------------------------+
| Variable_name | Value |
+-------------------------+------------------------+
| innodb_version | 5.6.17-65.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.17-65.0-587.wheezy |
| version_comment | (Debian) |
| version_compile_machine | x86_64 |
| version_compile_os | debian-linux-gnu |
+-------------------------+------------------------+

mysql> SHOW VARIABLES LIKE 'innodb_track_changed_pages';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_track_changed_pages | ON |
+----------------------------+-------+

# cat /etc/my.cnf
[mysqld]
datadir = /var/lib/mysql
innodb_data_home_dir= /var/lib/mysql/ibdata
innodb_track_changed_pages = 1

root: /var/lib/mysql
# ll
total 98376
-rw-rw---- 1 mysql mysql 56 Jun 5 05:12 auto.cnf
-rw-r--r-- 1 root root 0 Jun 5 05:12 debian-5.6.flag
-rw-r----- 1 mysql root 30587 Jun 5 05:34 debian.err
-rw-rw---- 1 mysql mysql 5 Jun 5 05:34 debian.pid
drwxr-xr-x 2 mysql mysql 4096 Jun 5 05:34 ibdata
-rw-rw---- 1 mysql mysql 50331648 Jun 5 05:36 ib_logfile0
-rw-rw---- 1 mysql mysql 50331648 Jun 5 05:28 ib_logfile1
drwx------ 2 mysql mysql 4096 Jun 5 05:28 mysql
-rw------- 1 root root 11 Jun 5 05:28 mysql_upgrade_info
drwx------ 2 mysql mysql 4096 Jun 5 05:28 performance_schema
drwx------ 2 mysql mysql 4096 Jun 5 05:30 test

root: /var/lib/mysql
# ls -lah ibdata/
total 13M
drwxr-xr-x 2 mysql mysql 4.0K Jun 5 05:34 .
drwx------ 6 mysql mysql 4.0K Jun 5 05:34 ..
-rw-rw---- 1 mysql mysql 12M Jun 5 05:36 ibdata1
-rw-rw---- 1 mysql mysql 80K Jun 5 05:36 ib_modified_log_1_0.xdb

[Santhi Kishore Balusu (santhikishore)]

Hi Guys

I am able to reproduce this with Percona Server 5.6.16 & 5.6.17.

Was trying to test XtraDB changed page tracking feature which we expect to speed up our Incremental Backups.

Even after enabling innodb_track_changed_pages in my.cnf Xtrabackup was scanning the log for changed pages which is obviously slow.

Started digging into this & it looks like i cannot select records from information_schema.INNODB_CHANGED_PAGES for some reason.

Let me know if need any further information reg this

################################
# 5.6.17-65.0-rel65.0-log
################################

[(root@localhost)]Master_shareddb[(none)]> SHOW VARIABLES LIKE '%version%';
+-------------------------+-----------------------------------------------------------------+
| Variable_name | Value |
+-------------------------+-----------------------------------------------------------------+
| innodb_version | 5.6.17-rel65.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.17-65.0-rel65.0-log |
| version_comment | Percona Server with XtraDB (GPL), Release rel65.0, Revision 587 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+-----------------------------------------------------------------+
7 rows in set (0.01 sec)

[(root@localhost)]Master_shareddb[(none)]> SHOW VARIABLES LIKE 'innodb_track_changed_pages';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_track_changed_pages | ON |
+----------------------------+-------+
1 row in set (0.00 sec)

[(root@localhost)]Master_shareddb[(none)]> SELECT * FROM information_schema.INNODB_CHANGED_PAGES;
ERROR 1012 (HY000): Can't read record in system table
[(root@localhost)]Master_shareddb[(none)]>

(shareddb)root@Percona-MariaDB-Test-Server:~# grep datadir /etc/my.cnf
datadir = /home/XXXXXXX/mysqlshards/shareddb/data

(shareddb)root@Percona-MariaDB-Test-Server:~# grep innodb_data_home_dir /etc/my.cnf
innodb_data_home_dir = /home/XXXXXXX/mysqlshards/shareddb/innodbdata

(shareddb)root@Percona-MariaDB-Test-Server:~# ls -lah /home/XXXXXXX/mysqlshards/shareddb/data
total 112K
drwxr-xr-x 10 mysql mysql 4.0K 2014-06-10 15:07 .
drwxr-xr-x 7 root root 82 2014-06-10 15:02 ..
-rw-rw---- 1 mysql mysql 56 2014-06-04 13:31 auto.cnf
drwx------ 2 mysql mysql 16K 2014-04-08 08:50 XXXXXXX
drwx------ 2 mysql mysql 4.0K 2014-04-08 16:39 XXXXXXX_plugin_blog
drwx------ 2 mysql mysql 4.0K 2014-04-08 16:38 XXXXXXX_plugin_ecommerce
drwx------ 2 mysql mysql 4.0K 2014-04-08 16:39 XXXXXXX_plugin_menu
-rw-rw---- 1 mysql mysql 4 2013-10-09 14:02 BKLIVE-SHAREDMASTER.pid
-rw-rw---- 1 mysql mysql 48K 2014-06-10 15:07 ib_modifi...

[Santhi Kishore Balusu (santhikishore)]

Hi Guys

If innodb_data_home_dir set to a directory other than datadir then the bitmap tables are created in both places as mentioned in the initial bug report.

At this point you get the below error when you try select records from information_schema.INNODB_CHANGED_PAGES

SELECT * FROM information_schema.INNODB_CHANGED_PAGES;
ERROR 1012 (HY000): Can't read record in system table

Trying a incremental backup with Xtrabackup will result in a log scan as xtrabackup cannot read information_schema.INNODB_CHANGED_PAGES.

Issuing a RESET CHANGED_PAGE_BITMAPS; deletes the files from datadir but not from innodb_data_home_dir

Once you set up innodb_data_home_dir, datadir to the same directory or entirely omit setting up innodb_data_home_dir then everything works fine

This bug may not affect everyone but it will for sure affect users who has innodb_data_home_dir , datadir set to different directories.

Please let me know if you need any further info reg this.

Thanks & Regards

Santhi Kishore Balusu

[Jericho Rivera (jericho-rivera)]

This must be OS specific since this is repeatable on Centos 6.5

[root@vagrant-centos65 mysql]# ls -lah
total 97M
drwxr-xr-x 8 mysql mysql 4.0K Jun 18 12:33 .
drwxr-xr-x. 20 root root 4.0K Jun 18 12:10 ..
-rw-rw---- 1 mysql mysql 56 Jun 18 12:12 auto.cnf
drwxr-xr-x 2 mysql mysql 4.0K Jun 18 12:12 ibdata
-rw-rw---- 1 mysql mysql 48M Jun 18 12:30 ib_logfile0
-rw-rw---- 1 mysql mysql 48M Jun 18 12:12 ib_logfile1
-rw-rw---- 1 mysql mysql 4.0K Jun 18 12:12 ib_modified_log_1_0.xdb
-rw-rw---- 1 mysql mysql 4.0K Jun 18 12:30 ib_modified_log_2_1625987.xdb
drwx------ 2 mysql mysql 4.0K Jun 18 12:12 mysql
srwxrwxrwx 1 mysql mysql 0 Jun 18 12:30 mysql.sock
drwx------ 2 mysql mysql 4.0K Jun 18 12:12 performance_schema
drwx------ 2 mysql mysql 4.0K Jun 18 12:33 sbtest
drwx------ 2 mysql mysql 4.0K Jun 18 12:12 test
drwx------ 2 mysql mysql 4.0K Jun 18 12:33 test1
-rw-rw---- 1 mysql mysql 5 Jun 18 12:30 vagrant-centos65.vagrantup.com.pid
[root@vagrant-centos65 mysql]# ls -lah ibdata/
total 13M
drwxr-xr-x 2 mysql mysql 4.0K Jun 18 12:12 .
drwxr-xr-x 8 mysql mysql 4.0K Jun 18 12:33 ..
-rw-rw---- 1 mysql mysql 12M Jun 18 12:30 ibdata1
-rw-rw---- 1 mysql mysql 32K Jun 18 12:12 ib_modified_log_1_0.xdb
-rw-rw---- 1 mysql mysql 4.0K Jun 18 12:12 ib_modified_log_2_1625987.xdb

And get the same results like in comment #3:
mysql> show variables like '%version%';
+-------------------------+--------------------------------------------------+
| Variable_name | Value |
+-------------------------+--------------------------------------------------+
| innodb_version | 5.6.17-66.0 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.17-66.0 |
| version_comment | Percona Server (GPL), Release 66.0, Revision 608 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+--------------------------------------------------+
7 rows in set (0.03 sec)

mysql> show variables like 'innodb_track%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_track_changed_pages | ON |
+----------------------------+-------+
1 row in set (0.00 sec)

mysql> select * from information_schema.INNODB_CHANGED_PAGES;
ERROR 1012 (HY000): Can't read record in system table

[Laurynas Biveinis (laurynas-biveinis)]

Jericho -

Are PS 5.1 and 5.5 on CentOS 6.5 affected too?

[Jericho Rivera (jericho-rivera)]

Tests with PS 5.1.73-rel14.11 on Centos 6.5

Installed PS 5.1 and started server with innodb_track_changed_pages OFF
[root@vagrant-centos65 lib]# cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
#innodb_data_home_dir=/var/lib/mysql/ibdata
#innodb_track_changed_pages=1
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

[root@vagrant-centos65 lib]# service mysql start
Starting MySQL (Percona Server). SUCCESS!
[root@vagrant-centos65 lib]# ls mysql -lah
total 21M
drwx------ 5 mysql mysql 4.0K Jun 23 01:36 .
drwxr-xr-x. 18 root root 4.0K Jun 23 01:35 ..
drwxr-xr-x 2 mysql mysql 4.0K Jun 23 01:35 ibdata
-rw-rw---- 1 mysql mysql 10M Jun 23 01:36 ibdata1
-rw-rw---- 1 mysql mysql 5.0M Jun 23 01:36 ib_logfile0
-rw-rw---- 1 mysql mysql 5.0M Jun 23 01:36 ib_logfile1
drwx------ 2 mysql mysql 4.0K Jun 23 01:35 mysql
srwxrwxrwx 1 mysql mysql 0 Jun 23 01:36 mysql.sock
drwx------ 2 mysql mysql 4.0K Jun 23 01:35 test
-rw-rw---- 1 mysql mysql 5 Jun 23 01:36 vagrant-centos65.vagrantup.com.pid
[root@vagrant-centos65 lib]# mysql
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 1
Server version: 5.1.73-rel14.11 Percona Server (GPL), 14.11, Revision 603

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, 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 @@version;
+-----------------+
| @@version |
+-----------------+
| 5.1.73-rel14.11 |
+-----------------+
1 row in set (0.00 sec)

mysql> show variables like 'innodb_track%';
+----------------------------+-------+
| Variable_name | Value |
+----------------------------+-------+
| innodb_track_changed_pages | OFF |
+----------------------------+-------+
1 row in set (0.00 sec)

mysql> exit
Bye

Enabled innodb_track_changed_pages and also added innodb_data_home_dir
[root@vagrant-centos65 lib]# cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
innodb_data_home_dir=/var/lib/mysql/ibdata
innodb_track_changed_pages=1
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

[root@vagrant-centos65 lib]# service mysql restart
Shutting down MySQL. SUCCESS!
Starting MySQL (Percona Server). SUCCESS!
[root@vagrant-centos65 lib]# ls -lah mysql
total 21M
drwx------ 5 mysql mysql 4.0K Jun 23 01:37 .
drwxr-xr-x. 18 root root 4.0K Jun 23 01:35 ..
drwxr-xr-x 2 mysql mysql 4.0K Jun 23 01:37 ibdata
-rw-rw---- 1 mysql mysql 10M Jun 23 01:37 ibdata1
-rw-rw---- 1 mysql mysql 5.0M Jun 23 01:37 ib_logfile0
-rw-rw---- 1 mysql mysql 5.0M Jun 23 01:36 ib_logfile1
drwx------ 2 mysql mysql 4.0K Jun 23 01:35 mysql
srwxrwxrwx 1 mysql mysql 0 Jun 23 01:37 mysq...

[Jericho Rivera (jericho-rivera)]

On PS 5.5.37-35.1 I get the following:

Started with innodb_track_changed_pages OFF and innodb_data_home_dir disabled
[root@vagrant-centos65 lib]# service mysql start
Starting MySQL (Percona Server).. SUCCESS!

[root@vagrant-centos65 lib]# cat /var/log/mysqld.log
140623 02:40:52 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
140623 2:40:52 [Note] Plugin 'FEDERATED' is disabled.
140623 2:40:52 InnoDB: The InnoDB memory heap is disabled
140623 2:40:52 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140623 2:40:52 InnoDB: Compressed tables use zlib 1.2.3
140623 2:40:52 InnoDB: Using Linux native AIO
140623 2:40:52 InnoDB: Initializing buffer pool, size = 128.0M
140623 2:40:52 InnoDB: Completed initialization of buffer pool
140623 2:40:52 InnoDB: highest supported file format is Barracuda.
140623 2:40:52 InnoDB: Waiting for the background threads to start
140623 2:40:53 Percona XtraDB (http://www.percona.com) 5.5.37-35.1-35.1 started; log sequence number 1597945
140623 2:40:53 [Note] Event Scheduler: Loaded 0 events
140623 2:40:53 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.37-35.1' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release 35.1, Revision 666

[root@vagrant-centos65 lib]# ls -lah mysql
total 29M
drwxr-xr-x 6 mysql mysql 4.0K Jun 23 02:40 .
drwxr-xr-x. 18 root root 4.0K Jun 23 02:07 ..
drwxr-xr-x 2 mysql mysql 4.0K Jun 23 02:09 ibdata
-rw-rw---- 1 mysql mysql 18M Jun 23 02:40 ibdata1
-rw-rw---- 1 mysql mysql 5.0M Jun 23 02:40 ib_logfile0
-rw-rw---- 1 mysql mysql 5.0M Jun 23 02:08 ib_logfile1
drwx------ 2 mysql mysql 4.0K Jun 23 02:07 mysql
srwxrwxrwx 1 mysql mysql 0 Jun 23 02:40 mysql.sock
drwx------ 2 mysql mysql 4.0K Jun 23 02:07 performance_schema
-rw-r--r-- 1 root root 117 Jun 23 02:07 RPM_UPGRADE_HISTORY
-rw-r--r-- 1 mysql mysql 117 Jun 23 02:07 RPM_UPGRADE_MARKER-LAST
drwx------ 2 mysql mysql 4.0K Jun 23 02:07 test
-rw-rw---- 1 mysql mysql 5 Jun 23 02:40 vagrant-centos65.vagrantup.com.pid

Added in the two options:
[root@vagrant-centos65 lib]# cat /etc/my.cnf
[mysqld]
datadir=/var/lib/mysql
innodb_data_home_dir=/var/lib/mysql/ibdata
innodb_track_changed_pages=1
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

Can't start server:
[root@vagrant-centos65 lib]# service mysql restart
Shutting down MySQL (Percona Server).... SUCCESS!
Starting MySQL (Percona Server). ERROR! The server quit without updating PID file (/var/lib/mysql/vagrant-centos65.vagrantup.com.pid).

Complete error log:
[root@vagrant-centos65 lib]# cat /var/log/mysqld.log
140623 02:40:52 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
140623 2:40:52 [Note] Plugin 'FEDERATED' is disabled.
140623 2:40:52 InnoDB: The InnoDB memory heap is disabled
140623 2:40:52 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140623 2:40:52 InnoDB: Compressed tables use zlib 1.2.3
140623 2:40:52 InnoDB: Using Linux native AIO
140623 2:40:52 InnoDB: Initializi...

[Laurynas Biveinis (laurynas-biveinis)]

Jericho -

5.1 test does not seem to write any actual bitmap data. Try creating a table and performing a (slow) server shutdown with bitmaps on.

5.5 test looks completely broken?

[Jericho Rivera (jericho-rivera)]

Laurynas,

On comment #7 every time I set innodb_track_changed_pages=1 and set innodb_data_home_dir I get the following:

mysql> show variables like 'innodb_track%';
Empty set (0.00 sec)

mysql> show engines;
+------------+---------+----------------------------------------------------------------+--------------+------+------------+
| Engine | Support | Comment | Transactions | XA | Savepoints |
+------------+---------+----------------------------------------------------------------+--------------+------+------------+
| MyISAM | DEFAULT | Default engine as of MySQL 3.23 with great performance | NO | NO | NO |
| MRG_MYISAM | YES | Collection of identical MyISAM tables | NO | NO | NO |
| BLACKHOLE | YES | /dev/null storage engine (anything you write to it disappears) | NO | NO | NO |
| CSV | YES | CSV storage engine | NO | NO | NO |
| MEMORY | YES | Hash based, stored in memory, useful for temporary tables | NO | NO | NO |
| FEDERATED | NO | Federated MySQL storage engine | NULL | NULL | NULL |
| ARCHIVE | YES | Archive storage engine | NO | NO | NO |
+------------+---------+----------------------------------------------------------------+--------------+------+------------+
7 rows in set (0.00 sec)

Notice the Empty set on 'show variables...' and the absence of InnoDB engine on 'show engines'.

On comment #8, setting both options on my.cnf would not let MySQL server start at all.

Do note that on comment #8 it was a clean install on an empty mysql dir.

Further tests on PS 5.1 below:
With innodb_track_changed_pages ON and set innodb_data_home_dir, created InnoDB table:

mysql> create table test1.tbl1 (a INT, b TEXT, c TEXT) ENGINE=InnoDB;
Query OK, 0 rows affected, 2 warnings (0.16 sec)

mysql> show warnings;
+---------+------+----------------------------------------------+
| Level | Code | Message |
+---------+------+----------------------------------------------+
| Warning | 1286 | Unknown table engine 'InnoDB' |
| Warning | 1266 | Using storage engine MyISAM for table 'tbl1' |
+---------+------+----------------------------------------------+
2 rows in set (0.00 sec)

mysql> show variables like 'innodb_track%';
Empty set (0.00 sec)

mysql> show engines;
+------------+---------+----------------------------------------------------------------+--------------+------+------------+
| Engine | Support | Comment | Transactions | XA | Savepoints |
+------------+---------+----------------------------------------------------------------+--------------+------+------------+
| MyISAM | DEFAULT | Default engine as of MySQL 3.23 with great performance | NO | NO | NO |
| MRG_MYISAM | YES | Collection of identical MyISAM tables | NO | NO | NO |
| BLACKHOLE | YES | /dev/null storage engine (anything you write to it disappears) | NO | NO | NO |
| CSV | YES | CSV storage engine | NO | NO | NO |
| MEMORY | YES | Hash based, stored in memory, useful for temporary tabl...

[Laurynas Biveinis (laurynas-biveinis)]

Both 5.1 and 5.5 tests are invalid if InnoDB fails to even start.

In case of 5.1 you show an error log with

140624 3:04:13 InnoDB: Assertion failure in thread 139795121317824 in file fsp/fsp0fsp.c line 3004
InnoDB: Failing assertion: space != 0

can you resolve its stacktrace please?

[Jericho Rivera (jericho-rivera)]

Here's the stacktrace:

0x88cdb5 my_print_stacktrace + 53
0x68703b handle_fatal_signal + 1035
0x7f3f2953e710 _end + 678987936
0x7f3f280a1925 _end + 657373877
0x7f3f280a3105 _end + 657379989
0x81afc3 fil_space_is_corrupt + 52195
0x81b4b1 fil_space_is_corrupt + 53457
0x8227da fil_space_is_corrupt + 82938
0x7c18b2 thr_local_hash_nodes + 151202
0x7ef205 thr_local_hash_nodes + 337909
0x7f031c thr_local_hash_nodes + 342284
0x799482 innobase_get_trx + 515202
0x71a168 innobase_get_slow_log + 5032
0x67aaa8 ha_initialize_handlerton(st_plugin_int*) + 56
0x6f8967 find_sys_var(THD*, char const*, unsigned int) + 1751
0x6fa9f5 plugin_init(int*, char**, int) + 1605
0x5a08de mysqld_get_one_option + 4734
0x5a2f1e main + 446
0x7f3f2808dd1d _end + 657292973
0x4ed749 _start + 41

[Shahriyar Rzayev (rzayev-sehriyar)]

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