Crash on select from I_S.INNODB_CHANGED_PAGES

[Ville Ojamo]

- Percona-Server-server-56-5.6.28-rel76.1.el6.x86_64
- Circular ("multi-master") replication with two servers
- innodb_flush_method=O_DIRECT, innodb_track_changed_pages=1, innodb_flush_neighbors=0 and innodb_log_block_size=4k (these servers have SSD)

MySQL crashes every time when doing:
mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_CHANGED_PAGES;
ERROR 2013 (HY000): Lost connection to MySQL server during query

Meanwhile, from log file, the first error happens exactly when the SELECT is run:
2016-01-27 11:49:49 14045 [ERROR] InnoDB: Tried to read 4096 bytes at offset 0. Was only able to read 0.
2016-01-27 11:49:49 7f7c241ca700 InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2016-01-27 11:49:49 14045 [ERROR] InnoDB: File (unknown): 'read' returned OS error 122. Cannot continue operation
160127 11:49:49 mysqld_safe Number of processes running now: 0
160127 11:49:49 mysqld_safe mysqld restarted
2016-01-27 11:49:49 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2016-01-27 11:49:49 0 [Note] /usr/sbin/mysqld (mysqld 5.6.28-76.1-log) starting as process 14138 ...
2016-01-27 11:49:49 14138 [Warning] The option innodb (skip-innodb) is deprecated and will be removed in a future release
2016-01-27 11:49:49 14138 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: Warning: innodb_log_block_size has been changed from default value 512. (###EXPERIMENTAL### operation)
InnoDB: The log block size is set to 4096.
...

[Paul (dbadojo)]

I received similar errors on Percona MySQL 5.5 and 5.6 but not 5.7 (5.7.14-7-log)

It occurs once a bitmap files exists...basically as soon as pages start changing.

mysql> select count(*) from INFORMATION_SCHEMA.INNODB_CHANGED_PAGES;
ERROR 2013 (HY000): Lost connection to MySQL server during query

-- Error log shows

016-09-07 06:29:08 6134 [ERROR] InnoDB: Tried to read 4096 bytes at offset 0. Was only able to read 0.
2016-09-07 06:29:08 7f3c18060700 InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
2016-09-07 06:29:08 6134 [ERROR] InnoDB: File (unknown): 'read' returned OS error 122. Cannot continue operation

As per https://bugs.launchpad.net/percona-xtradb-cluster/5.5/+bug/1500720/comments/4

Versions NOT AFFECTED:
5.5.44-37.3 does NOT have this problem.
5.7.14-7-log does NOT have this problem.

Confirmed on crash/restart on: Both Ubuntu and CentOS
5.5.48-37.8
5.5.49-37.9
5.5.51-38.1
5.6.32-rel78.0

Similar to
https://bugs.launchpad.net/percona-server/+bug/1131949
https://bugs.launchpad.net/percona-server/+bug/1529885
https://bugs.launchpad.net/percona-xtradb-cluster/5.5/+bug/1500720

Changing log block size did not help prevent the error.

From reading other bugs I suspect it is within log0online.c
A simple diff between 5.5 working < and not working >

diff ./percona-server-5.5.48-37.8/storage/innobase/log/log0online.c ./percona-server-5.5.44-37.3/storage/innobase/log/log0online.c
547c547
< OS_FILE_READ_WRITE_CACHED,
---
> OS_FILE_READ_WRITE,
707c707
< OS_FILE_READ_WRITE_CACHED, &success);
---
> OS_FILE_READ_WRITE, &success);
1497d1496
< size_t srv_data_home_len;
1501,1510c1500
< srv_data_home_len = strlen(srv_data_home);
< if (srv_data_home_len
< && srv_data_home[srv_data_home_len-1]
< != SRV_PATH_SEPARATOR) {
< ut_snprintf(bitmap_file->name, FN_REFLEN, "%s%c%s",
< srv_data_home, SRV_PATH_SEPARATOR, name);
< } else {
< ut_snprintf(bitmap_file->name, FN_REFLEN, "%s%s",
< srv_data_home, name);
< }
---
> ut_snprintf(bitmap_file->name, FN_REFLEN, "%s%s", srv_data_home, name);

As expected 5.7 source code is significantly difference.

[Rick Pizzi (pizzi)]

I have got the very same crash when issuing a select from information_schema.INNODB_BUFFER_PAGE_LRU

[Laurynas Biveinis (laurynas-biveinis)]

Rick, it is unlikely for a information_schema.INNODB_BUFFER_PAGE_LRU query to be the very same crash - the code paths are completely different - can you post error log contents? It will probably have to be logged as a new bug

[Roel Van de Paar (roel11)]

Could you please upload a full error log? Thank you

[Paul (dbadojo)]

The error is the same as listed previously.

Hopefully this is pre-formatted so it is easier to read.

The error log attached shows the same error.
<pre>
InnoDB: Error: tried to read 4096 bytes at offset 0 0.
InnoDB: Was only able to read 0.
170218 3:12:30 InnoDB: Operating system error number 22 in a file operation.
InnoDB: Error number 22 means 'Invalid argument'.
InnoDB: Some operating system error numbers are described at
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/operating-system-error-codes.html
InnoDB: File operation call: 'read'.
InnoDB: Cannot continue operation.
</pre>

[Rick Pizzi (pizzi)]

I don't seem to be able to reproduce it anymore (with INNODB_BUFFER_PAGE_LRU) but now I'm on 5.6.35.... but I remember the error printed in error log was 100% identical, that's why I reported it here. You may be right that it is probably unrelated, only has the same outcome perhaps.

Rick

[Shahriyar Rzayev (rzayev-sehriyar)]

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