Drizzle crash when running random query generator

[Lee Bieber]

When running the basic random query generator test, drizzle crashes with more than 7 threads and 40 queries

See for more details on the Random Query Generator - http://forge.mysql.com/wiki/RandomQueryGenerator

For now you can get the latest version that works with Drizzle at bzr branch lp:~kalebral/randgen/drizzle-fixes. Also need to have DBD::drizzle installed as this is a perl test framework

The following script runs the test and takes input as the number of threads and queries to run. It assumes you have a running drizzled to run the test against.

#! /bin/sh

if [ $# != 2 ]
then
        echo "Usage $0: <number of threads> <number of queries>"
        exit 1
else
        threads=$1
        queries=$2
        logfile=/tmp/randgen.log
fi

./gentest.pl \
  --dsn=dbi:drizzle:host=localhost:port=9306:user=root:password="":database=test \
  --gendata=conf/example.zz \
  --grammar=conf/example.yy \
  --queries=$queries \
  --threads=$threads \
  --duration=1800 \
  --engine=Innodb \
  --executor=drizzle | tee $logfile

total=`grep "Child process completed successfully" $logfile | wc -l`
echo "**** $total tests passed ****"

% run.sh 7 40
... lots of output......
# 16:13:16 Child process completed successfully.
# 16:13:17 Killing periodic reporting process with pid 13120...
# 16:13:17 Test completed successfully.
**** 7 tests passed ****

% run 8 50
....lots of output.....
# 16:14:39 Killing child process with pid 13241...
# 16:14:40 Killing periodic reporting process with pid 13225...
# 16:14:40 Test completed with failure status 34 <--- return status should be 0
**** 5 tests passed **** <---- should be 8

From drizzle.err file
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins.
090930 9:42:15 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 153154025
090930 9:42:15 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: Doing recovery: scanned up to log sequence number 153274732
090930 9:42:15 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 0, file name foo
090930 9:42:16 InnoDB Plugin 1.0.3 started; log sequence number 153274732
Listening on 0.0.0.0:9306
Listening on :::9306
./sbin/drizzled: Forcing close of thread 0 user: '(null)'
./sbin/drizzled: ready for connections.
Version: '2009.09.1144' Source distribution (trunk)
drizzled: diagnostics_area.cc:89: void Diagnostics_area::set_ok_status(Session*, ha_rows, ha_rows, uint64_t, const char*): Assertion `! is_set()' failed.
090930 9:42:21 - drizzled 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=8388608
read_buffer_size=131072
max_used_connections=7
connection_count=7
It is possible that drizzled could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*thread_count
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

session: 0xa0396a0
Attempting backtrace. You can use the following information to find out
where drizzled died. If you see no messages after this, something went
terribly wrong...
./sbin/drizzled [0x8199762]
./sbin/drizzled [0x81998fb]
./sbin/drizzled [0x8063ecf]
[0xb7f31400]
[0xb7f31422]
/lib/tls/i686/cmov/libc.so.6(gsignal+0x50) [0xb79996d0]
/lib/tls/i686/cmov/libc.so.6(abort+0x188) [0xb799b098]
/lib/tls/i686/cmov/libc.so.6(__assert_fail+0xee) [0xb79925ce]
./sbin/drizzled [0x80632f2]
./sbin/drizzled [0x818aa09]
./sbin/drizzled [0x8061005]
./sbin/drizzled [0x8162f3e]
./sbin/drizzled [0x8163ab2]
./sbin/drizzled [0x8163f44]
./sbin/drizzled [0x812a157]
./sbin/drizzled [0x812c132]
./sbin/drizzled [0x83614e3]
/lib/tls/i686/cmov/libpthread.so.0 [0xb7ad74ff]
/lib/tls/i686/cmov/libc.so.6(clone+0x5e) [0xb7a5249e]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
session->query at 0xa03ed10 = UPDATE `table10_innodb_int_autoinc` SET `char` = 2 WHERE `enum_not_null_key` = 0 LIMIT 6
session->thread_id=10
session->killed=NOT_KILLED

[fmpwizard (diego-fmpwizard)]

So far the reason could be that two threads are using the same session. and one resets Diagnostics_area.m_status while the other thread was hoping for m_status != DA_EMPTY.

Some more information, courtesy of gdb:

gdb) thread apply all bt

Thread 10 (process 18572 thread 0x293f):
#0 0x00007fff82b416be in __semwait_signal_nocancel ()
#1 0x00007fff82b412f4 in nanosleep$NOCANCEL ()
#2 0x00007fff82b3b404 in usleep$NOCANCEL ()
#3 0x00007fff82b4ff77 in abort ()
#4 0x00007fff82b468c1 in __assert_rtn ()
#5 0x000000010000db1a in Diagnostics_area::set_ok_status (this=0x1018669d8, session=0x101865e00, affected_rows_arg=0, found_rows_arg=0, last_insert_id_arg=0, message_arg=0x103646580 "Rows matched: 0 Changed: 0 Warnings: 0") at diagnostics_area.cc:89
#6 0x0000000100005ce9 in Session::my_ok (this=0x101865e00, affected_rows=0, found_rows_arg=0, passed_id=0, message=0x103646580 "Rows matched: 0 Changed: 0 Warnings: 0") at session.h:
1288
#7 0x00000001001767cf in mysql_update (session=0x101865e00, table_list=0x101889f48, fields=@0x101866ff8, values=@0x101867298, conds=0x10188a3c8, order_num=0, order=0x0, limit=6, ignore=false) at sql_update.cc:637
#8 0x000000010000ae0a in drizzled::statement::Update::execute (this=0x1028aeff0) at statement/update.cc:50
#9 0x0000000100146e7b in mysql_execute_command (session=0x101865e00) at sql_parse.cc:934
#10 0x0000000100147070 in mysql_parse (session=0x101865e00, inBuf=0x101889e10 "UPDATE `table0_innodb_int_autoinc` SET `int_key` = 6 WHERE `enum_not_null_key` = 0 LIMIT 6", length=90, found_semicolon=0x103646e28) at sql_parse.cc:1234
#11 0x00000001001475fc in dispatch_command (command=COM_QUERY, session=0x101865e00, packet=0x10268b001 "UPDATE `table0_innodb_int_autoinc` SET `int_key` = 6 WHERE `enum_not_null_key` = 0 LIMIT 6", packet_length=90) at sql_parse.cc:210
#12 0x0000000100104819 in Session::executeStatement (this=0x101865e00) at session.cc:727
#13 0x0000000100104e99 in Session::run (this=0x101865e00) at session.cc:602
#14 0x0000000100370012 in MultiThreadScheduler::runSession (this=0x10289d4f0, session=0x101865e00) at plugin/multi_thread/multi_thread.cc:102
#15 0x000000010036ecc8 in session_thread (arg=0x101865e00) at plugin/multi_thread/multi_thread.cc:123
#16 0x00007fff82aa5e8b in _pthread_start ()
#17 0x00007fff82aa5d4d in thread_start ()

Thread 9 (process 18572 thread 0x2603):
#0 0x00007fff82ac3582 in select$DARWIN_EXTSN ()
#1 0x00000001002f7afd in os_thread_sleep (tm=1000000) at plugin/innobase/os/os0thread.c:292
#2 0x00000001003463ee in srv_master_thread (arg=0x0) at plugin/innobase/srv/srv0srv.c:2326
#3 0x00007fff82aa5e8b in _pthread_start ()
#4 0x00007fff82aa5d4d in thread_start ()

Thread 8 (process 18572 thread 0x2503):
#0 0x00007fff82ac3582 in select$DARWIN_EXTSN ()
#1 0x00000001002f7afd in os_thread_sleep (tm=1000000) at plugin/innobase/os/os0thread.c:292
#2 0x0000000100346155 in srv_error_monitor_thread (arg=0x0) at plugin/innobase/srv/srv0srv.c:2195
#3 0x00007fff82aa5e8b in _pthread_start ()
#4 0x00007fff82aa5d4d in thread_start ()

Thread 7 (process 18572 thread 0x2407):
#0 0x00007fff82ac3582 in select$DARWIN_EXTSN ()
#1 0x00000001002f7afd in os_thread_sleep (tm=1000000...

[Stewart Smith (stewart)]

I don't think this would be the case. more likely, either overwriting something or not setting the diagnostic area correctly in some case. or, as has been seen in the past, not properly sending result for a command.

[Brian Aker (brianaker)]

Bad memory cleanup on diag area?

Hmmm hell-grind...

[Lee Bieber (kalebral-deactivatedaccount)]

many_indexes test also fails with the same error when using a small number of threads and queries, it will pass with 5 queries and 3 threads, but nothing above that works.

# 13:01:49 Starting ./gentest.pl \
# 13:01:49 --dsn=dbi:drizzle:host=localhost:port=9306:user=root:password=:database=test \
# 13:01:49 --gendata=conf/many_indexes_drizzle.zz \
# 13:01:49 --grammar=conf/many_indexes_drizzle.yy \
# 13:01:49 --queries=5 \
# 13:01:49 --threads=3 \
# 13:01:49 --duration=1800 \
# 13:01:49 --engine=Innodb \
# 13:01:49 --executor=drizzle
......
# 13:01:50 Child process completed successfully.
# 13:01:50 Executor initialized, id GenTest::Executor::Drizzle 2009.09.1144 ()
# 13:01:50 Started periodic reporting process...
# 13:01:50 Child process completed successfully.
# 13:01:51 Killing periodic reporting process with pid 8399...
# 13:01:52 Test completed successfully.

[fmpwizard (diego-fmpwizard)]

Maybe the relevant portion of the valgrind output:

==816== Invalid read of size 1
==816== at 0x66BF4D: my_strcasecmp_utf8mb4 (ctype-utf8.cc:2545)
==816== by 0x572A04: Select_Lex::add_table_to_list(Session*, Table_ident*, st_mysql_lex_string*, unsigned int, thr_lock_type, List<Index_hint>*, st_mysql_lex_string*) (sql_parse.cc:991)
==816== by 0x5ADD73: DRIZZLEparse(void*) (sql_yacc.yy:4685)
==816== by 0x57409F: parse_sql(Session*, Lex_input_stream*) (sql_parse.cc:1854)
==816== by 0x57211A: mysql_parse(Session*, char const*, unsigned int, char const**) (sql_parse.cc:759)
==816== by 0x570D60: dispatch_command(enum_server_command, Session*, char*, unsigned int) (sql_parse.cc:218)
==816== by 0x52B8E0: Session::executeStatement() (session.cc:730)
==816== by 0x52B3C0: Session::run() (session.cc:602)
==816== by 0x7A37A9: MultiThreadScheduler::runSession(Session*) (multi_thread.cc:102)
==816== by 0x7A2BA1: session_thread (multi_thread.cc:123)
==816== by 0x31B2406869: start_thread (in /lib64/libpthread-2.10.1.so)
==816== by 0x31B18DE3BC: clone (in /lib64/libc-2.10.1.so)
==816== Address 0x60af3b8 is 24 bytes inside a block of size 43 free'd
==816== at 0x4A05E3F: operator delete(void*) (vg_replace_malloc.c:342)
==816== by 0x31C0EA1548: std::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() (in /usr/lib64/libstdc++.so.6.0.12)
==816== by 0x31B18367F1: exit (in /lib64/libc-2.10.1.so)
==816== by 0x426CDB: handle_segfault (drizzled.cc:975)
==816== by 0x31B240EEDF: (within /lib64/libpthread-2.10.1.so)
==816== by 0x31B18332F4: raise (in /lib64/libc-2.10.1.so)
==816== by 0x31B1834B1F: abort (in /lib64/libc-2.10.1.so)
==816== by 0x31B182C2F9: __assert_fail (in /lib64/libc-2.10.1.so)
==816== by 0x4256FA: Diagnostics_area::set_ok_status(Session*, unsigned long, unsigned long, unsigned long, char const*) (diagnostics_area.cc:89)
==816== by 0x4147F6: Session::my_ok(unsigned long, unsigned long, unsigned long, char const*) (session.h:1297)
==816== by 0x55DED7: mysql_delete(Session*, TableList*, Item*, st_sql_list*, unsigned long, unsigned long, bool) (sql_delete.cc:169)
==816== by 0x417F66: drizzled::statement::Delete::execute() (delete.cc:50)
==816==

[fmpwizard (diego-fmpwizard)]

Thanks Lee for adding the other test, and thanks Brian and Stewart for the pointers.

I was able to reduce the steps to reproduce the crash to:

drizzle> create database test;
drizzle> use test;
drizzle> CREATE TABLE `table1_innodb_int_autoinc` (
    -> `int` int DEFAULT NULL,
    -> `int_not_null_key` int NOT NULL,
    -> `enum` enum('a','b','c','d','e','f','g','h','i','j','k','l','m','n','o','p','q','r','s','t','u','v','w','x','y','z') DEFAULT NULL,
    -> `char_key` varchar(1) DEFAULT NULL,
    -> `int_not_null` int NOT NULL,
    -> `char_not_null` varchar(1) NOT NULL,
    -> `enum_not_null` enum('a','b','c','d','e','f','g','h','i','j','k','l','m','n','o','p','q','r','s','t','u','v','w','x','y','z') NOT NULL,
    -> `enum_key` enum('a','b','c','d','e','f','g','h','i','j','k','l','m','n','o','p','q','r','s','t','u','v','w','x','y','z') DEFAULT NULL,
    -> `char` varchar(1) DEFAULT NULL,
    -> `pk` int NOT NULL AUTO_INCREMENT,
    -> `enum_not_null_key` enum('a','b','c','d','e','f','g','h','i','j','k','l','m','n','o','p','q','r','s','t','u','v','w','x','y','z') NOT NULL,
    -> `int_key` int DEFAULT NULL,
    -> `char_not_null_key` varchar(1) NOT NULL,
    -> PRIMARY KEY (`pk`),
    -> KEY `int_not_null_key` (`int_not_null_key`),
    -> KEY `char_key` (`char_key`),
    -> KEY `enum_key` (`enum_key`),
    -> KEY `enum_not_null_key` (`enum_not_null_key`),
    -> KEY `int_key` (`int_key`),
    -> KEY `char_not_null_key` (`char_not_null_key`)
    -> ) ENGINE=InnoDB
    -> ;

drizzle> UPDATE `table1_innodb_int_autoinc` SET `enum_not_null` = CONVERT( 'what' , CHAR) WHERE `enum_key` IN ( REPEAT( x'8156' , 165 ) , REPEAT( x'BF8D' , 40 ) , CONVERT( 'yeah' , CHAR) , CONVERT( 'ewscwgufzogybtkjkpttdftjvpfgwdleinctcibsanrkxmtskurjkbrfthplegltfvvbmyihkjcrhcfjqsgroeyjvqheofvdcujkgvyanveuqlyhnkwizomgnqqxmctihkgrzvgoxwzoaoqfhjaj' , CHAR) , CONVERT( 'okay' , CHAR) , CONVERT( 'we' , CHAR) , CONVERT( 'sewscwgufzogybtkjkpttdftjvpfgwdleinctcibsanrkxmtskurjkbrfthplegltfvvbmyihkjcrhcfjqsgroeyjvqheofvdcujkgvyanveuqlyhnkwizomgnqqxmctihkgrzvgoxwzoaoqfhjajxhchyeexglnxgoruczozuiawdckfqxatruutqbytleszhxgopyizrctmefncptaa' , CHAR) ) ORDER BY `pk` LIMIT 2;

As soon as you run the update statement, drizzled fails on the assert(). I'll see if I can make the table a bit simpler and then move to add a test case and come up with the fix.

-Diego

[fmpwizard (diego-fmpwizard)]

Simplified queries:

drizzle> create database test;
drizzle> use test;
drizzle> CREATE TABLE `table1_innodb_int_autoinc` ( `enum_not_null` enum('a','b','c','d','e','f','g','h','i','j','k','l','m','n','o','p','q','r','s','t','u','v','w','x','y','z') NOT NULL, `enum_key` enum('a','b','c','d','e','f','g','h','i','j','k','l','m','n','o','p','q','r','s','t','u','v','w','x','y','z') DEFAULT NULL, KEY `enum_key` (`enum_key`) ) ENGINE=InnoDB;

drizzle> UPDATE `table1_innodb_int_autoinc` SET `enum_not_null` = "crash" WHERE `enum_key` = now() ;

Few notes:

* I had to make enum_key a key, otherwise there was no crash.
* "WHERE `enum_key` = now()" produces a crash, but
"WHERE `enum_key` = select 1 " does not . I could replace now() for something like convert("text", CHAR)
* The SET and WHERE clauses had to specified different columns to reproduce the crash.

[fmpwizard (diego-fmpwizard)]

revno: 1138
committer: Diego Medina <email address hidden>
branch nick: bug-fixes
timestamp: Sun 2009-10-04 23:48:42 -0400
message:
  * On certain UPDATE and DELETE statements, drizzled failed an assert() in
     Diagnostic_area.
  ** Fixed by resetting m_status after "delete select"
  * Fixed LP bug#439719
  * Added test case