Percona Server moved to https://jira.percona.com/projects/PS

InnoDB: Failing assertion: log_sys->buf == ut_align(log_sys->buf_ptr, srv_log_write_ahead_size) in file log0log.cc line 1251

Bug #1597143 reported by Roel Van de Paar
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.5
Invalid
Undecided
Unassigned
5.6
Invalid
Undecided
Unassigned
5.7
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.7.13-6

Bug Description

2016-06-29 09:56:31 0x7f62789fd700 InnoDB: Assertion failure in thread 140060907263744 in file log0log.cc line 1251
InnoDB: Failing assertion: log_sys->buf == ut_align(log_sys->buf_ptr, srv_log_write_ahead_size)
InnoDB: We intentionally generate a memory trap.

+bt
#0 0x00007f629c73e741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x000000000183b0e8 in my_write_core (sig=6) at /git/PS-5.7_dbg/mysys/stacktrace.c:247
#2 0x0000000000e76cd3 in handle_fatal_signal (sig=6) at /git/PS-5.7_dbg/sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007f629aad75f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5 0x00007f629aad8ce8 in __GI_abort () at abort.c:90
#6 0x0000000001bab987 in ut_dbg_assertion_failed (expr=0x21be938 "log_sys->buf == ut_align(log_sys->buf_ptr, srv_log_write_ahead_size)", file=0x21be0d8 "/git/PS-5.7_dbg/storage/innobase/log/log0log.cc", line=1251) at /git/PS-5.7_dbg/storage/innobase/ut/ut0dbg.cc:67
#7 0x0000000001a10f18 in log_buffer_switch () at /git/PS-5.7_dbg/storage/innobase/log/log0log.cc:1250
#8 0x0000000001a11636 in log_write_up_to (lsn=2497562, flush_to_disk=true) at /git/PS-5.7_dbg/storage/innobase/log/log0log.cc:1414
#9 0x0000000001a11988 in log_buffer_sync_in_background (flush=true) at /git/PS-5.7_dbg/storage/innobase/log/log0log.cc:1518
#10 0x0000000001b40791 in srv_sync_log_buffer_in_background () at /git/PS-5.7_dbg/storage/innobase/srv/srv0srv.cc:2342
#11 0x0000000001b40d4b in srv_master_do_active_tasks () at /git/PS-5.7_dbg/storage/innobase/srv/srv0srv.cc:2515
#12 0x0000000001b419c4 in srv_master_thread (arg=0x0) at /git/PS-5.7_dbg/storage/innobase/srv/srv0srv.cc:2772
#13 0x00007f629c739dc5 in start_thread (arg=0x7f62789fd700) at pthread_create.c:308
#14 0x00007f629ab9821d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

DROP DATABASE test;CREATE DATABASE test;USE test;
INSTALL PLUGIN rpl_semi_sync_master SONAME 'semisync_master.so';
INSTALL PLUGIN rpl_semi_sync_slave SONAME 'semisync_slave.so';
INSTALL PLUGIN auth_pam SONAME 'auth_pam.so';
INSTALL PLUGIN auth_pam_compat SONAME 'auth_pam_compat.so';
INSTALL PLUGIN validate_password SONAME 'validate_password.so';
INSTALL PLUGIN version_tokens SONAME 'version_token.so';
INSTALL PLUGIN auth_socket SONAME 'auth_socket.so';
INSTALL PLUGIN mysql_no_login SONAME 'mysql_no_login.so';
INSTALL PLUGIN rewriter SONAME 'rewriter.so';
INSTALL PLUGIN tokudb_file_map SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_fractal_tree_info SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_fractal_tree_block_map SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_trx SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_locks SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_lock_waits SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_background_job_status SONAME 'ha_tokudb.so';
INSTALL PLUGIN mysqlx SONAME 'mysqlx.so';
create table t0(id int key)engine=innodb row_format=compressed;
SET global innodb_log_write_ahead_size=-0;

Revision history for this message
Roel Van de Paar (roel11) wrote :

Upstream does not crash

mysql> SHOW WARNINGS;
+---------+------+------------------------------------------------------------+
| Level | Code | Message |
 +---------+------+------------------------------------------------------------+
| Warning | 1292 | Truncated incorrect innodb_log_write_ahead_size value: '0' |
 +---------+------+------------------------------------------------------------+
1 row in set (0.00 sec)

Revision history for this message
Roel Van de Paar (roel11) wrote :

Adding qafix, this bug is a screenfiller

log0log.cc line 1251 (Seen 384 times: reducers 10043,10057,10121,10127,10146,10169,10183,10252,10259,10262,1026,10275,10293,10327,10357,10400,10466,10528,10532,10578,10623,1065,10676,10688,1069,10821,10822,10840,10849,10862,10874,10947,10950,10955,10996,11014,11027,11040,11093,11113,11124,11131,11167,11190,11219,11249,11427,1142,11444,1147,11498,11508,11509,11524,11530,11572,11582,11604,11618,11650,11666,11670,1194,1229,1271,1297,1358,1366,1375,1389,143,1444,1461,1494,1503,1509,1540,1550,1583,1587,1590,1612,1635,164,1680,1728,1747,1801,1818,1820,1852,186,1887,1919,1926,1934,1939,1940,1954,195,1968,1990,210,2134,2140,2195,2206,2220,2224,2245,2284,2340,2379,239,2456,2471,2516,2546,2548,2598,259,2648,264,2730,2768,2796,2798,2870,2882,2892,2904,2967,2973,2976,2983,2992,3000,3005,302,3089,308,3109,312,3183,323,3251,3256,3282,3333,3354,3360,3417,347,3497,3575,3600,3616,3646,3666,3693,3700,3709,3712,3723,37,3862,3874,3883,3895,3954,3989,4007,405,4082,4094,4100,4106,4144,4152,4164,4181,4188,4214,4228,4261,4369,4438,4515,458,4618,4638,466,4719,4724,4736,4744,4761,4776,4777,482,4872,4894,4931,4945,4997,5040,506,5105,5161,5165,5236,523,5251,5261,529,5303,5322,5358,5405,540,5460,5561,5567,5585,5599,5712,5746,5761,5835,5866,5902,5996,6003,6012,6026,6040,6055,605,607,609,6150,6170,6219,6227,6269,6302,6309,6317,6336,6350,6366,6373,6376,6388,6402,6438,6472,6476,6525,6536,6605,6656,6666,6710,671,6804,6888,6889,6904,6934,695,6989,7000,7037,7044,7144,7193,7206,7247,7263,7280,7291,7356,7378,7452,7453,745,7502,7560,7580,7584,7625,7635,7636,763,7662,7709,7730,7744,7759,7777,7791,7835,786,789,7907,7913,7925,7940,8002,8009,800,8046,8099,8146,8169,8177,8192,8202,8240,8253,8276,8279,8316,8321,8329,8360,8395,8411,8447,8462,8477,847,8490,8513,8522,860,8707,8725,8726,873,8740,8761,8780,8814,8864,8904,8920,9018,9021,9050,9096,9137,9139,9189,9245,9262,9285,9303,9310,9317,9364,9411,944,9466,9481,9501,950,9543,9595,961,9644,9661,9686,9712,9714,9725,9751,9784,9788,9843,9881,9925,992)

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

In order to support innodb_flush_method=ALL_O_DIRECT, the log I/O buffers were aligned to innodb_log_write_ahead_size. This missed that the variable is dynamic. Re-aligning the buffers on updating the variable seems like an overkill, and the simplest fix is to align them on the maximum allowed value (UNIV_PAGE_SIZE_DEF) instead.

tags: added: regression xtradb
Revision history for this message
Roel Van de Paar (roel11) wrote :

Another qafix issue ended up being related;

DROP DATABASE test;CREATE DATABASE test;USE test;
INSTALL PLUGIN rpl_semi_sync_master SONAME 'semisync_master.so';
INSTALL PLUGIN rpl_semi_sync_slave SONAME 'semisync_slave.so';
INSTALL PLUGIN auth_pam SONAME 'auth_pam.so';
INSTALL PLUGIN auth_pam_compat SONAME 'auth_pam_compat.so';
INSTALL PLUGIN QUERY_RESPONSE_TIME SONAME 'query_responset.so';
INSTALL PLUGIN QUERY_RESPONSE_TIME_AUDIT SONAME 'query_responset.so';
INSTALL PLUGIN QUERY_RESPONSE_TIME_READ SONAME 'query_responset.so';
INSTALL PLUGIN QUERY_RESPONSE_TIME_WRITE SONAME 'query_responset.so';
INSTALL PLUGIN validate_password SONAME 'validate_password.so';
INSTALL PLUGIN version_tokens SONAME 'version_token.so';
INSTALL PLUGIN auth_socket SONAME 'auth_socket.so';
INSTALL PLUGIN mysql_no_login SONAME 'mysql_no_login.so';
INSTALL PLUGIN rewriter SONAME 'rewriter.so';
INSTALL PLUGIN tokudb_file_map SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_fractal_tree_info SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_fractal_tree_block_map SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_trx SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_locks SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_lock_waits SONAME 'ha_tokudb.so';
INSTALL PLUGIN tokudb_background_job_status SONAME 'ha_tokudb.so';
INSTALL PLUGIN mysqlx SONAME 'mysqlx.so';
CREATE TABLE t0(a INT,b CHAR)ENGINE=InnoDB;
create table t0_myisam as select * from t0;
SET global innodb_log_write_ahead_size=0;

Revision history for this message
Roel Van de Paar (roel11) wrote :

The outcome from that one is slightly different;

2016-06-29 15:25:32 0x7f2f789fd700 InnoDB: Assertion failure in thread 139841863931648 in file log0log.cc line 1256
InnoDB: Failing assertion: log_sys->buf == ut_align(log_sys->buf_ptr, srv_log_write_ahead_size)

>> Note line 1256 instead of 1251

Revision history for this message
Roel Van de Paar (roel11) wrote :

+bt
#0 0x00007f2f9c85d741 in __pthread_kill (threadid=<optimized out>, signo=6) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x000000000183b0e8 in my_write_core (sig=6) at /git/PS-5.7_dbg/mysys/stacktrace.c:247
#2 0x0000000000e76cd3 in handle_fatal_signal (sig=6) at /git/PS-5.7_dbg/sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007f2f9abf65f7 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#5 0x00007f2f9abf7ce8 in __GI_abort () at abort.c:90
#6 0x0000000001bab987 in ut_dbg_assertion_failed (expr=0x21be938 "log_sys->buf == ut_align(log_sys->buf_ptr, srv_log_write_ahead_size)", file=0x21be0d8 "/git/PS-5.7_dbg/storage/innobase/log/log0log.cc", line=1256) at /git/PS-5.7_dbg/storage/innobase/ut/ut0dbg.cc:67
#7 0x0000000001a10fee in log_buffer_switch () at /git/PS-5.7_dbg/storage/innobase/log/log0log.cc:1255
#8 0x0000000001a11636 in log_write_up_to (lsn=2501989, flush_to_disk=true) at /git/PS-5.7_dbg/storage/innobase/log/log0log.cc:1414
#9 0x0000000001a11988 in log_buffer_sync_in_background (flush=true) at /git/PS-5.7_dbg/storage/innobase/log/log0log.cc:1518
#10 0x0000000001b40791 in srv_sync_log_buffer_in_background () at /git/PS-5.7_dbg/storage/innobase/srv/srv0srv.cc:2342
#11 0x0000000001b40d4b in srv_master_do_active_tasks () at /git/PS-5.7_dbg/storage/innobase/srv/srv0srv.cc:2515
#12 0x0000000001b419c4 in srv_master_thread (arg=0x0) at /git/PS-5.7_dbg/storage/innobase/srv/srv0srv.cc:2772
#13 0x00007f2f9c858dc5 in start_thread (arg=0x7f2f789fd700) at pthread_create.c:308
#14 0x00007f2f9acb721d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Revision history for this message
Roel Van de Paar (roel11) wrote :

Laurynas confirms second item is same bug

Revision history for this message
Roel Van de Paar (roel11) wrote :

Second issue just a prevalent;

log0log.cc line 1256 (Seen 408 times:....

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

https://github.com/percona/percona-server/pull/634

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

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

Other bug subscribers

Remote bug watches

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