Bug #46322 Sporadic timeout in mysql_upgrade.test
Submitted: 21 Jul 2009 12:44 Modified: 19 Dec 2009 0:08
Reporter: Sven Sandberg Email Updates:
Status: Closed Impact on me:
None 
Category:Tools: MTR / mysql-test-run Severity:S7 (Test Cases)
Version:5.1+ OS:Any
Assigned to: Bjørn Munch CPU Architecture:Any
Tags: crash, crash, handle_connections_sockets, pushbuild, segfault, sporadic, test failure

[21 Jul 2009 12:44] Sven Sandberg
Description:
main.mysql_upgrade fails randomly with stack trace inside select() called from handle_connection_sockets() called from main():

main.mysql_upgrade                       [ fail ]  timeout after 900 seconds
        Test ended at 2009-07-21 06:25:14

Test case timeout after 900 seconds

== /export/home4/pb2/build/sb_3-None-1248116894.23/mysql-azalea-perfschema-gcov/mysql-test/var/log/mysql_upgrade.log == 
mysql.ndb_binlog_index                             OK
mysql.plugin                                       OK
mysql.proc                                         OK
mysql.procs_priv                                   OK
mysql.servers                                      OK
mysql.slow_log
Error    : You can't use locks with log tables.
status   : OK
mysql.tables_priv                                  OK
mysql.time_zone                                    OK
mysql.time_zone_leap_second                        OK
mysql.time_zone_name                               OK
mysql.time_zone_transition                         OK
mysql.time_zone_transition_type                    OK
mysql.user                                         OK
DROP USER mysqltest1@'%';
Run mysql_upgrade with a non existing server socket
mysqlcheck: Got error when trying to connect
FATAL ERROR: Upgrade failed
set GLOBAL sql_mode='STRICT_ALL_TABLES,ANSI_QUOTES,NO_ZERO_DATE';

 == /export/home4/pb2/build/sb_3-None-1248116894.23/mysql-azalea-perfschema-gcov/mysql-test/var/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default' after 500 attempts: 2002 Can't connect to local MySQL server through socket '/export/home4/pb2/build/sb_3-None-1248116894.23/tmp/FzINVOQMxI/mysqld.1.sock' (111)

 - saving '/export/home4/pb2/build/sb_3-None-1248116894.23/mysql-azalea-perfschema-gcov/mysql-test/var/log/main.mysql_upgrade/' to '/export/home4/pb2/build/sb_3-None-1248116894.23/mysql-azalea-perfschema-gcov/mysql-test/var/log/main.mysql_upgrade/'
 - found 'core.9219' (0/5)

Trying 'dbx' to get a backtrace

Trying 'gdb' to get a backtrace
Guessing that core was generated by '/export/home4/pb2/build/sb_3-None-1248116894.23/mysql-azalea-perfschema-gcov/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `/export/home4/pb2/build/sb_3-None-1248116894.23/mysql-azalea-perfschema-gcov/sq'.
Program terminated with signal 6, Aborted.
#0  0x00000033e460b122 in pthread_kill () from /lib64/libpthread.so.0
#0  0x00000033e460b122 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000f20e4b in my_write_core (sig=6) at stacktrace.c:309
#2  0x000000000078d7f7 in handle_segfault (sig=6) at mysqld.cc:2754
#3  <signal handler called>
#4  0x00000033e3acb0a2 in select () from /lib64/libc.so.6
#5  0x000000000078e7ce in handle_connections_sockets () at mysqld.cc:5418
#6  0x0000000000794f28 in main (argc=35, argv=0x160f0d78) at mysqld.cc:4912

Thread 3 (process 9221):
#0  0x00000033e460dba8 in do_sigwait () from /lib64/libpthread.so.0
#1  0x00000033e460dc4d in sigwait () from /lib64/libpthread.so.0
#2  0x000000000078c999 in signal_hand (arg=0x0) at mysqld.cc:2957
#3  0x0000000001028f3e in pfs_spawn_thread (arg=0x16333128) at pfs.cc:1012
#4  0x00000033e46062f7 in start_thread () from /lib64/libpthread.so.0
#5  0x00000033e3ad1b6d in clone () from /lib64/libc.so.6

Thread 2 (process 15471):
#0  0x0000000000f20272 in _sanity (filename=0x110de8b "sql_string.h", 
    lineno=194) at safemalloc.c:526
#1  0x0000000000f1f363 in _myfree (ptr=0x1665e028, 
    filename=0x110de8b "sql_string.h", lineno=194, myflags=0)
    at safemalloc.c:277
#2  0x00000000005e670c in String::free (this=0x41c4cfd0) at ../sql_string.h:194
#3  0x0000000000629412 in String::set (this=0x41c4cfd0, 
    str=0x16e1d0b8 "Queryctuser", arg_length=5, cs=0x16bbbe0)
    at ../../sql/sql_string.h:141
#4  0x0000000000724c39 in Field_varstring::val_str (this=0x16890910, 
    val_buffer=0x41c4cfd0, val_ptr=0x41c4cfd0) at field.cc:6876
#5  0x0000000000bfa57a in ha_tina::encode_quote (this=0x16785660, 
    buf=0x16e1d0a0 "Ó=eJ'") at ha_tina.cc:530
#6  0x0000000000bfae2f in ha_tina::write_row (this=0x16785660, 
    buf=0x16e1d0a0 "Ó=eJ'") at ha_tina.cc:985
#7  0x00000000009e0aa7 in handler::ha_write_row (this=0x16785660, 
    buf=0x16e1d0a0 "Ó=eJ'") at handler.cc:5536
#8  0x0000000000a17bf0 in copy_data_between_tables (from=0x16587578, 
    to=0x1658e608, create=@0x41c4f1c8, ignore=false, order_num=0, order=0x0, 
    copied=0x41c4e4b8, deleted=0x41c4e4b0, keys_onoff=LEAVE_AS_IS, 
    error_if_not_empty=false) at sql_table.cc:7921
#9  0x0000000000a2beed in mysql_alter_table (thd=0x2aaaac014348, 
    new_db=0x1656d378 "mysql", new_name=0x1656cfa0 "general_log", 
    create_info=0x41c4e810, table_list=0x1656cfe8, alter_info=0x41c4f180, 
    order_num=0, order=0x0, ignore=false) at sql_table.cc:7517
#10 0x00000000007afef5 in mysql_execute_command (thd=0x2aaaac014348)
    at sql_parse.cc:2894
#11 0x00000000007bb44a in mysql_parse (thd=0x2aaaac014348, 
    inBuf=0x1656cec0 "ALTER TABLE general_log CONVERT TO CHARACTER SET utf8", 
    length=53, found_semicolon=0x41c4fec0) at sql_parse.cc:6060
#12 0x00000000007bd382 in dispatch_command (command=COM_QUERY, 
    thd=0x2aaaac014348, 
    packet=0x2aaaac01ecc9 "ALTER TABLE general_log CONVERT TO CHARACTER SET utf8", packet_length=53) at sql_parse.cc:1073
#13 0x00000000007bf603 in do_command (thd=0x2aaaac014348) at sql_parse.cc:755
#14 0x000000000079ee10 in do_handle_one_connection (thd_arg=0x2aaaac014348)
    at sql_connect.cc:1168
#15 0x000000000079efcf in handle_one_connection (arg=0x2aaaac014348)
    at sql_connect.cc:1108
#16 0x0000000001028f3e in pfs_spawn_thread (arg=0x2aaaac00f638) at pfs.cc:1012
#17 0x00000033e46062f7 in start_thread () from /lib64/libpthread.so.0
#18 0x00000033e3ad1b6d in clone () from /lib64/libc.so.6
Current language:  auto; currently c

Thread 1 (process 9219):
#0  0x00000033e460b122 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000f20e4b in my_write_core (sig=6) at stacktrace.c:309
#2  0x000000000078d7f7 in handle_segfault (sig=6) at mysqld.cc:2754
#3  <signal handler called>
#4  0x00000033e3acb0a2 in select () from /lib64/libc.so.6
#5  0x000000000078e7ce in handle_connections_sockets () at mysqld.cc:5418
#6  0x0000000000794f28 in main (argc=35, argv=0x160f0d78) at mysqld.cc:4912

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

How to repeat:
This is difficult to search for in xref, but it seems there are a lot of failures:

http://tinyurl.com/mtvddd
[10 Aug 2009 17:49] Sveta Smirnova
Thank you for the report.

I can not repeat it in my own setup as well, but if this is repeatable on several boxes in pushbuild this can be verified though.
[27 Aug 2009 12: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/81721

2821 Bjorn Munch	2009-08-27
      Bug #46322 Sporadic timeout in mysql_upgrade.test
      Apparently caused by logging to table
      Turn on logging to file only
[27 Aug 2009 13:18] 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/81734

2821 Bjorn Munch	2009-08-27
      Bug #46322 Sporadic timeout in mysql_upgrade.test
      Apparently caused by logging to table
      Turn on logging to file only, add to .opt file for tests needing log to table
[27 Aug 2009 21:16] Bjørn Munch
Pushed to azalea-mtr (soon to be renamed to next-mtr) and 5.1-mtr
[3 Sep 2009 17:12] Bugs System
Pushed into 5.1.40 (revid:bjorn.munch@sun.com-20090903170735-679d64zp580wl39j) (version source revid:bjorn.munch@sun.com-20090903170735-679d64zp580wl39j) (merge vers: 5.1.40) (pib:11)
[4 Sep 2009 0:58] Paul DuBois
Test suite change. No changelog entry needed.

Setting report to NDI pending push into 5.4.x.
[30 Sep 2009 8:18] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20090929093622-1mooerbh12e97zux) (version source revid:alik@sun.com-20090922182109-vs5ign07cwht12z6) (merge vers: 6.0.14-alpha) (pib:11)
[30 Sep 2009 8:20] Bugs System
Pushed into 5.4.5-beta (revid:alik@sun.com-20090925094254-tjl9eajkzwzgthoe) (version source revid:alik@sun.com-20090922142453-x275o41whpyezh4q) (merge vers: 5.4.4-beta) (pib:11)
[30 Sep 2009 19:38] Paul DuBois
Test suite change. No changelog entry needed.
[13 Nov 2009 10:27] Davi Arnaut
When logging to table was enabled by default, the log tables would get very large during a test suite run. mysql_upgrade was being called from certain tests and it tried to "upgrade" those large tables. This upgrade consists of modifying a column of the log tables (see scripts/mysql_system_tables_fix.sql), which implies a full table copy. Since those tables were very large and due to certain shortcomings of the CSV storage engine (ie Bug#35165), the test would take a long time to run and timeout.

See Bug#43801 for a similar problem.
[18 Dec 2009 10:28] Bugs System
Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)
[18 Dec 2009 10:44] Bugs System
Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)
[18 Dec 2009 10:59] Bugs System
Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)
[18 Dec 2009 11:14] Bugs System
Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)