percona_changed_page_bmp_flush fails intermittently

[Laurynas Biveinis]

percona_changed_page_bmp_flush fails to restart the server with innodb_flush_method=ALL_O_DIRECT intermittently. With an extra ut_a(errno != EINVAL) in I/O error handler, the stacktrace on 5.7 is

#0 __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
63 ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c: No such file or directory.
#0 __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1 0x000000000184d65f in my_write_core (sig=6) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/mysys/stacktrace.c:247
#2 0x0000000000e7aaba in handle_fatal_signal (sig=6) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007f10980a00d5 in __GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5 0x00007f10980a383b in __GI_abort () at abort.c:91
#6 0x0000000001ab2c8f in ut_dbg_assertion_failed (expr=0x21c75d3 "err != EINVAL", file=0x21c6918 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc", line=2795) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/ut/ut0dbg.cc:67
#7 0x00000000019425fb in os_file_get_last_error_low (report_all_errors=false, on_error_silent=false) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc:2795
#8 0x000000000194575b in os_file_handle_error_cond_exit (name=0x0, operation=0x21c7bdd "read", should_exit=true, on_error_silent=false) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc:5626
#9 0x0000000001945a73 in os_file_handle_error (name=0x0, operation=0x21c7bdd "read") at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc:5710
#10 0x00000000019455bc in os_file_read_page (type=..., file=8, buf=0x7ffcee9dea10, offset=0, n=2048, o=0x0, exit_on_err=true, trx=0x0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc:5567
#11 0x000000000194620d in os_file_read_func (type=..., file=8, buf=0x7ffcee9dea10, offset=0, n=2048, trx=0x0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc:5930
#12 0x00000000019481be in os_aio_func (type=..., mode=24, name=0x34d7ab8 "./ib_logfile0", file=8, buf=0x7ffcee9dea10, offset=0, n=2048, read_only=false, m1=0x34d79e8, m2=0x34d7d28, space_id=4294967280, trx=0x0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/os/os0file.cc:7218
#13 0x0000000001b92539 in pfs_os_aio_func (type=..., mode=24, name=0x34d7ab8 "./ib_logfile0", file=8, buf=0x7ffcee9dea10, offset=0, n=2048, read_only=false, m1=0x34d79e8, m2=0x34d7d28, space_id=4294967280, trx=0x0, src_file=0x22522c8 "/mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/fil/fil0fil.cc", src_line=5663) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/include/os0file.ic:255
#14 0x0000000001ba2a91 in _fil_io (type=..., sync=true, page_id=..., page_size=..., byte_offset=0, len=2048, buf=0x7ffcee9dea10, message=0x34d7d28, trx=0x0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/fil/fil0fil.cc:5663
#15 0x000000000193106c in recv_recovery_from_checkpoint_start (flush_lsn=20444399) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/log/log0recv.cc:3898
#16 0x0000000001a52049 in innobase_start_or_create_for_mysql () at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/srv/srv0start.cc:2230
#17 0x00000000018767b3 in innobase_init (p=0x30719c0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/storage/innobase/handler/ha_innodb.cc:3919
#18 0x0000000000f0af65 in ha_initialize_handlerton (plugin=0x32091d8) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/handler.cc:870
#19 0x0000000001559d87 in plugin_initialize (plugin=0x32091d8) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/sql_plugin.cc:1178
#20 0x000000000155a645 in plugin_init (argc=0x2c9a6b0, argv=0x306faf8, flags=0) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/sql_plugin.cc:1435
#21 0x0000000000e694c8 in init_server_components () at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/mysqld.cc:4221
#22 0x0000000000e6ab5e in mysqld_main (argc=93, argv=0x306faf8) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/mysqld.cc:4897
#23 0x0000000000e61dd4 in main (argc=10, argv=0x7ffcee9e8048) at /mnt/workspace/mysql-5.7-param/BUILD_TYPE/debug/Host/ubuntu-precise-64bit/sql/main.cc:25

Thus, this is read call returning EINVAL trying to read 2K from the log opened with O_DIRECT. The fix would be, for 5.5 and 5.6, to adjust the testcase to set innodb_log_block_size=4096 too, and for 5.7 setting innodb_log_write_ahead_size to the same and to ensure log reads are aligned too. 4K should work on our CI farm at least, if needed, the value can be bumped further.

[Nickolay Ihalainen (ihanick)]

Minimal test case:

--source include/not_windows.inc
--source include/have_innodb.inc

--disable_warnings
DROP TABLE IF EXISTS t1;
--enable_warnings

CREATE TABLE t1 (a INT, b BLOB) ENGINE=InnoDB;

INSERT INTO t1 VALUES (1, REPEAT("a", 20000));

--source include/shutdown_mysqld.inc
--let $restart_parameters=restart:--innodb-flush-method=ALL_O_DIRECT
--source include/start_mysqld.inc

[Laurynas Biveinis (laurynas-biveinis)]

5.7 bug is different: bug 1578516

[Laurynas Biveinis (laurynas-biveinis)]

https://github.com/percona/percona-server/pull/323, https://github.com/percona/percona-server/pull/334, https://github.com/percona/percona-server/pull/546

[Shahriyar Rzayev (rzayev-sehriyar)]

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