Crash on select from I_S.INNODB_CHANGED_PAGES

Bug #1538403 reported by Ville Ojamo on 2016-01-27
28
This bug affects 4 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
New
Undecided
Unassigned

Bug Description

- 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.
...

tags: added: bitmap xtradb
Paul (dbadojo) wrote :

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) wrote :

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

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) wrote :

Could you please upload a full error log? Thank you

Paul (dbadojo) wrote :

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) wrote :

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

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

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers