MySQL Bugs: #42419: Server crash with "Pure virtual method called" on two concurrent connections

Bug #42419	Server crash with "Pure virtual method called" on two concurrent connections
Submitted:	28 Jan 2009 13:15	Modified:	18 Mar 2009 14:57
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server	Severity:	S1 (Critical)
Version:	4.1.24, 5.0.42, 5.0.74, 5.0.76, 5.0.77, 5.1.31	OS:	Any
Assigned to:	Georgi Kodinov	CPU Architecture:	Any
Tags:	crash, subquery, UPDATE

Description:
master.err:

Version: '5.0.77-debug-log'  socket: '/export/home/pb2/test/sb_1-238032-1233026623.49/tmp/6Wn5u27jt3/master.sock'  port: 10670  Source distribution
Assertion failed: "Pure virtual method called." == "Aborted", file my_new.cc, line 50
090127  6:41:35 - 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=52
max_connections=120
threads_connected=50
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 47104 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Writing a core file

pstack fragment:

-----------------  lwp# 1110 / thread# 1110  --------------------
 ff045bf0 _lwp_kill (6, 6c29c0, 457a4, ff01c35c, ff072e50, 8cb3d0) + 8
 001a9bec handle_segfault (6, 0, fe3ad610, ff074784, 1bc3000, 755d48) + 330
 ff044b28 __sighndlr (6, 0, fe3ad610, 1a98bc, 0, 0) + c
 ff039b00 call_user_handler (6, 0, 12, 0, fef4ca00, fe3ad610) + 3b8
 ff045bf0 _lwp_kill (6, 6, 5, 6, 345ac, 0) + 8
 fefc10b8 abort    (fe3ad988, ff076f68, ff06f30c, ad314, ff06e308, ff0777b4) + d0
 fefc1334 _assert  (755dc8, 755df8, 32, 8, ad030, 79dcd8) + 64
 0054fd9c __cxa_pure_virtual (1cacf10, 1e59fc8, fe3ade7c, 8, fe3ade7c, fef4cb00) + 34
 000d9b9c Item::eq(const Item*, bool) const (1cacf10, 274fc38, 1, 8, 0, fef4cb00) + 28
 0024ea0c ???????? (274fcd8, 274fc38, fe3ade38, fe3ade34, 40000000, 1)
 0024f43c ???????? (274fd68, c0000000, 1, c0000000, 1, 0)
 0024f9d0 ???????? (22d1008, 22d1fe8, 274fd68, 0, 0, 0)
 0025e868 JOIN::optimize() (22d1008, 274f5b0, 6fc, fe3ae3cc, fe3ae3c8, fe3ae3c4) + 153c
 00160b98 subselect_single_select_engine::exec() (274ff00, 0, 4, 8, 0, fef4cb00) + fc
 00159938 Item_subselect::exec() (274fe60, 1e0ff44, fe3ae7ec, fe3ae7e8, 0, 316ea8) + 58
 0015addc Item_singlerow_subselect::val_int() (274fe60, 1e0ff44, fe3ae88c, fe3ae888, 0, fe3ae888) + 58
 000e2458 Item::save_in_field(Field*, bool) (274fe60, 1e59fc8, 0, fe3ae928, fe3ae924, fe3ae920) + 3fc
 0021cb80 ???????? (1e0edf0, 1e0fd70, 1e0ff44, 0, 0, fe3aec00)
 0021cd2c fill_record_n_invoke_before_triggers(THD*, List<Item>&, List<Item>&, bool, Table_triggers_list*, trg_event_type) (1e0edf0, 1e0fd70, 1e0ff44, 0, 0, 1) + 38
 00282170 mysql_update(THD*, TABLE_LIST*, List<Item>&, List<Item>&, Item*, unsigned, st_order*, unsigned long long, enum_duplicates, bool) (1e0edf0, 274f370, 1e0fd70, 1e0ff44, 2750a68, 0) + 1954
 001d4950 mysql_execute_command(THD*) (1e0edf0, 1e0edf0, 274f1e8, ed, fe3af818, fe3af814) + 365c
 001db71c mysql_parse(THD*, const char*, unsigned, const char**) (1e0edf0, 274f1e8, ed, fe3afd78, ed, 274f1e8) + 30c
 001dc3b8 dispatch_command(enum_server_command, THD*, char*, unsigned) (3, 1e0edf0, 29702e1, ee, fe3afea0, 3) + ab4
 001ddea0 ???????? (1e0edf0, 3c, 0, fef4ca00, 0, 0)
 001de4ec handle_one_connection (1e0edf0, fe3b0000, 0, 0, 1ddfb0, 1) + 53c
 ff0449fc _lwp_start (0, 0, 0, 0, 0, 0)

Full pstack is attached.

dbx:

t@1110 (l@1110) terminated by signal ABRT (Abort)
0xff045bf0: __lwp_kill+0x0008:  bcc,a,pt  %icc,__lwp_kill+0x18  ! 0xff045c00
(dbx) where
current thread: t@1110
=>[1] __lwp_kill(0x0, 0x6, 0xff073700, 0xfef4ca00, 0xff072e58, 0x6), at 0xff045bf0
  [2] write_core(0x6, 0x6c29c0, 0x457a4, 0xff01c35c, 0xff072e50, 0x8cb3d0), at 0x38cb80
  [3] handle_segfault(0x6, 0x0, 0xfe3ad610, 0xff074784, 0x1bc3000, 0x755d48), at 0x1a9bec
  [4] __sighndlr(0x6, 0x0, 0xfe3ad610, 0x1a98bc, 0x0, 0x0), at 0xff044b28
  ---- called from signal handler with signal 6 (SIGABRT) ------
  [5] __lwp_kill(0x0, 0x6, 0x864f8, 0xff3b849c, 0xff076648, 0x0), at 0xff045bf0
  [6] raise(0x6, 0x6, 0x5, 0x6, 0x345ac, 0x0), at 0xfefe4bf4
  [7] abort(0xfe3ad988, 0xff076f68, 0xff06f30c, 0xad314, 0xff06e308, 0xff0777b4), at 0xfefc10b8
  [8] __assert(0x755dc8, 0x755df8, 0x32, 0x8, 0xad030, 0x79dcd8), at 0xfefc1334
  [9] __cxa_pure_virtual(0x1cacf10, 0x1e59fc8, 0xfe3ade7c, 0x8, 0xfe3ade7c, 0xfef4cb00), at 0x54fd9c
  [10] _ZNK4Item2eqEPKS_b(0x1cacf10, 0x274fc38, 0x1, 0x8, 0x0, 0xfef4cb00), at 0xd9b9c
  [11] 0x24ea0c(0x274fcd8, 0x274fc38, 0xfe3ade38, 0xfe3ade34, 0x40000000, 0x1), at 0x24ea0c
  [12] 0x24f43c(0x274fd68, 0xc0000000, 0x1, 0xc0000000, 0x1, 0x0), at 0x24f43c
  [13] 0x24f9d0(0x22d1008, 0x22d1fe8, 0x274fd68, 0x0, 0x0, 0x0), at 0x24f9d0
  [14] _ZN4JOIN8optimizeEv(0x22d1008, 0x274f5b0, 0x6fc, 0xfe3ae3cc, 0xfe3ae3c8, 0xfe3ae3c4), at 0x25e868
  [15] _ZN30subselect_single_select_engine4execEv(0x274ff00, 0x0, 0x4, 0x8, 0x0, 0xfef4cb00), at 0x160b98
  [16] _ZN14Item_subselect4execEv(0x274fe60, 0x1e0ff44, 0xfe3ae7ec, 0xfe3ae7e8, 0x0, 0x316ea8), at 0x159938
  [17] _ZN24Item_singlerow_subselect7val_intEv(0x274fe60, 0x1e0ff44, 0xfe3ae88c, 0xfe3ae888, 0x0, 0xfe3ae888), at 0x15addc
  [18] _ZN4Item13save_in_fieldEP5Fieldb(0x274fe60, 0x1e59fc8, 0x0, 0xfe3ae928, 0xfe3ae924, 0xfe3ae920), at 0xe2458
  [19] 0x21cb80(0x1e0edf0, 0x1e0fd70, 0x1e0ff44, 0x0, 0x0, 0xfe3aec00), at 0x21cb80
  [20] _Z36fill_record_n_invoke_before_triggersP3THDR4ListI4ItemES4_bP19Table_triggers_list14trg_event_type(0x1e0edf0, 0x1e0fd70, 0x1e0ff44, 0x0, 0x0, 0x1), at 0x21cd2c
  [21] _Z12mysql_updateP3THDP10TABLE_LISTR4ListI4ItemES6_PS4_jP8st_ordery15enum_duplicatesb(0x1e0edf0, 0x274f370, 0x1e0fd70, 0x1e0ff44, 0x2750a68, 0x0), at 0x282170
  [22] _Z21mysql_execute_commandP3THD(0x1e0edf0, 0x1e0edf0, 0x274f1e8, 0xed, 0xfe3af818, 0xfe3af814), at 0x1d4950
  [23] _Z11mysql_parseP3THDPKcjPS2_(0x1e0edf0, 0x274f1e8, 0xed, 0xfe3afd78, 0xed, 0x274f1e8), at 0x1db71c
  [24] _Z16dispatch_command19enum_server_commandP3THDPcj(0x3, 0x1e0edf0, 0x29702e1, 0xee, 0xfe3afea0, 0x3), at 0x1dc3b8
  [25] 0x1ddea0(0x1e0edf0, 0x3c, 0x0, 0xfef4ca00, 0x0, 0x0), at 0x1ddea0
  [26] handle_one_connection(0x1e0edf0, 0xfe3b0000, 0x0, 0x0, 0x1ddfb0, 0x1), at 0x1de4ec

Core file can be provided on demand, file size is ~50Mb.

How to repeat:
The crash happens sporadically during daily SystemQA tests (sys_rpl_combo suite) under PB2. This is a stress test with multiple connections and considerable load, so extracting the particular chain which causes the crash is problematic.

pstack core (c++filt)

Attachment: pstack_core_1 (application/octet-stream, text), 98.77 KiB.

Thank you for a problem report. Had you identified specific query that leads to this problem? Any ideas on how to reapeat are greatly appriciated.

As I wrote in the description, it is a stress test with many connections running different scenarios on the same tables concurrently in a rapid fashion, so due to race conditions they can produce a huge number of possible execution branches. I'll keep trying to track down the exact action which causes the problem, but it might be much faster to have a developer take a look at core files (I can offer wide choice of those) -- if they don't figure the error itself, they might give a hint on which queries/actions could be most suspicious and worth paying attention to, for example to point that a function in question might be called only upon queries of a certain type, etc.

Scenario to reproduce (2 client connections needed):

# CONNECTION 1

CREATE DATABASE systest1;
USE systest1;

CREATE TABLE tb1_eng1 (
   i1 INT NOT NULL AUTO_INCREMENT, PRIMARY KEY (i1),
   f1 INT
) ENGINE = InnoDB;

INSERT INTO systest1.tb1_eng1 VALUES (1,1),(2,2),(3,3);
COMMIT;
SET AUTOCOMMIT = 0;

CREATE TEMPORARY TABLE systest1.t1_tmp ( f1 INT );

INSERT INTO systest1.t1_tmp (f1)
   SELECT f1 FROM systest1.tb1_eng1 WHERE i1 = 3;
INSERT INTO systest1.t1_tmp (f1)
   SELECT f1 FROM systest1.tb1_eng1 WHERE i1 = 2;

# CONNECTION 2

SET AUTOCOMMIT = 0;
USE systest1;

CREATE TEMPORARY TABLE systest1.t2_tmp ( i1 int, new_i1 int );
INSERT INTO systest1.t2_tmp VALUES
(1,51),(2,52),(3,53);

UPDATE systest1.tb1_eng1 target
SET i1 = (SELECT new_i1 FROM systest1.t2_tmp source WHERE source.i1 = target.i1)
   WHERE i1 = 1;
UPDATE systest1.tb1_eng1 target
SET i1 = (SELECT new_i1 FROM systest1.t2_tmp source WHERE source.i1 = target.i1)
   WHERE i1 = 2;

# While connection 2 is waiting for lock, ...

# CONNECTION 1

INSERT INTO systest1.t1_tmp (f1)
   SELECT f1 FROM systest1.tb1_eng1 WHERE i1 = 1;

# Connection 1 says 
# ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction
# Connection 2 gets lock and finishes query

# CONNECTION 2

UPDATE systest1.tb1_eng1 target
SET i1 = (SELECT new_i1 FROM systest1.t2_tmp source WHERE source.i1 = target.i1)
   WHERE i1 = 3;

##################

At this moment mysqld dies with error message and core file as described before. 

The problem is also reproducible in 5.0.67, 5.0.72sp1, 5.1.30.

Core file and pstack were from Solaris Sparc, but the problem is reproducible on Linux as well.

Also, in the scenario above missed the leading query on connection #1:

DROP DATABASE IF EXISTS systest1;

# the rest as described

I repeated this on 5.0.74 and 5.1.30 on windows too.

testcase

Attachment: bug42419.c (text/plain), 7.71 KiB.

Just for the record : with a fresh 5.0-bk Shane's test program doesn't seem to reproduce it.
I'm getting a lot of :
query failed 'update tb1_eng1 target set i1 = (select new_i1 from t2_tmp source where source.i1 = target.i1) where i1 = abs(4)%10' : 1242 (Subquery returns more than 1 row) (21000)

and some (at the beginning):

select f1 from tb1_eng1 where i1 = abs(14)%10' : 1146 (Table 'test.t1_tmp' doesn't exist) (42S02)

Looking further.

bug42419.test : mysqltest script to reproduce the crash

Attachment: bug42419.test (, text), 1.34 KiB.

a 5.0-bugteam callstack: 

#0  0x000000312300c216 in pthread_kill () from /lib64/libpthread.so.0
#1  0x00000000007b808e in write_core (sig=11) at stacktrace.c:254
#2  0x000000000061be59 in handle_segfault (sig=11) at mysqld.cc:2376
#3  <signal handler called>
#4  0x00000000006851e0 in part_of_refkey (table=0x30218c8, field=0x30225f8) at sql_select.cc:12121
#5  0x00000000006852d8 in test_if_ref (left_item=0x3030188, right_item=0x3030090) at sql_select.cc:11986
#6  0x000000000068a396 in make_cond_for_table (cond=0x3030270, tables=13835058055282163713, 
    used_table=13835058055282163713) at sql_select.cc:12100
#7  0x0000000000699a58 in make_join_select (join=0x301f8d8, select=0x3020e98, cond=0x3030270)
    at sql_select.cc:5805
#8  0x00000000006a7fe1 in JOIN::optimize (this=0x301f8d8) at sql_select.cc:999
#9  0x00000000005da84e in subselect_single_select_engine::exec (this=0x30304d8) at item_subselect.cc:1798
#10 0x00000000005d86bc in Item_subselect::exec (this=0x30303e0) at item_subselect.cc:212
#11 0x00000000005d93b5 in Item_singlerow_subselect::val_int (this=0x30303e0) at item_subselect.cc:506
#12 0x000000000056b69a in Item::save_in_field (this=0x30303e0, field=0x30225f8, no_conversions=false)
    at item.cc:4737
#13 0x000000000066e4dc in fill_record (thd=0x3024e98, fields=@0x30267e0, values=@0x3026b48, 
    ignore_errors=false) at sql_base.cc:5815
#14 0x000000000066e5e8 in fill_record_n_invoke_before_triggers (thd=0x3024e98, fields=@0x30267e0, 
    values=@0x3026b48, ignore_errors=false, triggers=0x0, event=TRG_EVENT_UPDATE) at sql_base.cc:5860
#15 0x00000000006cac27 in mysql_update (thd=0x3024e98, table_list=0x302f218, fields=@0x30267e0, 
    values=@0x3026b48, conds=0x30306a8, order_num=0, order=0x0, limit=18446744073709551615, 
    handle_duplicates=DUP_ERROR, ignore=false) at sql_update.cc:465
#16 0x0000000000639ea0 in mysql_execute_command (thd=0x3024e98) at sql_parse.cc:3590
#17 0x000000000063fc32 in mysql_parse (thd=0x3024e98, 
    inBuf=0x302f0c8 "UPDATE systest1.tb1_eng1 target\nSET i1 = (SELECT new_i1 FROM systest1.t2_tmp source WHERE source.i1 = target.i1)\nWHERE i1 = 3", length=125, found_semicolon=0x7fc7ff6e1e40) at sql_parse.cc:6267
#18 0x0000000000640951 in dispatch_command (command=COM_QUERY, thd=0x3024e98, 
    packet=0x3027039 "UPDATE systest1.tb1_eng1 target\nSET i1 = (SELECT new_i1 FROM systest1.t2_tmp source WHERE source.i1 = target.i1)\nWHERE i1 = 3", packet_length=126) at sql_parse.cc:1938
#19 0x0000000000642089 in do_command (thd=0x3024e98) at sql_parse.cc:1628
#20 0x0000000000642595 in handle_one_connection (arg=0x3024e98) at sql_parse.cc:1234
#21 0x00000031230073da in start_thread () from /lib64/libpthread.so.0
#22 0x00000031224e62bd in clone () from /lib64/libc.so.6

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/66698

2742 Georgi Kodinov	2009-02-17
      Bug #42419: Server crash with "Pure virtual method called" on two concurrent connections
      
      The problem is that tables can enter open table cache for a thread without being properly
      cleaned up. This can happen if make_join_statistics() fails to read a const table because
      of e.g. a deadlock. It does set a member of TABLE structure to a value it allocates,
      but doesn't clean-up this setting on error nor does it set the rest of the members in 
      JOIN to allow for automatic cleanup.
      As a result when such an error occurs and the next statement depends re-uses the table from
      the open tables cache it will get it with this TABLE::reginfo.join_tab pointing to a 
      memory area that's freed.
      Fixed by making sure make_join_statistics() cleans up TABLE::reginfo.join_tab on error.
      modified:
        mysql-test/r/innodb_mysql.result
        mysql-test/t/innodb_mysql.test
        sql/sql_select.cc

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/66925

2742 Georgi Kodinov	2009-02-19
      Bug #42419: Server crash with "Pure virtual method called" on two concurrent
      connections
      The problem is that tables can enter open table cache for a thread without 
      being properly cleaned up. This can happen if make_join_statistics() fails 
      to read a const table because of e.g. a deadlock. It does set a member of 
      TABLE structure to a value it allocates, but doesn't clean-up this setting 
      on error nor does it set the rest of the members in JOIN to allow for 
      automatic cleanup.
      As a result when such an error occurs and the next statement depends re-uses 
      the table from the open tables cache it will get it with this 
      TABLE::reginfo.join_tab pointing to a memory area that's freed.
      Fixed by making sure make_join_statistics() cleans up TABLE::reginfo.join_tab 
      on error.
     @ mysql-test/r/innodb_mysql.result
        Bug #42419: test case
     @ mysql-test/t/innodb_mysql.test
        Bug #42419: test case
     @ sql/sql_select.cc
        Bug #42419: clean up the members of TABLE on failure in 
        make_join_statisitcs()

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/66933

2742 Georgi Kodinov	2009-02-19
      Bug #42419: Server crash with "Pure virtual method called" on two concurrent
      connections
      The problem is that tables can enter open table cache for a thread without 
      being properly cleaned up. This can happen if make_join_statistics() fails 
      to read a const table because of e.g. a deadlock. It does set a member of 
      TABLE structure to a value it allocates, but doesn't clean-up this setting 
      on error nor does it set the rest of the members in JOIN to allow for 
      automatic cleanup.
      As a result when such an error occurs and the next statement depends re-uses 
      the table from the open tables cache it will get it with this 
      TABLE::reginfo.join_tab pointing to a memory area that's freed.
      Fixed by making sure make_join_statistics() cleans up TABLE::reginfo.join_tab 
      on error.
     @ mysql-test/r/innodb_mysql.result
        Bug #42419: test case
     @ mysql-test/t/innodb_mysql-master.opt
        Bug #42419: increase the timeout so it covers te conservative 
        sleep 3 in the test
     @ mysql-test/t/innodb_mysql.test
        Bug #42419: test case
     @ sql/sql_select.cc
        Bug #42419: clean up the members of TABLE on failure in 
                make_join_statisitcs()

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/66999

2755 Georgi Kodinov	2009-02-20
      Bug #42419: test suite fix
      
      Moved the test case for the bug into a separate file (and restored the 
      original innodb_mysql test setup).
      Used the new wait_show_condition test macro to avoid the usage of sleep
     @ mysql-test/include/wait_show_condition.inc
        Bug #42419: new test macro to wait for a row in SHOW to have a certain value.
     @ mysql-test/r/innodb_bug42419.result
        Bug #42419: test case
     @ mysql-test/r/innodb_mysql.result
        Bug #42419: revert to the original innodb_mysql test
     @ mysql-test/t/innodb_bug42419.test
        Bug #42419: test case
     @ mysql-test/t/innodb_mysql-master.opt
        Bug #42419: revert to the original innodb_mysql test
     @ mysql-test/t/innodb_mysql.test
        Bug #42419: revert to the original innodb_mysql test

Pushed into 5.0.79 (revid:joro@sun.com-20090309135922-a0di9ebkxoj4d4wv) (version source revid:joro@sun.com-20090220091206-nj6djcj323w1pbae) (merge vers: 5.0.79) (pib:6)

Noted in 5.0.79 changelog.

Tables could enter open table cache for a thread without being
properly cleaned up, leading to a server crash.

Setting report to NDI pending push into 5.1.x/6.0.x.

Pushed into 5.1.33 (revid:joro@sun.com-20090313111355-7bsi1hgkvrg8pdds) (version source revid:azundris@mysql.com-20090224070618-mr7stu6rfcvoj18g) (merge vers: 5.1.33) (pib:6)

Noted in 5.1.33 changelog.

Setting report to NDI pending push into 6.0.x.

Pushed into 6.0.11-alpha (revid:joro@sun.com-20090318122208-1b5kvg6zeb4hxwp9) (version source revid:azundris@mysql.com-20090223123708-n9rf2to3g15br7za) (merge vers: 6.0.10-alpha) (pib:6)

Noted in 6.0.11 changelog.

Pushed into 5.1.34-ndb-6.2.18 (revid:jonas@mysql.com-20090508185236-p9b3as7qyauybefl) (version source revid:jonas@mysql.com-20090508100057-30ote4xggi4nq14v) (merge vers: 5.1.33-ndb-6.2.18) (pib:6)

Pushed into 5.1.34-ndb-6.3.25 (revid:jonas@mysql.com-20090509063138-1u3q3v09wnn2txyt) (version source revid:jonas@mysql.com-20090508175813-s6yele2z3oh6o99z) (merge vers: 5.1.33-ndb-6.3.25) (pib:6)

Pushed into 5.1.34-ndb-7.0.6 (revid:jonas@mysql.com-20090509154927-im9a7g846c6u1hzc) (version source revid:jonas@mysql.com-20090509073226-09bljakh9eppogec) (merge vers: 5.1.33-ndb-7.0.6) (pib:6)

Noted in 5.0.74sp1 changelog.