Bug #49020 Semi-sync master crashed with free_pool == NULL, assertion `free_pool_'
Submitted: 24 Nov 2009 3:51 Modified: 13 Feb 2010 3:04
Reporter: Elena Stepanova Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Replication Severity:S1 (Critical)
Version:5.5.0 OS:Any
Assigned to: Zhenxing He CPU Architecture:Any

[24 Nov 2009 3:51] Elena Stepanova
Description:
091124  1:02:27 [ERROR] You have encountered a semi-sync bug (free_pool == NULL), please report to http://bugs.mysql.com
mysqld: semisync_master.cc:162: ActiveTranx::TranxNode* ActiveTranx::alloc_tranx_node(): Assertion `free_pool_' failed.
091124  1:02:27 - 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=1048576
read_buffer_size=131072
max_used_connections=65
max_threads=120
threads_connected=65
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 48338 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x2712a40
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 = 0x467c5190 thread_stack 0x40000
/export/home/tmp/qauser/bin64_550/bin/mysqld(my_print_stacktrace+0x2e)[0x8b78fe]
/export/home/tmp/qauser/bin64_550/bin/mysqld(handle_segfault+0x322)[0x5cab22]
/lib64/libpthread.so.0[0x2b93c3617c00]
/lib64/libc.so.6(gsignal+0x35)[0x2b93c3bfbbb5]
/lib64/libc.so.6(abort+0x110)[0x2b93c3bfcfb0]
/lib64/libc.so.6(__assert_fail+0xf6)[0x2b93c3bf5286]
/export/home/tmp/qauser/bin64_550/lib/plugin/libsemisync_master.so[0x2aaabbe69ba4]
/export/home/tmp/qauser/bin64_550/lib/plugin/libsemisync_master.so(_ZN18ReplSemiSyncMaster18writeTranxInBinlogEPKcy+0xa8)[0x2aaabbe69c58]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_ZN23Binlog_storage_delegate11after_flushEP3THDPKcyb+0xcd)[0x75681d]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_ZN13MYSQL_BIN_LOG5writeEP9Log_event+0x42b)[0x66f59b]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_ZN3THD12binlog_queryENS_22enum_binlog_query_typeEPKcmbbi+0xd1)[0x5b8db1]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_ZN13select_insert8send_eofEv+0xe9)[0x649ca9]
/export/home/tmp/qauser/bin64_550/bin/mysqld[0x62f30b]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_ZN4JOIN4execEv+0x96f)[0x645daf]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_sel
ect_lex+0x12a)[0x641dba]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x174)[0x647814]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_Z21mysql_execute_commandP3THD+0x5478)[0x5e0658]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x376)[0x5e1056]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x100e)[0x5e206e]
/export/home/tmp/qauser/bin64_550/bin/mysqld(_Z10do_commandP3THD+0xe3)[0x5e2893]
/export/home/tmp/qauser/bin64_550/bin/mysqld(handle_one_connection+0x23e)[0x5d4bee]
/lib64/libpthread.so.0[0x2b93c3610143]
/lib64/libc.so.6(__clone+0x6d)[0x2b93c3c8c8cd]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x271d3a0 = INSERT INTO systest1.t1_tmp (f1, f2 ,f3, f4)
SELECT f1, f2, f3, f4 FROM systest1.tb1_eng1
WHERE i1 = ( SELECT i1 FROM systest1.tb1_eng1
ORDER BY i1 LIMIT 1 OFFSET 56 )
thd->thread_id=66886
thd->killed=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.

(gdb) bt
#0  0x00002b93c3614ea3 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000005cab55 in handle_segfault (sig=6) at mysqld.cc:2576
#2  <signal handler called>
#3  0x00002b93c3bfbbb5 in raise () from /lib64/libc.so.6
#4  0x00002b93c3bfcfb0 in abort () from /lib64/libc.so.6
#5  0x00002b93c3bf5286 in __assert_fail () from /lib64/libc.so.6
#6  0x00002aaabbe69ba4 in ActiveTranx::insert_tranx_node (this=0x1913af0, log_file_name=0x20edd78 "master-bin.000016", log_file_pos=2397537) at semisync_master.cc:162
#7  0x00002aaabbe69c58 in ReplSemiSyncMaster::writeTranxInBinlog (this=0x2aaabbf6c940, log_file_name=0x20edd78 "master-bin.000016", log_file_pos=2397537)
    at semisync_master.cc:1111
#8  0x000000000075681d in Binlog_storage_delegate::after_flush (this=0xd06e20, thd=0x2712a40, log_file=<value optimized out>, log_pos=<value optimized out>,
    synced=<value optimized out>) at rpl_handler.cc:245
#9  0x000000000066f59b in MYSQL_BIN_LOG::write (this=0xcffc00, event_info=0x467c2f20) at log.cc:4205
#10 0x00000000005b8db1 in THD::binlog_query (this=0x2712a40, qtype=<value optimized out>,
    query_arg=0x271d3a0 "INSERT INTO systest1.t1_tmp (f1, f2 ,f3, f4)\nSELECT f1, f2, f3, f4 FROM systest1.tb1_eng1 \nWHERE i1 = ( SELECT i1 FROM systest1.tb1_eng1 \nORDER BY i1 LIMIT 1 OFFSET 56 )", query_len=169, is_trans=false, suppress_use=false, errcode=0) at sql_class.cc:3970
#11 0x0000000000649ca9 in select_insert::send_eof (this=0x239f1c8) at sql_insert.cc:3277
#12 0x000000000062f30b in do_select (join=0x239f268, fields=0x2714710, table=0x0, procedure=<value optimized out>) at sql_select.cc:11146
#13 0x0000000000645daf in JOIN::exec (this=0x239f268) at sql_select.cc:2270
#14 0x0000000000641dba in mysql_select (thd=0x2712a40, rref_pointer_array=<value optimized out>, tables=<value optimized out>, wild_num=0,
    fields=<value optimized out>, conds=<value optimized out>, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=0, result=0x239f1c8,
    unit=0x27141e0, select_lex=0x2714608) at sql_select.cc:2459
#15 0x0000000000647814 in handle_select (thd=0x2712a40, lex=0x2714140, result=0x239f1c8, setup_tables_done_option=1073741824) at sql_select.cc:272
#16 0x00000000005e0658 in mysql_execute_command (thd=0x2712a40) at sql_parse.cc:3366
#17 0x00000000005e1056 in mysql_parse (thd=0x2712a40,
    inBuf=0x271d3a0 "INSERT INTO systest1.t1_tmp (f1, f2 ,f3, f4)\nSELECT f1, f2, f3, f4 FROM systest1.tb1_eng1 \nWHERE i1 = ( SELECT i1 FROM systest1.tb1_eng1 \nORDER BY i1 LIMIT 1 OFFSET 56 )", length=169, found_semicolon=0x467c50f0) at sql_parse.cc:6211
#18 0x00000000005e206e in dispatch_command (command=COM_QUERY, thd=0x2712a40,
    packet=0x2715371 "INSERT INTO systest1.t1_tmp (f1, f2 ,f3, f4)\nSELECT f1, f2, f3, f4 FROM systest1.tb1_eng1 \nWHERE i1 = ( SELECT i1 FROM systest1.tb1_eng1 \nORDER BY i1 LIMIT 1 OFFSET 56 )", packet_length=<value optimized out>) at sql_parse.cc:1240
#19 0x00000000005e2893 in do_command (thd=0x2712a40) at sql_parse.cc:873
#20 0x00000000005d4bee in handle_one_connection (arg=<value optimized out>) at sql_connect.cc:1154
#21 0x00002b93c3610143 in start_thread () from /lib64/libpthread.so.0
#22 0x00002b93c3c8c8cd in clone () from /lib64/libc.so.6
#23 0x0000000000000000 in ?? ()

How to repeat:
No repeatable test case yet
[24 Nov 2009 8:32] Elena Stepanova
# Test case:

# rpl_semisync.test
# run as
# perl ./mysql-test-run.pl --mysqld=--binlog_format=row --mysqld=--max_connections=23 rpl_semisync

source include/have_binlog_format_row.inc;
source include/master-slave.inc;
source include/have_innodb.inc;

connection slave;

INSTALL PLUGIN rpl_semi_sync_slave SONAME 'libsemisync_slave.so';
SET GLOBAL rpl_semi_sync_slave_enabled = 1;

connection master;
SET GLOBAL event_scheduler = ON;
INSTALL PLUGIN rpl_semi_sync_master SONAME 'libsemisync_master.so';
SET GLOBAL rpl_semi_sync_master_enabled = 1;

connection slave;
STOP SLAVE;
START SLAVE;

connection master;

CREATE TABLE t ( i INT NOT NULL AUTO_INCREMENT PRIMARY KEY, f varchar(8) ) ENGINE = InnoDB;
INSERT INTO t (f) VALUES ('a'),('a'),('a'),('a'),('a');
INSERT INTO t SELECT i+5, f FROM t;
INSERT INTO t SELECT i+10, f FROM t;

CREATE EVENT ev1 ON SCHEDULE EVERY 1 SECOND
DO INSERT INTO t VALUES (SLEEP(5),CONCAT('ev1_',CONNECTION_ID()));
CREATE EVENT ev2 ON SCHEDULE EVERY 1 SECOND
DO INSERT INTO t VALUES (SLEEP(5),CONCAT('ev2_',CONNECTION_ID()));

connection slave;
STOP SLAVE IO_THREAD;

connection master;
sleep 4;
let $run = 20;
while ($run)
{
        connect (m$run,localhost,root,,);
        connection m$run;
        send;
        eval UPDATE t SET f = CONCAT('up_',CONNECTION_ID()) WHERE i = $run;
        connection master;
        dec $run;
}
sleep 3;
[28 Nov 2009 14:46] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/91996

3123 He Zhenxing	2009-11-28
      Bug#49020 Semi-sync master crashed with free_pool == NULL, assertion `free_pool_'
      
      Before this patch, semisync assumed transactions running in parallel
      can not be larger than max_connections, but this is not true when
      the event scheduler is executing events, and cause semisync run out
      of preallocated transaction nodes.
      
      Fix the problem by allocating transaction nodes dynamically.
      
      This patch also fixed a possible deadlock when running UNINSTALL
      PLUGIN rpl_semi_sync_master and updating in parallel. Fixed by
      releasing the internal Delegate lock before unlock the plugins.
     @ plugin/semisync/semisync_master.cc
        Allocating TranxNode dynamically
     @ plugin/semisync/semisync_master.h
        Allocating TranxNode dynamically
     @ sql/rpl_handler.cc
        Unlock plugins after we have released the Delegate lock to avoid possible deadlock when uninstalling semisync master plugin and doing update in parallel.
[28 Nov 2009 14:48] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/91997

3123 He Zhenxing	2009-11-28
      Bug#49020 Semi-sync master crashed with free_pool == NULL, assertion `free_pool_'
      
      Before this patch, semisync assumed transactions running in parallel
      can not be larger than max_connections, but this is not true when
      the event scheduler is executing events, and cause semisync run out
      of preallocated transaction nodes.
      
      Fix the problem by allocating transaction nodes dynamically.
      
      This patch also fixed a possible deadlock when running UNINSTALL
      PLUGIN rpl_semi_sync_master and updating in parallel. Fixed by
      releasing the internal Delegate lock before unlock the plugins.
     @ mysql-test/suite/rpl/t/rpl_semi_sync_event.test
        Add test case for bug#49020
     @ plugin/semisync/semisync_master.cc
        Allocating TranxNode dynamically
     @ plugin/semisync/semisync_master.h
        Allocating TranxNode dynamically
     @ sql/rpl_handler.cc
        Unlock plugins after we have released the Delegate lock to avoid possible deadlock when uninstalling semisync master plugin and doing update in parallel.
[4 Dec 2009 1:47] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92806

3123 He Zhenxing	2009-12-04
      Bug#49020 Semi-sync master crashed with free_pool == NULL, assertion `free_pool_'
      
      Before this patch, semisync assumed transactions running in parallel
      can not be larger than max_connections, but this is not true when
      the event scheduler is executing events, and cause semisync run out
      of preallocated transaction nodes.
      
      Fix the problem by allocating transaction nodes dynamically.
      
      This patch also fixed a possible deadlock when running UNINSTALL
      PLUGIN rpl_semi_sync_master and updating in parallel. Fixed by
      releasing the internal Delegate lock before unlock the plugins.
     @ mysql-test/suite/rpl/t/rpl_semi_sync_event.test
        Add test case for bug#49020
     @ plugin/semisync/semisync_master.cc
        Allocating TranxNode dynamically
     @ plugin/semisync/semisync_master.h
        Allocating TranxNode dynamically
     @ sql/rpl_handler.cc
        Unlock plugins after we have released the Delegate lock to avoid possible deadlock when uninstalling semisync master plugin and doing update in parallel.
[4 Dec 2009 2:04] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92809

3124 He Zhenxing	2009-12-04 [merge]
      Auto merge fix for Bug#49020
[4 Dec 2009 5:25] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92816

3124 He Zhenxing	2009-12-04
      Post fix for previous patch of Bug#49020
      
      Added back n_frees, use 'clear' instead of 'free' since memory is
      not freed here.
     @ plugin/semisync/semisync_master.cc
        Added back n_frees, use 'clear' instead of 'free' in the message since memory is not freed here.
[4 Dec 2009 5:29] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92818

3126 He Zhenxing	2009-12-04 [merge]
      Auto merge postfix of Bug#49020
[4 Dec 2009 5:44] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92819

3124 He Zhenxing	2009-12-04
      Post fix for previous patch of Bug#49020
      
      Added back n_frees, use 'clear' instead of 'free' since memory is
      not freed here.
     @ plugin/semisync/semisync_master.cc
        Added back n_frees, use 'clear' instead of 'free' in the message since memory is not freed here.
[4 Dec 2009 5:46] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92820

3126 He Zhenxing	2009-12-04 [merge]
      Auto merge postfix of Bug#49020
[4 Dec 2009 8:06] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92832

2911 He Zhenxing	2009-12-04 [merge]
      Auto merge fixes for Bug#49020
[4 Dec 2009 9:54] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92845

2912 He Zhenxing	2009-12-04
      Postfix after merge patch for Bug#49020
     @ plugin/semisync/CMakeLists.txt
        Add mysqlservices to link libraries
     @ plugin/semisync/Makefile.am
        Add mysqlservices to link libraries
[4 Dec 2009 9:57] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/92846

3753 He Zhenxing	2009-12-04 [merge]
      Merge patch for Bug#49020, resolved conflicts on plugin/semisync
[11 Dec 2009 6:02] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20091211055901-yp18b3c7xuhl87rf) (version source revid:alik@sun.com-20091211055401-43rjwq7gjed6ds83) (merge vers: 6.0.14-alpha) (pib:13)
[11 Dec 2009 6:03] Bugs System
Pushed into 5.5.0-beta (revid:alik@sun.com-20091211055436-aagpwm5ac26waw4b) (version source revid:alik@sun.com-20091211055436-aagpwm5ac26waw4b) (merge vers: 5.5.0-beta) (pib:13)
[11 Dec 2009 6:05] Bugs System
Pushed into 5.6.0-beta (revid:alik@sun.com-20091211055628-ltr7fero363uev7r) (version source revid:alik@sun.com-20091211055453-717czhtezc74u8db) (merge vers: 5.6.0-beta) (pib:13)
[16 Dec 2009 2:44] Paul Dubois
Noted in 5.5.0, 6.0.14 changelogs.

Semisynchronous replication could run out of nodes to execute 
simultaneous transactions if the Event Scheduler was executing
events.
[18 Dec 2009 15:43] Paul Dubois
Removed 5.5.0 changelog entry. In 5.5, semisync replication first appears in 5.5.0, so this bug affects no 5.5.x releases.
[12 Feb 2010 17:41] Bugs System
Pushed into 5.5.2-m2 (revid:joerg@mysql.com-20100212164100-jnurxdw5z88m472s) (version source revid:joerg@mysql.com-20100212164100-jnurxdw5z88m472s) (merge vers: 5.5.2-m2) (pib:16)