MySQL Bugs: #38741: main.innodb_mysql crashes randomly (2)

Bug #38741	main.innodb_mysql crashes randomly (2)
Submitted:	12 Aug 2008 8:35	Modified:	12 May 2009 2:11
Reporter:	Alexander Nozdrin	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.1	OS:	Any (debx86-b, valgrind)
Assigned to:	Alexander Nozdrin	CPU Architecture:	Any
Tags:	crash, pushbuild, sporadic, test failure

Description:
main.innodb_mysql sporadically crashes on debx86-b in embedded mode
with the following symptoms (in server log):

---------------------------------------------------------------------
WARNING:  'Attempting backtrace...'
    COUNT: 1
    FILES:    master.err
    TESTS:    main.innodb_mysql

WARNING:  'mysqltest_embedded: sql_parse.cc:5529: void mysql_reset_thd_for_next_command(THD*): Assertion `!thd->spcont' failed.'
    COUNT: 1
    FILES:    master.err
    TESTS:    main.innodb_mysql
---------------------------------------------------------------------

The cause of this bug might be similar to the one of Bug#37795.

How to repeat:
https://intranet.mysql.com/secure/pushbuild/xref.pl?startdate=&enddate=&dir=&plat=debx86-b...

This pushbuild failure happens only in innodb_mysql, in embedded, and on either debx86-b or pb-valgrind. In 5.1-rpl and 6.0-rpl, the error message includes a stack trace.

This xref includes only failures with the stack trace: http://tinyurl.com/5nbugw
One example of a failure with a stack trace: https://intranet.mysql.com/secure/pushbuild/showpush.pl?dir=bzr_mysql-6.0-rpl&order=71 debx86-b/embedded

The full error message for a failure with stack trace:

main.innodb_mysql                        [ fail ]

CURRENT_TEST: main.innodb_mysql
InnoDB: The first specified data file /dev/shm/var-embedded-112/1/mysqld.1/data/ibdata1 did not exist:
InnoDB: a new database to be created!
080912 10:03:41  InnoDB: Setting file /dev/shm/var-embedded-112/1/mysqld.1/data/ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
080912 10:03:41  InnoDB: Log file /dev/shm/var-embedded-112/1/mysqld.1/data/ib_logfile0 did not exist: new to be created
InnoDB: Setting log file /dev/shm/var-embedded-112/1/mysqld.1/data/ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
080912 10:03:41  InnoDB: Log file /dev/shm/var-embedded-112/1/mysqld.1/data/ib_logfile1 did not exist: new to be created
InnoDB: Setting log file /dev/shm/var-embedded-112/1/mysqld.1/data/ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
080912 10:04:24  InnoDB: Error: table `test`.`bug29807` does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.
InnoDB: Have you copied the .frm file of the table to the
InnoDB: MySQL database directory from another database?
InnoDB: You can look for further help from
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/innodb-troubleshooting.html
mysqltest_embedded: sql_parse.cc:5652: void mysql_reset_thd_for_next_command(THD*): Assertion `!thd->spcont' failed.
mysqltest got signal 6
read_command_buf at 0x8c994e0 = SELECT * FROM t1
conn->name at 0x9cd7460 = con2
conn->cur_query at 0x9ce5b9d = CALL p1;
Attempting backtrace...
stack_bottom = (nil) thread_stack 0x30c00
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(my_print_stacktrace+0x26)[0x825658b]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded[0x81fd414]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded[0x81fd43e]
[0xffffe420]
/lib/tls/libc.so.6(abort+0x109)[0x401bf0c9]
/lib/tls/libc.so.6(__assert_fail+0x10f)[0x401b705f]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(_Z32mysql_reset_thd_for_next_commandP3THD+0x5b)[0x82ec2d9]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(_Z11mysql_parseP3THDPKcjPS2_+0x6c)[0x82f7eba]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(_Z16dispatch_command19enum_server_commandP3THDPcj+0x813)[0x82f8a17]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded[0x821e153]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(mysql_send_query+0x86)[0x8210a5e]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded[0x81ff572]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(_Z16run_query_normalP13st_connectionP10st_commandiPciP17st_dynamic_stringS5_+0xb2)[0x8209438]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(_Z9run_queryP13st_connectionP10st_commandi+0x5a1)[0x8209da9]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(main+0xa88)[0x820b1f6]
/lib/tls/libc.so.6(__libc_start_main+0xc8)[0x401a9ea8]
/data0/pushbuild/pb2/pb/bzr_mysql-6.0-rpl/71/mysql-6.0.8-alpha-pb71/libmysqld/examples/mysqltest_embedded(__gxx_personality_v0+0xed)[0x81face1]

 - saving '/dev/shm/var-embedded-112/1/log/main.innodb_mysql/' to '/dev/shm/var-embedded-112/log/main.innodb_mysql/'

Retrying test, attempt(2/3)...

A similar but less common crash: BUG#39855

same questions as for the bug mentioned in the previous note:

a- when (as in bzr revno) do you think it started?
b- do you have a numerical estimate on 'sporadically'? Does it fail in every other run, or
at a rate of something like 5-10%, for example?

Bug#37795 has been marked as a duplicate of this one.

> a- when (as in bzr revno) do you think it started?

The first occurrence in the new history was on 2008-04-29.
Unfortunately, I can't provide bzr revno.

> b- do you have a numerical estimate on 'sporadically'?
> Does it fail in every other run, or at a rate of something like 5-10%,\
> for example?

We've got 12 failures since 2008-04-29 so far. That means, it fails very rare.
I would say less than 1%.

Also, please note, that it's failing only in embedded mode
on valgrind and debx86-b (slooow boxes). That makes me think about
a kind of race condition there.

In got this crash running on a fairly fast Linux server (but during high load) for the same test and with the same assert using the latest version from mysql-6.0-falcon-team tree. In case it is of interest, I am adding the call stack and
will add the content of a few data structures as a attachment (thd is biiig).

Assert:

mysqltest_embedded: sql_parse.cc:5458: void mysql_reset_thd_for_next_command(THD*): Assertion `!thd->spcont' failed.

and call stack:

#5  0x00000030236295d6 in __assert_fail () from /lib64/libc.so.6
#6  0x00000000005fcc0b in mysql_reset_thd_for_next_command (thd=0x14b27e00) at sql_parse.cc:5458
#7  0x0000000000600fc5 in mysql_parse (thd=0x14b27e00, inBuf=0x14b6a698 "SELECT * FROM t1", 
    length=16, found_semicolon=0x7fff513b8ef0) at sql_parse.cc:5698
#8  0x00000000006021e8 in dispatch_command (command=COM_QUERY, thd=0x14b27e00, 
    packet=0x2aaac001cb90 "SELECT * FROM t1", packet_length=<value optimized out>)
    at sql_parse.cc:1009
#9  0x0000000000559897 in emb_advanced_command (mysql=0xe421c0, command=COM_QUERY, header=0x0, 
    header_length=0, arg=0x2aaac001cb90 "SELECT * FROM t1", arg_length=16, skip_check=1 '\001', 
    stmt=0x0) at lib_sql.cc:130
#10 0x000000000054b736 in mysql_send_query (mysql=0xe421c0, 
    query=0x2aaac001cb90 "SELECT * FROM t1", length=16) at client.c:2783
#11 0x000000000054860e in run_query_normal (cn=0xe421c0, command=0x2aaac003bf90, flags=2, 
    query=0x2aaac001cb90 "SELECT * FROM t1", query_len=16, ds=0xe6bbe0, 
    ds_warnings=0x7fff513b9120) at mysqltest.cc:704
#12 0x0000000000548866 in run_query (cn=0xe421c0, command=0x2aaac003bf90, 
    flags=<value optimized out>) at mysqltest.cc:7149
#13 0x000000000054a8f8 in main (argc=<value optimized out>, argv=<value optimized out>)
    at mysqltest.cc:7777

Content of tdh and tdh->spcont

Attachment: tdh.txt (text/plain), 35.99 KiB.

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

2850 Alexander Nozdrin	2009-04-02
      Patch for Bug#38741: main.innodb_mysql crashes randomly (2).
      
      It was a test case problem: one 'reap' statement was forgotten.

Patch queued in 5.1-bugteam.

See also Bug#44042.

Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)

Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:timothy.smith@sun.com-20090402084651-goti17omc8o30l3w) (merge vers: 6.0.11-alpha) (pib:6)

Test case change. No changelog entry needed.

Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)

Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)

Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)