Random randgen test failures

[Lee Bieber]

As of build version 1235, we are getting random test failures with randgen. See http://hudson.drizzle.org/view/Drizzle-staging/job/Drizzle-randgen-staging/107/console as an example.

On orisndriz05, cd to repos/randgen and then run the script ./f.sh starts drizzled (build 1245) and runs the test. It will fail approximately ever 3rd or 4th try. Build version 1245 has been compiled with debug information.

# 09:07:19 Starting
# 09:07:19 ./gentest.pl \
# 09:07:19 --dsn=dbi:drizzle:host=localhost:port=9306:user=root:password=:database=test \
# 09:07:19 --queries=500 \
# 09:07:19 --threads=10 \
# 09:07:19 --gendata=conf/combinations_drizzle.zz \
# 09:07:19 --grammar=conf/combinations.yy \
# 09:07:19 --engine=Innodb
# 09:07:19 Executor initialized, id GenTest::Executor::Drizzle 2009.12.1245 ()
# 09:07:19 # Creating table table0_innodb_int_autoinc .
# 09:07:19 # Creating table table1_innodb_int_autoinc .
# 09:07:19 # Creating table table2_innodb_int_autoinc .
# 09:07:19 Query: INSERT /*! IGNORE */ INTO table2_innodb_int_autoinc VALUES ('i', 'n', 'z', '1593180160', NULL, 'g', 'I\'ll', 'r', 'wemegyaluzytnccflbvqnqnmfvvlhitckzgppyilihmleccmmxqxcilxqvfikqseftdkgtlqzbwpucapktdeqxndcqytizhxaaiyashf', '4', '4', '2002-09-18 16:27:07', 't', '2009', NULL, '2004', '2004-10-05') , ('vwemegyaluzytnccflbvqnqn', 'f', 'really', '1', NULL, 'b', 'o', 't', 'why', '611450880', '2', '2004-04-14 06:29:37', 'w', '2001-07-16 04:09:22', NULL, '2005-04-16', '2002') failed: 1686 Received an invalid datetime value '%d'.. Further errors of this kind will be suppressed.
# 09:07:19 # Creating table table10_innodb_int_autoinc .
# 09:07:19 # Creating table table100_innodb_int_autoinc .
# 09:07:19 Reporters: ErrorLog, Backtrace
# 09:07:19 Validators: ErrorMessageCorruption
# 09:07:19 Starting 10 processes, 500 queries each, duration 3600 seconds.
# 09:07:19 Executor initialized, id GenTest::Executor::Drizzle 2009.12.1245 ()
# 09:07:19 Query: INSERT INTO `table1_innodb_int_autoinc` ( `enum_not_null` ) VALUES ( '20040912034947' ) failed: 1364 Field 'int_not_null' doesn't have a default value. Further errors of this kind will be suppressed.
# 09:07:19 Query: UPDATE `table1_innodb_int_autoinc` SET `datetime_not_null` = "you're" failed: 1686 Received an invalid datetime value 'you're'.. Further errors of this kind will be suppressed.
.......lots of output.
# 09:07:20 Executor initialized, id GenTest::Executor::Drizzle 2009.12.1245 ()
# 09:07:20 Executor initialized, id GenTest::Executor::Drizzle 2009.12.1245 ()
DBD::drizzle::dr connect warning: drizzle_state_read:lost connection to server (104) at /usr/local/lib/perl/5.10.0/DBI.pm line 653.
# 09:07:20 connect() to dsn dbi:drizzle:host=localhost:port=9306:user=root:password=:database=test failed: drizzle_state_read:lost c
onnection to server (104)
# 09:07:20 Started periodic reporting process...
# 09:07:21 Killing periodic reporting process with pid 19112...
# 09:07:21 Test completed with failure status 34.
One can only use the --user switch if running as root
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins.
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
091204 9:07:16 InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
091204 9:07:17 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
091204 9:07:17 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./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
091204 9:07:17 InnoDB Plugin 1.0.4 started; log sequence number 0
Listening on 0.0.0.0:9307
Listening on :::9307
Listening on 0.0.0.0:9306
Listening on :::9306
./drizzled/drizzled: Forcing close of thread 0 user: ''
./drizzled/drizzled: ready for connections.
Version: '2009.12.1245' Source distribution (staging-randgen-randgen-r1245)
091204 9:07:20 - drizzled got signal 11;
This could be because you hit a bug. It i091204 9:07:21 InnoDB: Shutdown completed; log sequence number 118485
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=6
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: 0x21f4510
drizzled: field/varstring.cc:90: virtual int Field_varstring::store(const char*, uint32_t, const CHARSET_INFO*): Assertion `!table || (table->write_set == __null || isWriteSet())' failed.
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...
Fatal signal 6 while backtracing

[Lee Bieber (kalebral-deactivatedaccount)]

I get this from the core file that is generated:

Core was generated by `/usr/bin/perl ./gentest.pl --dsn=dbi:drizzle:host=localhost:port=9306:user=root'.
Program terminated with signal 11, Segmentation fault.
[New process 6232]
#0 drizzle_result_column_count (result=0x0) at libdrizzle/result.c:155
155 {
(gdb) where
#0 drizzle_result_column_count (result=0x0) at libdrizzle/result.c:155
#1 0x00000010fcb53730 in ?? ()
#2 0x00000000017fd010 in ?? ()
#3 0x0000000001810200 in ?? ()
#4 0x00000000017fd010 in ?? ()
#5 0x0000000001f0b110 in ?? ()
#6 0x0000000001f2be90 in ?? ()
#7 0x000000004e1bc0b2 in ?? ()
#8 0x0000003000000018 in ?? ()
#9 0x00007fff0655b600 in ?? ()
#10 0x00007fff0655b540 in ?? ()
#11 0x0000000000000028 in ?? ()
#12 0x00000000000202b0 in ?? ()
#13 0x0000000001f4ed50 in ?? ()
#14 0x00007fadfd925a00 in ?? () from /lib/libc.so.6
#15 0x00007fadfd63453f in calloc () from /lib/libc.so.6
#16 0x00007fadfe553670 in ?? ()
#17 0x0000000000000005 in ?? ()
#18 0x0000000000000008 in ?? ()
#19 0x00000000be582cf9 in ?? ()
#20 0x00007fadfe347c2c in ?? () from /lib64/ld-linux-x86-64.so.2
#21 0x00007fadfe3480e0 in ?? () from /lib64/ld-linux-x86-64.so.2
#22 0x00007fadfe34832e in ?? () from /lib64/ld-linux-x86-64.so.2
#23 0x00007fadfe34c70a in ?? () from /lib64/ld-linux-x86-64.so.2
#24 0x0000000001e77300 in ?? ()
#25 0x0000000001e77300 in ?? ()
#26 0x00007fadfd63aa05 in memmove () from /lib/libc.so.6
#27 0x00007fadfe093fcb in Perl_sv_setpvn () from /usr/lib/libperl.so.5.10
#28 0x00007fadfbefcf9f in drizzle_dr_error (h=<value optimized out>, rc=<value optimized out>,
    what=0x2000000000 <Address 0x2000000000 out of bounds>, sqlstate=0x1ed80a6 "HY000") at dbdimp.c:801
#29 0x00007fadfbefedc0 in drizzle_st_internal_execute (h=0x1f23dc0, statement=<value optimized out>,
    attribs=<value optimized out>, num_params=0, params=0x0, result=0x1f30460, con=0x1f30890, unbuffered_result=0) at dbdimp.c:1955
#30 0x00007fadfbeff4d8 in drizzle_st_execute (sth=0x1f23dc0, imp_sth=0x1f303a0) at dbdimp.c:2048
#31 0x00007fadfbf06f77 in XS_DBD__drizzle__st_execute (my_perl=<value optimized out>, cv=<value optimized out>) at drizzle.xsi:588
#32 0x00007fadfcb51a2e in XS_DBI_dispatch (my_perl=0x17fd010, cv=0x1b3a840) at DBI.xs:3292
#33 0x00007fadfe07c6d0 in Perl_pp_entersub () from /usr/lib/libperl.so.5.10
#34 0x00007fadfe07a972 in Perl_runops_standard () from /usr/lib/libperl.so.5.10
#35 0x00007fadfe078d5f in perl_run () from /usr/lib/libperl.so.5.10
#36 0x0000000000400d4c in main ()

[Brian Aker (brianaker)]

Hi!

On Dec 4, 2009, at 9:22 AM, Lee Bieber wrote:

> drizzled: field/varstring.cc:90: virtual int Field_varstring::store(const char*, uint32_t, const CHARSET_INFO*): Assertion `!table || (table->write_set == __null || isWriteSet())' failed.

Yes, this is a bitmap bug.

Cheers,
 -Brian

[Jay Pipes (jaypipes)]

Looking into the drizzle.err log file:

http://hudson.drizzle.org/view/Drizzle-staging/job/Drizzle-randgen-staging/113/console

I saw that the query which triggers this is:

SHOW FIELDS FROM table10_innodb_int_autoinc

I will create, hopefully, a test case which repeats the failure.

Cheers,

Jay

[Lee Bieber (kalebral-deactivatedaccount)]

Above test case doesn't repeat the failure. I ran with valgrind and am attaching the logfile for when it core dumps

[Lee Bieber (kalebral-deactivatedaccount)]

Valgrind log file

[Brian Aker (brianaker)]

Another bit of info:

#3 0x00000036d7c74576 in malloc_printerr (action=3, str=0x36d7d3dca8 "double free or corruption (!prev)", ptr=<value optimized out>) at malloc.c:6264
#4 0x00007fffce3261b7 in ~InfoSchemaRecord (this=<value optimized out>, __in_chrg=<value optimized out>) at ./drizzled/plugin/info_schema_table.h:235
#5 operator()<drizzled::plugin::InfoSchemaRecord> (this=<value optimized out>, __in_chrg=<value optimized out>) at ./drizzled/plugin/info_schema_table.h:290
#6 for_each<__gnu_cxx::__normal_iterator<drizzled::plugin::InfoSchemaRecord**, std::vector<drizzled::plugin::InfoSchemaRecord*, std::allocator<drizzled::plugin::InfoSchemaRecord*> > >, drizzled::plugin::DeleteRows> (this=<value optimized out>, __in_chrg=<value optimized out>) at /usr/lib/gcc/x86_64-redhat-linux/4.4.2/../../../../include/c++/4.4.2/bits/stl_algo.h:4200
#7 clearRows (this=<value optimized out>, __in_chrg=<value optimized out>) at ./drizzled/plugin/info_schema_table.h:526
#8 InformationCursor::rnd_init (this=<value optimized out>, __in_chrg=<value optimized out>) at plugin/information_engine/information_cursor.cc:66
#9 0x0000000000765608 in Cursor::ha_rnd_init (this=0x7fff74008348, scan=<value optimized out>) at drizzled/cursor.cc:101

[Brian Aker (brianaker)]

bzr push lp:~brianaker/drizzle/concurrency-IS

The above has a test case in it that triggers the bug.

[Jay Pipes (jaypipes)]

Awesome! :)

Thanks,

Jay

Brian Aker wrote:
> bzr push lp:~brianaker/drizzle/concurrency-IS
>
> The above has a test case in it that triggers the bug.
>

[Stewart Smith (stewart)]

http://bazaar.launchpad.net/~stewart-flamingspork/drizzle/concurrency-IS/revision/1254

[Stewart Smith (stewart)]

I_S is very broken in regard to thread safety. This is the simpler patch that fixes it (at about the total expense of concurrency).

The more complex fix is to have InformationCursor get a copy of the rows and just use them.

that patch is much.. much larger (got about 1/2 way there)

[Jay Pipes (jaypipes)]

Looking at your patch on that branch for r1254, I fail to see why this
is necessary at all. InformationCursor's methods should not need any
locking calls inside of it, nor should a pthread_mutex_t be necessary as
a data member of InformationCursor, because an InformationCursor should
be local to a Session object. Are we now moving towards an era of
having shareable Cursors? I thought that's where the TableShare was used?

Or am I missing something here?

To me, this bug is caused by the read/write bitmaps not being set
properly inside some InformationSchemaTable calls...

-jay

Stewart Smith wrote:
> I_S is very broken in regard to thread safety. This is the simpler patch
> that fixes it (at about the total expense of concurrency).
>
> The more complex fix is to have InformationCursor get a copy of the rows
> and just use them.
>
> that patch is much.. much larger (got about 1/2 way there)
>

[Stewart Smith (stewart)]

yeah, you missed something :)

The mutex is in InfoSchemaTable, which inherits from Plugin. i.e. it's a singleton

the std::vector<InfoSchemaRecord *> which is filled out with rows in fillTable is in InfoSchemaTable, which is a singleton in the server, leading to much fail in the InformationCursor code when more than one is running at once.

[Jay Pipes (jaypipes)]

Gotcha.

Thanks for the conversation, I understand the problem much better now.

Cheers!

Jay

[Lee Bieber (kalebral-deactivatedaccount)]

Attaching the output and log file when running with valgrind from the latest failure as of build 1320

See complete log of the run at http://hudson.drizzle.org/job/drizzle-lee-test/134/console

[Lee Bieber (kalebral-deactivatedaccount)]

attaching valgrind log file from a non-debug build per request from Brian

[Lee Bieber (kalebral-deactivatedaccount)]

See https://bugs.launchpad.net/bugs/534806 and https://bugs.launchpad.net/bugs/534790 which narrow down the problem

[Brian Aker (brianaker)]

Hi!

On Apr 20, 2010, at 11:24 AM, Lee Bieber wrote:

> drizzled: field/varstring.cc:90: virtual int Field_varstring::store(const char*, uint32_t, const CHARSET_INFO*): Assertion `!table || (table->write_set == __null || isWriteSet())' failed.

Bitfield issues. We have no compressive test on those at the moment. Engines are not safe to use them as a means for testing anything but BLOBs.

Cheers,
 -Brian

[Stewart Smith (stewart)]

On Tue, 20 Apr 2010 18:37:13 -0000, Brian Aker <email address hidden> wrote:
> On Apr 20, 2010, at 11:24 AM, Lee Bieber wrote:
>
> > drizzled: field/varstring.cc:90: virtual int
> Field_varstring::store(const char*, uint32_t, const CHARSET_INFO*):
> Assertion `!table || (table->write_set == __null || isWriteSet())'
> failed.
>
> Bitfield issues. We have no compressive test on those at the moment.
> Engines are not safe to use them as a means for testing anything but
> BLOBs.

The API is a little obscure, but it should work. This is how we do
partial row fetch/set (to save disk reads or network hops). Anything
hitting these asserts should be considered a bug and be fixed.

If using the Field classes to do read row for this, it's pretty simple
to get it going right.

--
Stewart Smith