handle_fatal_signal (sig=11) in pfs_mutex_enter_func on SET @@GLOBAL.innodb_track_redo_log_now=TRUE

[Roel Van de Paar]

(gdb) bt
#0 0x00007fb96506a771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ab09a2 in my_write_core (sig=11) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/mysys/stacktrace.c:422
#2 0x000000000072ca03 in handle_fatal_signal (sig=11) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x0000000000b3ce59 in pfs_mutex_enter_func (mutex=0x200460, file_name=0x1040f50 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/log/log0online.cc", line=1222) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/include/sync0sync.ic:360
#5 0x0000000000b3f27f in log_online_follow_redo_log () at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/log/log0online.cc:1222
#6 0x0000000000ae0394 in track_redo_log_now_set (thd=0x7fb8b62a2000, var=0x158c220 <mysql_sysvar_track_redo_log_now>, var_ptr=0x158bae4 <innodb_track_redo_log_now>, save=0x7fb86a01f1c0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/handler/ha_innodb.cc:16555
#7 0x00000000007f7e98 in sys_var_pluginvar::global_update (this=0x7fb9633e5540, thd=0x7fb8b62a2000, var=0x7fb86a01f1a0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_plugin.cc:3314
#8 0x000000000072a423 in sys_var::update (this=0x7fb9633e5540, thd=0x7fb8b62a2000, var=0x7fb86a01f1a0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/set_var.cc:193
#9 0x000000000072b5be in set_var::update (this=0x7fb86a01f1a0, thd=0x7fb8b62a2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/set_var.cc:679
#10 0x000000000072b132 in sql_set_variables (thd=0x7fb8b62a2000, var_list=0x7fb8b62a5200) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/set_var.cc:579
#11 0x00000000007e304d in mysql_execute_command (thd=0x7fb8b62a2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:4117
#12 0x00000000007ea051 in mysql_parse (thd=0x7fb8b62a2000, rawbuf=0x7fb86a01f010 "SET @@GLOBAL.innodb_track_redo_log_now=TRUE", length=43, parser_state=0x7fb96565adf0) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:6744
#13 0x00000000007dc5ec in dispatch_command (command=COM_QUERY, thd=0x7fb8b62a2000, packet=0x7fb8a5f06001 "SET @@GLOBAL.innodb_track_redo_log_now=TRUE", packet_length=43) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:1432
#14 0x00000000007db518 in do_command (thd=0x7fb8b62a2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:1049
#15 0x00000000007a34d5 in do_handle_one_connection (thd_arg=0x7fb8b62a2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_connect.cc:1532
#16 0x00000000007a2fdd in handle_one_connection (arg=0x7fb8b62a2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_connect.cc:1443
#17 0x0000000000dbdbb8 in pfs_spawn_thread (arg=0x7fb948fc9f20) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/perfschema/pfs.cc:1860
#18 0x00007fb965065df3 in start_thread () from /lib64/libpthread.so.0
#19 0x00007fb963d2f3dd in clone () from /lib64/libc.so.6

[Roel Van de Paar (roel11)]

================== Use version:
Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug

================== Testcase:
SET @@GLOBAL.innodb_track_changed_pages=TRUE;
SET @@GLOBAL.innodb_track_redo_log_now=TRUE;

================== Server start command:
[roel@localhost Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug]$ cat start
if [ -r /usr/lib64/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib64/libjemalloc.so.1
elif [ -r /usr/lib/x86_64-linux-gnu/libjemalloc.so.1 ]; then export LD_PRELOAD=/usr/lib/x86_64-linux-gnu/libjemalloc.so.1
elif [ -r /sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/lib/mysql/libjemalloc.so.1 ]; then export LD_PRELOAD=/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/lib/mysql/libjemalloc.so.1
else echo 'Error: jemalloc not found, please install it first'; exit 1; fi
/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/bin/mysqld --innodb_buffer_pool_size=2147483648 --basedir=/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug --datadir=/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/data --plugin-load=tokudb=ha_tokudb.so --core --socket=/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/socket.sock --port=13781 --log-error=/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/log/master.err 2>&1 &
echo 'Server socket: /sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/socket.sock with datadir: /sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/data'

[Roel Van de Paar (roel11)]

================== Same result testcase:
SET GLOBAL innodb_track_changed_pages = 1;
SET GLOBAL innodb_track_redo_log_now = 1;

[Roel Van de Paar (roel11)]

(That last testcase gives sig11 instead)

[Roel Van de Paar (roel11)]

================== Yet another crash with
SET @@GLOBAL.innodb_track_changed_pages=TRUE;
SET @@GLOBAL.innodb_track_redo_log_now=1;

Stack traces in bug 1369357 - InnoDB: Failing assertion: event in file os0sync.cc line 475 | abort (sig=6) in os_event_reset

[Roel Van de Paar (roel11)]

Marking bug 1369357 as a duplicate of this one for the time being

[Laurynas Biveinis (laurynas-biveinis)]

innodb_track_changed_pages is a dynamic variable in debug builds and only in debug builds to provide means for pausing the redo log tracker for testcases. The scenario of starting the server with it set to FALSE, and setting to TRUE later is unsupported and results in the variable set but the subsystem uninitialised.

A very minor bug, will only prioritise if QA asks.

[Roel Van de Paar (roel11)]

No need to prio at all, good to know details/info.

[Laurynas Biveinis (laurynas-biveinis)]

QA,

if there are more crashes where a server is _not_ started with --innodb-track-changed-pages[=TRUE], and the reduced testcase has SET innodb_track_changed_pages=TRUE anywhere in it, please completely ignore them. They are all duplicates of this bug, and there is more than enough info already.

[Roel Van de Paar (roel11)]

# Temporarily disabled due to bug 1368530
# SET @@GLOBAL.innodb_track_redo_log_now = truefalse |
# SET @@GLOBAL.innodb_track_changed_pages = truefalse |

For debug builds only, in Percona base RQG grammar.

[Roel Van de Paar (roel11)]

Additional maxigen filter
FILTER="${FILTER}|set.*[globalsession]*[ \.\t]*innodb_track_redo_log_now|set.*[globalsession]*[ \.\t]*innodb_track_changed_pages" # See PS bug 1368530

[Roel Van de Paar (roel11)]

grep -vi "innodb_track_redo_log_now" | \ was already filtered for pquery
grep -vi "set.*[globalsession]*[ \.\t]*innodb_track_changed_pages.*=" | \ added

[Roel Van de Paar (roel11)]

Based on new testcase #5 in bug 1372210 (dup of this one) I propose we triage as high.

[Roel Van de Paar (roel11)]

(The new testcase came out of a old run being cleaned up)

[Roel Van de Paar (roel11)]

Another one for this one, also from an old run

DROP DATABASE test;CREATE DATABASE test;USE test;
SET @@GLOBAL.innodb_track_changed_pages=TRUE;
PURGE CHANGED_PAGE_BITMAPS BEFORE 0;

[Roel Van de Paar (roel11)]

Last one has different resulting stack

#2 0x000000000072ca03 in handle_fatal_signal (sig=11) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x0000000000b3ce59 in pfs_mutex_enter_func (mutex=0x200460, file_name=0x1040f50 "/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/log/log0online.cc", line=1801) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/include/sync0sync.ic:360
#5 0x0000000000b4054f in log_online_purge_changed_page_bitmaps (lsn=200) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/log/log0online.cc:1801
#6 0x0000000000aca1a1 in innobase_purge_changed_page_bitmaps (lsn=200) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/storage/innobase/handler/ha_innodb.cc:3857
#7 0x0000000000649179 in purge_changed_page_bitmaps_handlerton (unused1=0x0, plugin=0x7fcfa1049bb8, lsn=0x7fcfa1049c08) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/handler.cc:7314
#8 0x00000000007f5187 in plugin_foreach_with_mask (thd=0x0, func=0x649128 <purge_changed_page_bitmaps_handlerton(THD*, plugin_ref, void*)>, type=1, state_mask=4294967287, arg=0x7fcfa1049c08) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_plugin.cc:2162
#9 0x00000000006491a9 in ha_purge_changed_page_bitmaps (lsn=200) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/handler.cc:7319
#10 0x00000000007e0030 in mysql_execute_command (thd=0x1e45250) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:3017
#11 0x00000000007ea051 in mysql_parse (thd=0x1e45250, rawbuf=0x7fcf641e6d70 "PURGE CHANGED_PAGE_BITMAPS BEFORE 200", length=37, parser_state=0x7fcfa104ae30) at/mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:6744
#12 0x00000000007dc5ec in dispatch_command (command=COM_QUERY, thd=0x1e45250, packet=0x263d4e1 "PURGE CHANGED_PAGE_BITMAPS BEFORE 200;", packet_length=38) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:1432
#13 0x00000000007db518 in do_command (thd=0x1e45250) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_parse.cc:1049
#14 0x00000000007a34d5 in do_handle_one_connection (thd_arg=0x1e45250) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_connect.cc:1532
#15 0x00000000007a2fdd in handle_one_connection (arg=0x1e45250) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_connect.cc:1443
#16 0x0000000000dbdbb8 in...

[Laurynas Biveinis (laurynas-biveinis)]

https://github.com/percona/percona-server/pull/146, https://github.com/percona/percona-server/pull/206

[Shahriyar Rzayev (rzayev-sehriyar)]

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