MySQL Bugs: #68835: MySQL cluster fails after fast insert/delete in table with blob field

Bug #68835	MySQL cluster fails after fast insert/delete in table with blob field
Submitted:	2 Apr 2013 13:49	Modified:	3 Apr 2013 11:14
Reporter:	Pavel Nekrasov	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Cluster: Cluster (NDB) storage engine	Severity:	S2 (Serious)
Version:	5.5.29	OS:	Linux (Ubuntu 10.04.4 LTS)
Assigned to:		CPU Architecture:	Any

Description:
Hello mysql team,

I'm using mysql cluster from debian package mysql-cluster-gpl-7.2.10-debian6.0-x86_64.deb with following topology:

[ndbd(NDB)]     2 node(s)
id=2    @10.0.0.131  (mysql-5.5.29 ndb-7.2.10, Nodegroup: 0, Master)
id=3    @10.0.0.132  (mysql-5.5.29 ndb-7.2.10, Nodegroup: 0)

[ndb_mgmd(MGM)] 1 node(s)
id=1    @10.0.0.130  (mysql-5.5.29 ndb-7.2.10)

[mysqld(API)]   3 node(s)
id=4    @10.0.0.131  (mysql-5.5.29 ndb-7.2.10)
id=5    @10.0.0.132  (mysql-5.5.29 ndb-7.2.10)
id=6 (not connected, accepting connect from any host)

I have a simple test table with two fields: Integer (PK) and Blob.

When I try to make a lot of INSERT/DELETE operations I usually get flollwing message in error log:

--------
09:54:12 UTC - mysqld got signal 11 ;
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=16777216
read_buffer_size=262144
max_used_connections=3
max_threads=350
thread_count=3
connection_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 289198 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x3c67160
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 = 7fc63cddee58 thread_stack 0x40000
/opt/mysql/server-5.5/bin/mysqld(my_print_stacktrace+0x35)[0x842f55]
/opt/mysql/server-5.5/bin/mysqld(handle_fatal_signal+0x4a4)[0x7119b4]
/lib/libpthread.so.0(+0xf8f0)[0x7fc63ca648f0]
/lib/libc.so.6(+0x83052)[0x7fc63b977052]
/opt/mysql/server-5.5/bin/mysqld[0x9f801b]
/opt/mysql/server-5.5/bin/mysqld(ndb_binlog_thread_func+0x222e)[0xa005ae]
/lib/libpthread.so.0(+0x69ca)[0x7fc63ca5b9ca]
/lib/libc.so.6(clone+0x6d)[0x7fc63b9da70d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0): is an invalid pointer
Connection ID (thread ID): 1
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.
--------

After this message both cluster nodes restarts.

How to repeat:
Following bash script can help you to reproduce this error:

#!/bin/bash
mysql test -e "DROP TABLE IF EXISTS test; CREATE TABLE test (id INT, BigData blob, PRIMARY KEY (id)) ENGINE=ndbcluster;"
for i in `seq 1 1000`; do
	echo "INSERT INTO test (id) VALUES ($i); DELETE FROM test WHERE id=$i;"
done | mysql test

Suggested fix:
1. Use UNIQUE KEY instead of PRIMARY KEY (but in this case I get another error in log: "logging of table XXX with BLOB attribute and no PK is not supported")
2. Do not use Blob at all

Hello Pavel Nekrasov,

Thank you for the report.
Verified as described on reported version(7.2.10) using the test case provided but this is not reproducible/fixed in current Generally Available Release: 7.2.12

Please could you try/confirm on 7.2.12?

## 7.2.10

Seems to be affected when binary logging is enabled...

08:28:21 UTC - mysqld got signal 11 ;
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=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 338531 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7ff09c001410
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 = 7ff095952d70 thread_stack 0x40000
/home/ushastry/mybuilds/mysql-cluster-7.2.10/bin/mysqld(my_print_stacktrace+0x35)[0x969e7d]
/home/ushastry/mybuilds/mysql-cluster-7.2.10/bin/mysqld(handle_fatal_signal+0x416)[0x7f2426]
/lib64/libpthread.so.0[0x328280f4c0]
/lib64/libc.so.6[0x3281c80022]
/home/ushastry/mybuilds/mysql-cluster-7.2.10/bin/mysqld[0xb9a479]
/home/ushastry/mybuilds/mysql-cluster-7.2.10/bin/mysqld(ndb_binlog_thread_func+0x22ab)[0xba3b26]
/lib64/libpthread.so.0[0x32828077e1]
/lib64/libc.so.6(clone+0x6d)[0x3281ce153d]

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

## resolved stack trace

0x969e7d my_print_stacktrace + 53
0x7f2426 handle_fatal_signal + 1046
0x328280f4c0 _end + -2128427752
0x3281c80022 _end + -2140548998
0xb9a479 ndbcluster_log_schema_op(THD*, char const*, int, char const*, char const*, unsigned int, unsigned int, SCHEMA_OP_TYPE, char const*, char const*) + 9137
0xba3b26 ndb_binlog_thread_func + 8875
0x32828077e1 _end + -2128459719
0x3281ce153d _end + -2140150379

## 7.2.12

Not affected..

Thanks,
Umesh

Hi , I have the same issue with mysql
mysql-5.6.17 ndb-7.3.5

ERROR

2014-09-06 11:01:10 48442 [Note] NDB Binlog: Node: 6, subscribe from node 202, Subscriber bitmask 00
14:05:43 UTC - mysqld got signal 11 ;
(NOTE 14:05:43 UTC == 2014-09-06 11:05:43)
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=1073741824
read_buffer_size=1048576
max_used_connections=25
max_threads=151
thread_count=23
connection_count=22
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1359893 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x483ce60
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 = 7fbd4c584e18 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x94d585]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x6d9944]
/lib64/libpthread.so.0[0x35b7a0f500]
/usr/sbin/mysqld(_ZN11Query_cache12unlink_tableEP23Query_cache_block_table+0x1b)[0x715bbb]
/usr/sbin/mysqld(_ZN11Query_cache19free_query_internalEP17Query_cache_block+0x82)[0x7164d2]
/usr/sbin/mysqld(_ZN11Query_cache27invalidate_query_block_listEP3THDP23Query_cache_block_table+0x88)[0x717298]
/usr/sbin/mysqld(_ZN11Query_cache12insert_tableEjPKcP23Query_cache_block_tablejhPFcP3THDPcjPyEy+0x91)[0x7183b1]
/usr/sbin/mysqld(_ZN11Query_cache25register_tables_from_listEP10TABLE_LISTjP23Query_cache_block_table+0x150)[0x718630]
/usr/sbin/mysqld(_ZN11Query_cache19register_all_tablesEP17Query_cache_blockP10TABLE_LISTj+0x15)[0x7187a5]
/usr/sbin/mysqld(_ZN11Query_cache11store_queryEP3THDP10TABLE_LIST+0x415)[0x718bc5]
/usr/sbin/mysqld(_Z11mysql_unionP3THDP3LEXP13select_resultP18st_select_lex_unitm+0x88)[0x7bf298]
/usr/sbin/mysqld(_Z13handle_selectP3THDP13select_resultm+0x9c)[0x77888c]
/usr/sbin/mysqld[0x75340d]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x21ce)[0x7569ee]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x32f)[0x75977f]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x140b)[0x75ac7b]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0xcf)[0x72797f]
/usr/sbin/mysqld(handle_one_connection+0x47)[0x727aa7]
/usr/sbin/mysqld(pfs_spawn_thread+0x12a)[0xc946ba]
/lib64/libpthread.so.0[0x35b7a07851]
/lib64/libc.so.6(clone+0x6d)[0x35b72e894d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fbc94004bb0): 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.
140906 11:05:43 mysqld_safe Number of processes running now: 0
140906 11:05:43 mysqld_safe mysqld restarted
2014-09-06 11:05:43 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2014-09-06 11:05:44 50004 [Note] Plugin 'FEDERATED' is disabled.
2014-09-06 11:05:44 50004 [Note] InnoDB: Using atomics to ref count buffer pool pages
2014-09-06 11:05:44 50004 [Note] InnoDB: The InnoDB memory heap is disabled
2014-09-06 11:05:44 50004 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2014-09-06 11:05:44 50004 [Note] InnoDB: Compressed tables use zlib 1.2.3
2014-09-06 11:05:44 50004 [Note] InnoDB: Using Linux native AIO
2014-09-06 11:05:44 50004 [Note] InnoDB: Using CPU crc32 instructions
2014-09-06 11:05:44 50004 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2014-09-06 11:05:44 50004 [Note] InnoDB: Completed initialization of buffer pool
2014-09-06 11:05:44 50004 [Note] InnoDB: Highest supported file format is Barracuda.
2014-09-06 11:05:44 50004 [Note] InnoDB: Log scan progressed past the checkpoint lsn 24725844
2014-09-06 11:05:44 50004 [Note] InnoDB: Database was not shutdown normally!
2014-09-06 11:05:44 50004 [Note] InnoDB: Starting crash recovery.
2014-09-06 11:05:44 50004 [Note] InnoDB: Reading tablespace information from the .ibd files...
2014-09-06 11:05:44 50004 [Note] InnoDB: Restoring possible half-written data pages
2014-09-06 11:05:44 50004 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 24764769
2014-09-06 11:05:44 50004 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
2014-09-06 11:05:44 50004 [Note] InnoDB: 128 rollback segment(s) are active.
2014-09-06 11:05:44 50004 [Note] InnoDB: Waiting for purge to start
2014-09-06 11:05:44 50004 [Note] InnoDB: 5.6.17 started; log sequence number 24764769
2014-09-06 11:05:45 50004 [Note] NDB: Changed global value of binlog_format from STATEMENT to MIXED
2014-09-06 11:05:45 50004 [Note] NDB: NodeID is 207, management server '10.76.255.130:1186'
2014-09-06 11:05:45 50004 [Note] NDB[0]: NodeID: 207, all storage nodes connected
2014-09-06 11:05:45 50004 [Note] Starting Cluster Binlog Thread

I have enable a binlog group on two of the nodes.

Additional Version info: '5.6.17-ndb-7.3.5-cluster-commercial-advanced'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Cluster Server - Advanced Edition (Commercial)

additional info:

mysql> show variables like '%max_co%';
+---------------------------------------+-------+
| Variable_name                         | Value |
+---------------------------------------+-------+
| max_connect_errors                    | 100   |
| max_connections                       | 151   |
| performance_schema_max_cond_classes   | 80    |
| performance_schema_max_cond_instances | 3504  |
+---------------------------------------+-------+
4 rows in set (0.01 sec)

mysql> show global status like '%connections%';
+-----------------------------------+-------+
| Variable_name                     | Value |
+-----------------------------------+-------+
| Connection_errors_max_connections | 0     |
| Connections                       | 3937  |
| Max_used_connections              | 25    |
+-----------------------------------+-------+
3 rows in set (0.00 sec)

mysql> show global status like '%tables%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_alter_tablespace    | 0     |
| Com_lock_tables         | 0     |
| Com_show_open_tables    | 0     |
| Com_show_tables         | 3     |
| Com_unlock_tables       | 0     |
| Created_tmp_disk_tables | 41    |
| Created_tmp_tables      | 3001  |
| Open_tables             | 274   |
| Opened_tables           | 341   |
| Slave_open_temp_tables  | 0     |
+-------------------------+-------+

-------------------

# Options for MySQL Cluster processes:
ndb-connectstring=10.76.255.130,10.76.255.134 # location of management server

[mysqld]
ndbcluster
bind-address=0.0.0.0

max_allowed_packet=32M
key_buffer_size=1G
myisam_sort_buffer_size=64M

sort_buffer_size=1M
read_buffer_size=1M
read_rnd_buffer_size=768K
#Query Cache
query_cache_limit=1M
query_cache_size=100M
query_cache_type=1
query_cache_min_res_unit=1024
bulk_insert_buffer_size=100M
tmp_table_size=500M
max_heap_table_size=500M

-------------------------
Additional info

	2014-09-08 14:02:36 6280 [Warning] Buffered warning: Changed limits: max_open_files: 1024 (requested 5000)
	2014-09-08 14:02:36 6280 [Warning] Buffered warning: Changed limits: table_cache: 431 (requested 2000)

This restart of mysqld with binlog on also occurs when applying an ndb backup with BLOB (or longtext). Also have replicated the problem in 7.3.6.

Apologies. I meant applying NDB backup to 7.2.10 version causes the restart of mysqld with binlog enabled when table has a BLOB column.

query cache must be disabled on cluster nodes because that is known to crash..
(internal bug report exists).