MEMORY/MyISAM tables + binlogging OFF | Empty GRA_*_*.log file(s) with Release build | Assertion failure binlog_cache_data::finalize(THD*, Log_event*): Assertion `!flags.finalized' failed in UNIV_DEBUG build.

Bug #1277986 reported by Jaime Sicam on 2014-02-08
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL patches by Codership
Status tracked in 5.6
5.6
High
Seppo Jaakola
Percona XtraDB Cluster
Status tracked in 5.6
5.5
Undecided
Unassigned
5.6
High
Unassigned

Bug Description

Version: PXC 5.6.15-56

Console commands:
[root@pxc-node-01-61 mysql]# mysql
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 45
Server version: 5.6.15-56 Percona XtraDB Cluster (GPL), Release 25.3, Revision 706, wsrep_25.3.r4034

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> use memtables;
Database changed
mysql> create table mem1(a int not null auto_increment primary key, b int null) engine=memory;
Query OK, 0 rows affected (0.03 sec)

mysql> insert into mem1(b) values(1),(2),(3);
Query OK, 3 rows affected (0.02 sec)
Records: 3 Duplicates: 0 Warnings: 0

mysql> quit
Bye

General Log:
140208 23:42:59 45 Connect root@localhost on
     45 Query select @@version_comment limit 1
140208 23:43:32 45 Query SELECT DATABASE()
     45 Init DB memtables
     45 Query show databases
     45 Query show tables
140208 23:44:25 45 Query create table mem1(a int not null auto_increment primary key, b int null) engine=memory
140208 23:44:50 45 Query insert into mem1(b) values(1),(2),(3)
140208 23:45:05 45 Quit

Timestamp on GRA_*_*.log:
[root@pxc-node-01-61 mysql]# stat GRA_45_-1.log
 File: `GRA_45_-1.log'
  Size: 0 Blocks: 0 IO Block: 4096 regular empty file
Device: fd00h/64768d Inode: 1047418 Links: 1
Access: (0660/-rw-rw----) Uid: ( 498/ mysql) Gid: ( 498/ mysql)
Access: 2014-02-08 23:45:05.032278519 +0800
Modify: 2014-02-08 23:45:05.032278519 +0800
Change: 2014-02-08 23:45:05.032278519 +0800

Paul Namuag (paul-namuag) wrote :

Verified this as well in Centos.

Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 11
Server version: 5.6.15-56-log Percona XtraDB Cluster (GPL), Release 25.3, Revision 706, wsrep_25.3.r4034

Copyright (c) 2009-2013 Percona LLC and/or its affiliates
Copyright (c) 2000, 2013, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> select @@general_log;
+---------------+
| @@general_log |
+---------------+
| 1 |
+---------------+
1 row in set (0.00 sec)

mysql> use memtables;
Database changed
mysql> create table mem1(a int not null auto_increment primary key, b int null) engine=memory;
Query OK, 0 rows affected (0.00 sec)

mysql> insert into mem1(b) values(1),(2),(3);
Query OK, 3 rows affected (0.01 sec)
Records: 3 Duplicates: 0 Warnings: 0

mysql> quit
Bye

[root@node1 mysql]# ls -alth .
total 237M
drwxr-xr-x 6 mysql mysql 4.0K Feb 11 06:02 .
-rw-rw---- 1 root root 0 Feb 11 06:02 GRA_11_-1.log
-rw-r----- 1 root root 26K Feb 11 06:02 node1.err
-rw-rw---- 1 root root 6.5K Feb 11 06:02 node1.log
-rw-rw---- 1 root root 104 Feb 11 06:02 grastate.dat
drwx------ 2 root root 4.0K Feb 11 06:02 memtables
-rw------- 1 root root 129M Feb 11 06:02 galera.cache
-rw-rw---- 1 root root 3.6K Feb 11 05:52 innobackup.backup.log
-rw-rw---- 1 mysql mysql 48M Feb 11 05:45 ib_logfile0
-rw-rw---- 1 mysql mysql 12M Feb 11 05:45 ibdata1
-rw-rw---- 1 root root 5 Feb 11 05:45 node1.pid
srwxrwxrwx 1 root root 0 Feb 11 05:45 mysql.sock
-rw-rw---- 1 mysql mysql 56 Feb 11 03:49 auto.cnf
-rw-r--r-- 1 root root 120 Feb 11 03:49 RPM_UPGRADE_HISTORY
-rw-r--r-- 1 mysql mysql 120 Feb 11 03:49 RPM_UPGRADE_MARKER-LAST
drwx------ 2 mysql mysql 4.0K Feb 11 03:49 mysql
drwx------ 2 mysql mysql 4.0K Feb 11 03:49 performance_schema
-rw-rw---- 1 mysql mysql 48M Feb 11 03:49 ib_logfile1
drwx------ 2 mysql mysql 4.0K Feb 11 03:49 test
drwxr-xr-x. 25 root root 4.0K Feb 11 03:49 ..

[root@node1 mysql]# uname -a
Linux node1 2.6.32-358.el6.x86_64 #1 SMP Fri Feb 22 00:31:26 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

[root@node1 mysql]# lsb_release -a
LSB Version: :base-4.0-amd64:base-4.0-noarch:core-4.0-amd64:core-4.0-noarch
Distributor ID: CentOS
Description: CentOS release 6.4 (Final)
Release: 6.4
Codename: Final

Paul Namuag (paul-namuag) wrote :

Verified that it creates an empty GRA_*.log files.

Changed in percona-xtradb-cluster:
status: New → Confirmed
Download full text (5.0 KiB)

With PXC56 release binary, I could reproduce it.

With codership-5.6 UNIV_DEBUG binary I got

mysqld: /media/Tintin/Work/code/codership/codership-5.6/sql/binlog.cc:1181: int binlog_cache_data::finalize(THD*, Log_event*): Assertion `!flags.finalized' failed.
09:09:18 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=4
max_threads=151
thread_count=4
connection_count=4
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68318 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2a392f0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f797c077e48 thread_stack 0x40000
/chip/bin/mysqld(my_print_stacktrace+0x2c)[0x936e5a]
/chip/bin/mysqld(handle_fatal_signal+0x2f7)[0x66da3f]
/usr/lib/libpthread.so.0(+0xf880)[0x7f79a928a880]
/usr/lib/libc.so.6(gsignal+0x39)[0x7f79a7822389]
/usr/lib/libc.so.6(abort+0x148)[0x7f79a7823788]
/usr/lib/libc.so.6(+0x2e4a6)[0x7f79a781b4a6]
/usr/lib/libc.so.6(+0x2e552)[0x7f79a781b552]
/chip/bin/mysqld(_ZN17binlog_cache_data8finalizeEP3THDP9Log_event+0xdd)[0x8ccb6d]
/chip/bin/mysqld(_ZN22binlog_stmt_cache_data8finalizeEP3THD+0x7a)[0x8ccd04]
/chip/bin/mysqld(_ZN13MYSQL_BIN_LOG6commitEP3THDb+0x385)[0x8dfce5]
/chip/bin/mysqld(_Z23wsrep_thd_binlog_commitP3THDb+0x4a)[0x8e035b]
/chip/bin/mysqld(_ZN12TC_LOG_DUMMY6commitEP3THDb+0xf)[0x65d68d]
/chip/bin/mysqld(_Z15ha_commit_transP3THDbb+0x4e5)[0x5a7dcf]
/chip/bin/mysqld(_Z17trans_commit_stmtP3THD+0x475)[0x79bde1]
/chip/bin/mysqld(_Z21mysql_execute_commandP3THD+0x76f1)[0x7007dd]
/chip/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x4e8)[0x701ddd]
/chip/bin/mysqld[0x702761]
/chip/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x132d)[0x704005]
/chip/bin/mysqld(_Z10do_commandP3THD+0x716)[0x7067a1]
/chip/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x143)[0x6c9738]
/chip/bin/mysqld(handle_one_connection+0x40)[0x6c98c3]
/chip/bin/mysqld(pfs_spawn_thread+0x14e)[0xc22de8]
/usr/lib/libpthread.so.0(+0x80a2)[0x7f79a92830a2]
/usr/lib/libc.so.6(clone+0x6d)[0x7f79a78d2d1d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f7930004fd0): is an invalid pointer
Connection ID (thread ID): 5
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.

Config used:
 [mysqld]
 socket = /chip/datadir/pxc.sock
 port = 40000
 basedir=/chip
 datadir=/chip/datadir

 binlog_format = ROW
 innodb_buffer_pool_size = 500M
 innodb_flush_log_at_tr...

Read more...

Can reproduce the same crash with UNIV_DEBUG binary of PXC:

mysqld-debug: /media/Tintin/Work/code/percona-xtradb-cluster/pxc56/Percona-Server/sql/binlog.cc:1187: int binlog_cache_data::finalize(THD*, Log_event*): Assertion `!flags.finalized' failed.
09:22:22 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona XtraDB Cluster better by reporting any
bugs at https://bugs.launchpad.net/percona-xtradb-cluster

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=4
max_threads=153
thread_count=4
connection_count=4
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 69229 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x3338c60
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 7f2bb4053e98 thread_stack 0x40000
/pxc56/bin/mysqld-debug(my_print_stacktrace+0x2c)[0x97c6dc]
/pxc56/bin/mysqld-debug(handle_fatal_signal+0x489)[0x6f4179]
/usr/lib/libpthread.so.0(+0xf880)[0x7f2be0c34880]
/usr/lib/libc.so.6(gsignal+0x39)[0x7f2bdefc4389]
/usr/lib/libc.so.6(abort+0x148)[0x7f2bdefc5788]
/usr/lib/libc.so.6(+0x2e4a6)[0x7f2bdefbd4a6]
/usr/lib/libc.so.6(+0x2e552)[0x7f2bdefbd552]
/pxc56/bin/mysqld-debug[0x91bd07]
/pxc56/bin/mysqld-debug(_ZN22binlog_stmt_cache_data8finalizeEP3THD+0x7e)[0x91bd8e]
/pxc56/bin/mysqld-debug(_ZN13MYSQL_BIN_LOG6commitEP3THDb+0x43f)[0x92aa4f]
/pxc56/bin/mysqld-debug(_Z15ha_commit_transP3THDbb+0x143)[0x64de53]
/pxc56/bin/mysqld-debug(_Z17trans_commit_stmtP3THD+0xb8)[0x8076d8]
/pxc56/bin/mysqld-debug(_Z21mysql_execute_commandP3THD+0x3268)[0x77cfa8]
/pxc56/bin/mysqld-debug(_Z11mysql_parseP3THDPcjP12Parser_state+0x6e8)[0x780f28]
/pxc56/bin/mysqld-debug[0x7815dc]
/pxc56/bin/mysqld-debug(_Z16dispatch_command19enum_server_commandP3THDPcj+0x15d9)[0x783059]
/pxc56/bin/mysqld-debug(_Z10do_commandP3THD+0x1b3)[0x7837f3]
/pxc56/bin/mysqld-debug(_Z24do_handle_one_connectionP3THD+0x142)[0x74e3a2]
/pxc56/bin/mysqld-debug(handle_one_connection+0x20)[0x74e4e0]
/pxc56/bin/mysqld-debug(pfs_spawn_thread+0x143)[0xbf5323]
/usr/lib/libpthread.so.0(+0x80a2)[0x7f2be0c2d0a2]
/usr/lib/libc.so.6(clone+0x6d)[0x7f2bdf074d1d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f2b50005020): is an invalid pointer
Connection ID (thread ID): 4
Status: NOT_KILLED

You may download the Percona XtraDB Cluster operations manual by visiting
http://www.percona.com/software/percona-xtradb-cluster/. You may find information
in the manual which will help you identify the cause of the crash.

With binlog disabled, it crashes as above in UNIV_DEBUG build, however, with it enabled, it doesn't crash nor does it leave any GRA files behind. (so that is also a workaround)

Download full text (3.3 KiB)

Demangled backtrace for codership-5.6 binary:

#0 0x00007ffff6166389 in raise () from /usr/lib/libc.so.6
#1 0x00007ffff6167788 in abort () from /usr/lib/libc.so.6
#2 0x00007ffff615f4a6 in __assert_fail_base () from /usr/lib/libc.so.6
#3 0x00007ffff615f552 in __assert_fail () from /usr/lib/libc.so.6
#4 0x00000000008ccb6d in binlog_cache_data::finalize (this=this@entry=0x7fff8000f720, thd=thd@entry=0x2438e20, end_event=end_event@entry=0x7fffcc1b6240)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/binlog.cc:1181
#5 0x00000000008ccd04 in binlog_stmt_cache_data::finalize (this=this@entry=0x7fff8000f720, thd=thd@entry=0x2438e20) at /media/Tintin/Work/code/codership/codership-5.6/sql/binlog.cc:601
#6 0x00000000008dfce5 in MYSQL_BIN_LOG::commit (this=this@entry=0x147bdc0 <mysql_bin_log>, thd=0x2438e20, all=<optimized out>) at /media/Tintin/Work/code/codership/codership-5.6/sql/binlog.cc:6287
#7 0x00000000008e035b in wsrep_thd_binlog_commit (thd=<optimized out>, all=<optimized out>) at /media/Tintin/Work/code/codership/codership-5.6/sql/binlog.cc:8985
#8 0x000000000065d68d in TC_LOG_DUMMY::commit (this=<optimized out>, thd=<optimized out>, all=<optimized out>) at /media/Tintin/Work/code/codership/codership-5.6/sql/log.h:124
#9 0x00000000005a7dcf in ha_commit_trans (thd=thd@entry=0x2438e20, all=all@entry=false, ignore_global_read_lock=ignore_global_read_lock@entry=false)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/handler.cc:1458
#10 0x000000000079bde1 in trans_commit_stmt (thd=thd@entry=0x2438e20) at /media/Tintin/Work/code/codership/codership-5.6/sql/transaction.cc:473
#11 0x00000000007007dd in mysql_execute_command (thd=thd@entry=0x2438e20) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:5405
#12 0x0000000000701ddd in mysql_parse (thd=thd@entry=0x2438e20, rawbuf=rawbuf@entry=0x7fff80005020 "insert into mem1(a) values (NULL)", length=length@entry=33, parser_state=parser_state@entry=0x7fffcc1b9610)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:6775
#13 0x0000000000702761 in wsrep_mysql_parse (thd=thd@entry=0x2438e20, rawbuf=0x7fff80005020 "insert into mem1(a) values (NULL)", length=33, parser_state=parser_state@entry=0x7fffcc1b9610)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:6555
#14 0x0000000000704005 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x2438e20, packet=packet@entry=0x2548491 "insert into mem1(a) values (NULL)", packet_length=packet_length@entry=33)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:1526
#15 0x00000000007067a1 in do_command (thd=0x2438e20) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:1118
#16 0x00000000006c9738 in do_handle_one_connection (thd_arg=thd_arg@entry=0x2438e20) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_connect.cc:1007
#17 0x00000000006c98c3 in handle_one_connection (arg=arg@entry=0x2438e20) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_connect.cc:916
#18 0x0000000000c22de8 in pfs_spawn_thread (arg=0x24c0390) at /media/Tintin/Work/code/codership/codership-5.6/storage/perfschema/pfs.cc:1858
#19 0x00007ffff7bc7...

Read more...

Full backtrace of the crash - 'bt full'

This (the crash) happens with MyISAM too as reported here https://groups.google.com/d/topic/codership-team/3GPGWt8UwhM

summary: Empty GRA_*_*.log file generated after closing a MySQL session that was
- used to insert rows on a MEMORY table
+ used to insert rows on a MEMORY/MyISAM with binlogging OFF.

To trigger this crash/issue: you need to do an insert to a non-innodb table followed by anything that touches binlog logic - ie. another insert to any table (an innodb), it will crash. This seems to be due to lack of cleanup in binlog_cache_data::reset() (called from thd_binlog_trx_reset):

#0 thd_binlog_trx_reset (thd=thd@entry=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/binlog.cc:8976
#1 0x00000000007b5566 in wsrep_cleanup_transaction (thd=thd@entry=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/wsrep_hton.cc:39
#2 0x00000000007b5da9 in wsrep_post_commit (thd=thd@entry=0x2444170, all=all@entry=false) at /media/Tintin/Work/code/codership/codership-5.6/sql/wsrep_hton.cc:110
#3 0x000000000079be15 in trans_commit_stmt (thd=thd@entry=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/transaction.cc:481
#4 0x00000000007007dd in mysql_execute_command (thd=thd@entry=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:5405
#5 0x0000000000701ddd in mysql_parse (thd=thd@entry=0x2444170, rawbuf=rawbuf@entry=0x7fff74005020 "insert into i1(a) values (NULL)", length=length@entry=31, parser_state=parser_state@entry=0x7fffcc1b9610)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:6775
#6 0x0000000000702761 in wsrep_mysql_parse (thd=thd@entry=0x2444170, rawbuf=0x7fff74005020 "insert into i1(a) values (NULL)", length=31, parser_state=parser_state@entry=0x7fffcc1b9610)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:6555
#7 0x0000000000704005 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x2444170, packet=packet@entry=0x2552f91 "insert into i1(a) values (NULL)", packet_length=packet_length@entry=31)
    at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:1526
#8 0x00000000007067a1 in do_command (thd=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_parse.cc:1118
#9 0x00000000006c9738 in do_handle_one_connection (thd_arg=thd_arg@entry=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_connect.cc:1007
#10 0x00000000006c98c3 in handle_one_connection (arg=arg@entry=0x2444170) at /media/Tintin/Work/code/codership/codership-5.6/sql/sql_connect.cc:916
#11 0x0000000000c22de8 in pfs_spawn_thread (arg=0x24cae90) at /media/Tintin/Work/code/codership/codership-5.6/storage/perfschema/pfs.cc:1858
#12 0x00007ffff7bc70a2 in start_thread () from /usr/lib/libpthread.so.0
#13 0x00007ffff6216d1d in clone () from /usr/lib/libc.so.6

(i1 is an innodb table).

This cleanup is not called for non-innodb - memory/myisam tables.

summary: - Empty GRA_*_*.log file generated after closing a MySQL session that was
- used to insert rows on a MEMORY/MyISAM with binlogging OFF.
+ Empty GRA_*_*.log file with MEMORY/MyISAM tables + binlogging OFF in
+ Release | Assertion failure binlog_cache_data::finalize(THD*,
+ Log_event*): Assertion `!flags.finalized' failed in UNIV_DEBUG build.
summary: - Empty GRA_*_*.log file with MEMORY/MyISAM tables + binlogging OFF in
- Release | Assertion failure binlog_cache_data::finalize(THD*,
+ MEMORY/MyISAM tables + binlogging OFF | Empty GRA_*_*.log file(s) with
+ Release build | Assertion failure binlog_cache_data::finalize(THD*,
Log_event*): Assertion `!flags.finalized' failed in UNIV_DEBUG build.
Seppo Jaakola (seppo-jaakola) wrote :

This problem happens when binlog is not enabled and there are statements for non InnoDB tables. Then, binlog events will be created for these statements, but they are never cleaned from transaction cache.

A simple fix is to prevent creating of binlog events for non-InnoDB tables. With this fix MEMORY tables will always remain node local.

Note that MyISAM replication (if wanted by wsrep_replicate_myisam), will still work through TOI replication, these binlog events would not be needed for that.

Seppo Jaakola (seppo-jaakola) wrote :

Merged the fix also to wsrep-5.5 in revision: http://bazaar.launchpad.net/~codership/codership-mysql/wsrep-5.5/revision/3949
Removed the debug message, which was too chatty, all temporary table access was reported

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

Other bug subscribers

Bug attachments