Bug #34392 mysql slave crashes when updating multiple tables in master by calling procedure
Submitted: 7 Feb 2008 19:40 Modified: 22 Mar 2008 18:03
Reporter: Vladimir Kukuruzovic Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: Row Based Replication ( RBR ) Severity:S1 (Critical)
Version:5.1.22 OS:Linux (Centos 5.1)
Assigned to: Assigned Account CPU Architecture:Any
Tags: innodb, replication, temporary tables

[7 Feb 2008 19:40] Vladimir Kukuruzovic
Description:
When calling stored procedure on master that updates multiple tables, slave crashes with signal 11. Table engines used: innodb, myisam and memory tables.

here is the info from the log on the slave:

080207 12:43:51 - 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=67108864
read_buffer_size=4190208
max_used_connections=3
max_threads=100
threads_connected=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1294850 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x20abc3c0
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...
Cannot determine thread, fp=0x450ac0e8, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
(nil)
New value of fp=0x20abc3c0 failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/refman/5.1/en/resolve-stack-dump.html
and follow instructions on how to resolve the stack trace.
Resolved stack trace is much more helpful in diagnosing the
problem, so please do resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at (nil)  is invalid pointer
thd->thread_id=7
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.
080207 12:43:51 mysqld_safe Number of processes running now: 0
080207 12:43:51 mysqld_safe mysqld restarted
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
080207 12:43:51  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Last MySQL binlog file position 0 169752, file name ./mysql-bin.000002
080207 12:43:52  InnoDB: Started; log sequence number 0 42326501
080207 12:43:52 [Note] Recovering after a crash using mysql-bin
080207 12:43:52 [Note] Starting crash recovery...
080207 12:43:52 [Note] Crash recovery finished.
080207 12:43:52 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and ha
s his hostname changed!! Please use '--relay-log=/usr/local/mysql-5.1.22/var/app1-relay-bin' to avoid this problem.
080207 12:43:52 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000001' at position 172624, relay log '/usr/local/mysql-5
.1.22/var/app1-relay-bin.000002' position: 3209
080207 12:43:52 - mysqld got signal 11;

and then the story repeats itself.

here is my.cnf
[client]
port            = 3388
socket          = /tmp/mysql.sock

[mysqld]
port            = 3388
socket          = /tmp/mysql.sock
back_log = 50
max_connections = 100
max_connect_errors = 10
table_cache = 2048
net_buffer_length = 2K
max_allowed_packet = 4M
binlog_cache_size = 512K
sort_buffer_size = 8M
join_buffer_size = 4M
thread_cache_size = 32
thread_concurrency = 8
query_cache_type = 2
query_cache_size = 16M
query_cache_limit = 512K
ft_min_word_len = 4
default_table_type = INNODB
thread_stack = 128K
transaction_isolation = READ-UNCOMMITTED
max_heap_table_size = 32M
tmp_table_size = 32M
log-bin=mysql-bin
log_slow_queries=/var/log/mysql/slow_queries_log
log_queries_not_using_indexes=1
log_output=file
long_query_time = 2
log_long_format
skip_external_locking
low_priority_updates=0
event_scheduler=ON
max_seeks_for_key=100
optimizer_prune_level=1
optimizer_search_depth=1
max_sp_recursion_depth=3
log=/var/log/mysql/full_log
log_error=/var/log/mysql/error_log
binlog-format=row
sync-binlog=1
server-id = 7
replicate-wild-ignore-table = mydatabase.tt%
replicate-ignore-table = mydatabase.memSPstats
concurrent_insert=2
key_buffer_size = 64M
read_buffer_size = 4M
read_rnd_buffer_size = 16M
bulk_insert_buffer_size = 4M
myisam_sort_buffer_size = 128M
myisam_max_sort_file_size = 10G
myisam_max_extra_sort_file_size = 10G
myisam_repair_threads = 3
myisam_recover
innodb_file_per_table
innodb_max_purge_lag = 10000
expire_logs_days = 5
innodb_additional_mem_pool_size = 8M
innodb_buffer_pool_size = 2600M
innodb_autoextend_increment = 30M
innodb_file_io_threads = 6
innodb_thread_concurrency = 8
innodb_flush_log_at_trx_commit = 0
innodb_log_buffer_size = 8M
innodb_log_files_in_group = 4
innodb_max_dirty_pages_pct = 85
innodb_flush_method=O_DIRECT
innodb_lock_wait_timeout = 3
init-file=/etc/mysqld_init.sql
init_connect = 'call mydatabase.Up_SessInit_Connect(0);'

[mysqldump]
quick
max_allowed_packet = 16M

[mysql]
no-auto-rehash

[isamchk]
key_buffer = 512M
sort_buffer_size = 512M
read_buffer = 80M
write_buffer = 80M

[myisamchk]
key_buffer = 512M
sort_buffer_size = 512M
read_buffer = 80M
write_buffer = 80M

[mysqlhotcopy]
interactive-timeout

[mysqld_safe]
open-files-limit = 4096

How to repeat:
call the procedure that updates multiple tables, and tables which are in ignore list.
[8 Feb 2008 3:22] Vladimir Kukuruzovic
while trying to make a simple test case, I bumped to more crashes. Here is the procedure to update the tables:

DELIMITER $$

DROP PROCEDURE IF EXISTS `rbr_test`.`p_rbr_writetoalltables`$$

CREATE DEFINER=`deweyg`@`%` PROCEDURE `p_rbr_writetoalltables`()
    MODIFIES SQL DATA
    COMMENT 'writes to all tables when called by event scheduler'
BEGIN
Declare vNow Datetime Default Now();
Declare vChar Char(30) Default 'my name is sally';
Declare vVarChar VarChar(100) Default 'Who wants some of this';
Declare vText Text Default 'now is the time for all good men to come to the aid of their country';

Drop TEMPORARY TABLE IF EXISTS `rbr_test`.`ttLabelValue`;
CREATE TEMPORARY TABLE `rbr_test`.`ttLabelValue` (
        `ttlabel` CHAR(30),
        `ttvalue` CHAR(255)  )
        ENGINE = MEMORY;

Drop view if exists v3, v;
create view v3 as select 1 n union all select 1 union all select 1;
create view v as select 1 n from v3 a, v3 b union all select 1;
set @n = 0;
insert ttLabelValue select (now()-interval @n:=@n+1 second) lab, @N Val from v a,v b,v c, v d;  -- ,v e,v

-- Truncate Table rbr_test.memorytest;

insert into rbr_test.memorytest 
 ( MEM_DTTM, MEM_CHAR, MEM_VARCHAR) Select 
 vNow, vChar, vVarChar from ttLabelValue Limit 500;

insert into rbr_test.myisamtest
 (MYI_DTTM, MYI_CHAR, MYI_VARCHAR, MYI_TEXT) values
 (vNow, vChar, vVarChar, vText);
insert into rbr_test.innodbtest 
 (IDB_DTTM, IDB_CHAR, IDB_VARCHAR, IDB_TEXT) Select 
 vNow, ttlabel, ttvalue, vText from ttLabelValue Limit 10000;

/* code for the even which calls this proc every 1 minute is:
-- DELIMITER $$
Create EVENT WriteTablesEachMin
ON SCHEDULE EVERY 1 MINUTE
ON COMPLETION PRESERVE
DO 
Begin
call rbr_test.p_rbr_writetoalltables();
END$$
-- DELIMITER ;
*/
END$$

DELIMITER ;

when calling that procedure, mysql server dies(!) 

mysql> call p_rbr_writetoalltables();
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>
[8 Feb 2008 7:45] Sveta Smirnova
Thank you for the report.

Please provide output of SHOW CREATE TABLE for tables memorytest, myisamtest and innodbtest.
[8 Feb 2008 14:30] Dewey Gaedcke
entire db dump

Attachment: rbrtest_080207.sql (application/octet-stream, text), 3.08 KiB.

[8 Feb 2008 19:01] Dewey Gaedcke
this crash is ONLY reproducible on the 64 bit version of mysql.  We are running 5.1.22-rc-log (32 bit) and the same db and sp DO NOT cause a crash.   Also, we're not certain that this crash of the master is related to our crash of the slave but  we do believe that BOTH are related to the temp, memory tables we're using.

The crash (of the Master) only began to occur after we added the temp, memory table to the stored proc (sp).
[11 Feb 2008 7:33] Dewey Gaedcke
would someone at MySQL verify that the "exclude list" (tables NOT TO replicate) works properly with TEMPORARY (session local) memory tables.

I have a VERY STRONG hunch that since temp table names are NOT unique WITHIN the replication thread name space, that they are not being handled correctly in the "exclude" list.  In other words, if a temporary table is called "ttLabel" in both Session 1, and Session 2, but are clearly different tables, then MySQL must be using an internal file pointer (some type of alias) to refer to the tables.  Therefore, putting "ttLabel" in the exclude list is ambiguous and replication-thread-writes (on the slave) are trying on non-existent tables and failing (thereby causing a crash??)

that's my theory---please advise as this is urgent for us
[18 Feb 2008 18:48] Baron Schwartz
I wonder whether you can eliminate temp tables to narrow down the problem.  Is the temp table ever used outside the stored procedure (and so is the omission of DROP TEMPORARY TABLE deliberate so the event can use the temp table further)?  Does the crash happen if you use a non-temporary table with a unique name?

You could build the temp table as a non-temp table with a unique name like this:

set @name := replace(uuid(), '-', '');
set @sql := concat('create table test.ttLabelValue', @name, '(.....)engine=memory');
prepare stmt from @sql;

And so on.  I know it's tedious, but it might help narrow down the options.

Even though UUID() isn't "safe" for replication, it ought to work here, as long as you don't use the temp table outside the procedure.
[21 Feb 2008 21:25] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior in my environment.

Please indicate accurate name of package you are using and provide master configuration file.
[21 Feb 2008 21:58] Dewey Gaedcke
We've gotten farther---the slave now hangs on:
Error 'Table 'minggl.ttLabelValue' doesn't exist' on query. Default
database: 'minggl'. Query: 'Truncate TABLE ttLabelValue'

minggl.ttLabelValue is a temp memory table.  The query involving it managed to make it to the slave even though temps are NOT supposed to replicate under RBR.

we have reduced my.cnf to as close to default as possible and have also setup the slave to skip over errors if type 1146 (Error: 1146
SQLSTATE: 42S02 (ER_NO_SUCH_TABLE)).
[21 Feb 2008 22:07] Vladimir Kukuruzovic
my.cnf on master is still the same as in one of previous comments:

client]
port            = 3388
socket          = /tmp/mysql.sock

[mysqld]
port            = 3388
socket          = /tmp/mysql.sock
back_log = 50
max_connections = 100
max_connect_errors = 10
table_cache = 2048
net_buffer_length = 2K
max_allowed_packet = 4M
binlog_cache_size = 512K
sort_buffer_size = 8M
join_buffer_size = 4M
thread_cache_size = 32
thread_concurrency = 8
query_cache_type = 2
query_cache_size = 16M
query_cache_limit = 512K
ft_min_word_len = 4
default_table_type = INNODB
thread_stack = 128K
transaction_isolation = READ-UNCOMMITTED
max_heap_table_size = 32M
tmp_table_size = 32M
log-bin=mysql-bin
log_slow_queries=/var/log/mysql/slow_queries_log
log_queries_not_using_indexes=1
log_output=file
long_query_time = 2
log_long_format
skip_external_locking
low_priority_updates=0
event_scheduler=ON
max_seeks_for_key=100
optimizer_prune_level=1
optimizer_search_depth=1
max_sp_recursion_depth=3
log=/var/log/mysql/full_log
log_error=/var/log/mysql/error_log
binlog-format=row
sync-binlog=1
server-id = 7
replicate-wild-ignore-table = mydatabase.tt%
replicate-ignore-table = mydatabase.memSPstats
concurrent_insert=2
key_buffer_size = 64M
read_buffer_size = 4M
read_rnd_buffer_size = 16M
bulk_insert_buffer_size = 4M
myisam_sort_buffer_size = 128M
myisam_max_sort_file_size = 10G
myisam_max_extra_sort_file_size = 10G
myisam_repair_threads = 3
myisam_recover
innodb_file_per_table
innodb_max_purge_lag = 10000
expire_logs_days = 5
innodb_additional_mem_pool_size = 8M
innodb_buffer_pool_size = 2600M
innodb_autoextend_increment = 30M
innodb_file_io_threads = 6
innodb_thread_concurrency = 8
innodb_flush_log_at_trx_commit = 0
innodb_log_buffer_size = 8M
innodb_log_files_in_group = 4
innodb_max_dirty_pages_pct = 85
innodb_flush_method=O_DIRECT
innodb_lock_wait_timeout = 3
init-file=/etc/mysqld_init.sql
init_connect = 'call mydatabase.Up_SessInit_Connect(0);'

[mysqldump]
quick
max_allowed_packet = 16M

[mysql]
no-auto-rehash

[isamchk]
key_buffer = 512M
sort_buffer_size = 512M
read_buffer = 80M
write_buffer = 80M

[myisamchk]
key_buffer = 512M
sort_buffer_size = 512M
read_buffer = 80M
write_buffer = 80M

[mysqlhotcopy]
interactive-timeout

[mysqld_safe]
open-files-limit = 4096
[21 Feb 2008 22:16] Vladimir Kukuruzovic
package is mysql-5.1.22-rc (source)
compiled with 
./configure --prefix=/usr/local/mysql-5.1.22 --with-unix-socket-path=/var/lib/mysql/mysql.sock --with-plugins=innobase
[22 Feb 2008 18:03] Sveta Smirnova
Thank you for the feedback.

I still can not repeat described behavior.

Please try current version 5.1.23 and if problem still exists indicate how much physical RAM slave has and if >1,2G try to build debug version and get core file.
[23 Mar 2008 0:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".