percona_changed_page_bmp_flush fails intermittently

Bug #1529885 reported by Laurynas Biveinis
10
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Fix Released
Medium
Nickolay Ihalainen
5.6
Fix Released
Medium
Nickolay Ihalainen
5.7
Invalid
Medium
Nickolay Ihalainen

Bug Description

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.

Tags: ci xtradb 64171
tags: added: ci xtradb
Revision history for this message
Nickolay Ihalainen (ihanick) wrote :

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

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

5.7 bug is different: bug 1578516

tags: added: 64171
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

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

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.