mysql will not start with changed page tracking and O_DIRECT

[Jervin R]

Start and restart Percona Server 5.6.26 with the following setting, eventually it will fail to start with the below error:

innodb_track_changed_pages = 1
innodb_flush_method = O_DIRECT

2015-09-29 02:36:50 15856 [Note] /opt/mysql/5.6.260/bin/mysqld: ready for connections.
Version: '5.6.26-74.0' socket: '/tmp/mysql_sandbox56260.sock' port: 56260 Percona Server (GPL), Release 74.0, Revision 32f8dfd
2015-09-29 02:36:52 7f7b0cfff700 InnoDB: Error: Write to file ./ib_modified_log_3_1627158.xdb failed at offset 0.
InnoDB: 4096 bytes should have been written, only 0 were written.
InnoDB: Operating system error number 22.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
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
2015-09-29 02:36:52 7f7b0cfff700 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
2015-09-29 02:36:52 15856 [ERROR] InnoDB: failed writing changed page bitmap file './ib_modified_log_3_1627158.xdb'

2015-09-29 02:36:52 15856 [ERROR] InnoDB: log tracking bitmap write failed, stopping log tracking thread!

This seems to be reminiscent of:

https://bugs.launchpad.net/percona-server/+bug/1105709
https://bugs.launchpad.net/percona-server/+bug/1131949

[Roel Van de Paar (roel11)]

./bin/perror 22
OS error code 22: Invalid argument

[Rick Pizzi (pizzi)]

This also bites me on 5.5.45-37.4:

151007 14:25:53 mysqld_safe Starting mysqld daemon with databases from /db/data
151007 14:25:53 [Note] /usr/sbin/mysqld (mysqld 5.5.45-37.4-log) starting as process 6915 ...
151007 14:25:53 [Note] Plugin 'FEDERATED' is disabled.
151007 14:25:53 InnoDB: The InnoDB memory heap is disabled
151007 14:25:53 InnoDB: Mutexes and rw_locks use GCC atomic builtins
151007 14:25:53 InnoDB: Compressed tables use zlib 1.2.3
151007 14:25:53 InnoDB: Using Linux native AIO
151007 14:25:53 InnoDB: Initializing buffer pool, size = 24.0G
151007 14:25:54 InnoDB: Completed initialization of buffer pool
151007 14:25:54 InnoDB: highest supported file format is Barracuda.
InnoDB: starting tracking changed pages from LSN 305663925781
151007 14:25:55 InnoDB: Waiting for the background threads to start
151007 14:25:56 Percona XtraDB (http://www.percona.com) 5.5.45-37.4 started; log sequence number 305663925781
151007 14:25:56 [Note] Slave SQL thread initialized, starting replication in log 'jcdb01.000020' at position 475027604, relay log './mysqld-relay-bin.000020' position: 2377876
151007 14:25:56 [Note] Slave I/O thread: connected to master 'replication@172.16.0.30:3306',replication started in log 'jcdb01.000020' at position 475027604
151007 14:25:56 [Note] Event Scheduler: Loaded 0 events
151007 14:25:56 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.45-37.4-log' socket: '/db/data/mysql.sock' port: 3306 Percona Server (GPL), Release 37.4, Revision 042e02b
151007 14:25:56 InnoDB: Error: Write to file ./ib_modified_log_1_0.xdb failed at offset 0 0.
InnoDB: 4096 bytes should have been written, only 0 were written.
InnoDB: Operating system error number 22.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
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
151007 14:25:56 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: Error: failed writing changed page bitmap file './ib_modified_log_1_0.xdb'
InnoDB: Error: log tracking bitmap write failed, stopping log tracking thread!

Looks like a regression bug. This is with O_DIRECT on XFS filesystem.

[Rick Pizzi (pizzi)]

Downgraded to 5.5.44-37.3 and it works fine on that version.

[Laurynas Biveinis (laurynas-biveinis)]

Jervin, can you please check 5.5 ?

[Jervin R (revin)]

Confirming, 5.5.45 is affected:

Version: '5.5.45-37.4' socket: '/tmp/mysql_sandbox55450.sock' port: 55450 Percona Server (GPL), Release 37.4, Revision 042e02b
151027 6:33:24 [Note] /opt/mysql/5.5.450/bin/mysqld: Normal shutdown

151027 6:33:24 [Note] Event Scheduler: Purging the queue. 0 events
151027 6:33:24 InnoDB: Starting shutdown...
151027 6:33:26 InnoDB: Shutdown completed; log sequence number 1597945
151027 6:33:26 [Note] /opt/mysql/5.5.450/bin/mysqld: Shutdown complete

151027 06:33:26 mysqld_safe mysqld from pid file /opt/msb/msb_5_5_450/data/mysql_sandbox55450.pid ended
151027 06:33:28 mysqld_safe Starting mysqld daemon with databases from /opt/msb/msb_5_5_450/data
151027 6:33:28 [Note] /opt/mysql/5.5.450/bin/mysqld (mysqld 5.5.45-37.4) starting as process 25667 ...
151027 6:33:28 [Note] Plugin 'FEDERATED' is disabled.
151027 6:33:28 InnoDB: The InnoDB memory heap is disabled
151027 6:33:28 InnoDB: Mutexes and rw_locks use GCC atomic builtins
151027 6:33:28 InnoDB: Compressed tables use zlib 1.2.3
151027 6:33:28 InnoDB: Using Linux native AIO
151027 6:33:28 InnoDB: Initializing buffer pool, size = 128.0M
151027 6:33:28 InnoDB: Completed initialization of buffer pool
151027 6:33:28 InnoDB: highest supported file format is Barracuda.
InnoDB: last tracked LSN in './ib_modified_log_2_8204.xdb' is 8204, but the last checkpoint LSN is 1597945. This might be due to a server crash or a very fast shutdown. Reading the log to advance the last tracked LSN.
151027 6:33:28 InnoDB: Error: Write to file ./ib_modified_log_2_8204.xdb failed at offset 0 0.
InnoDB: 4096 bytes should have been written, only 0 were written.
InnoDB: Operating system error number 22.
InnoDB: Check that your OS and file system support files of this size.
InnoDB: Check also that the disk is not full or a disk quota exceeded.
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
151027 6:33:28 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: Error: failed writing changed page bitmap file './ib_modified_log_2_8204.xdb'
151027 06:33:28 mysqld_safe mysqld from pid file /opt/msb/msb_5_5_450/data/mysql_sandbox55450.pid ended

[Marc Castrovinci (marc-castrovinci)]

Is the fix in this latest Percona Cluster release?

https://www.percona.com/blog/2016/01/11/percona-xtradb-cluster-5-6-27-25-13-is-now-available/

[Hrvoje Matijakovic (hrvojem)]

Marc,

Yes, PXC-5.6.27-25.13 is based on Percona Server 5.6.27-76.0 so it contains that fix as well (among others).

[Marc Castrovinci (marc-castrovinci)]

Ok thanks. I never saw it in the Percona Cluster release notes here: https://www.percona.com/blog/2016/01/11/percona-xtradb-cluster-5-6-27-25-13-is-now-available/

[Shahriyar Rzayev (rzayev-sehriyar)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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