mysql will not start with changed page tracking and O_DIRECT

Bug #1500720 reported by Jervin R on 2015-09-29
18
This bug affects 3 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
High
Laurynas Biveinis
5.1
Invalid
Undecided
Unassigned
5.5
Fix Released
High
Laurynas Biveinis
5.6
Fix Released
High
Laurynas Biveinis
Percona XtraDB Cluster moved to https://jira.percona.com/projects/PXC
Status tracked in 5.6
5.5
Confirmed
Undecided
Unassigned
5.6
Fix Released
Undecided
Unassigned

Bug Description

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

tags: added: bitmap xtradb
Roel Van de Paar (roel11) wrote :

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

summary: - mysql will not start with changed page tracking and O_DIRECT on 5.6
+ mysql will not start with changed page tracking and O_DIRECT
Rick Pizzi (pizzi) wrote :

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

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

Jervin, can you please check 5.5 ?

Jervin R (revin) wrote :

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

tags: added: i62848
Hrvoje Matijakovic (hrvojem) wrote :

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

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/

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

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

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

Other bug subscribers