Failing assertion: (ulint) index == offsets[3] at rem0rec.ic line 973

[Elena Stepanova]

Version: '5.5.19-debug-log'

120113 21:55:09 InnoDB: Assertion failure in thread 2810686320 in file rem0rec.ic line 973
InnoDB: Failing assertion: (ulint) index == offsets[3]

#2 0x084939f4 in my_write_core (sig=6) at /home/elenst/Percona-Server-5.5.19-src/mysys/stacktrace.c:423
#3 0x0818ea21 in handle_segfault (sig=6) at /home/elenst/Percona-Server-5.5.19-src/sql/mysqld.cc:2600
#4 <signal handler called>
#5 0xffffe430 in __kernel_vsyscall ()
#6 0xb75607af in raise () from /lib/libc.so.6
#7 0xb75620f0 in abort () from /lib/libc.so.6
#8 0x0864d173 in rec_offs_validate (rec=0xb68944ec "\200", index=0x919cd88, offsets=0xa78796d4)
    at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/include/rem0rec.ic:973
#9 0x0865681a in lock_rec_queue_validate (block=0xaeaf0968, rec=0xb68944ec "\200", index=0x919cd88, offsets=0xa78796d4)
    at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/lock/lock0lock.c:4753
#10 0x08656fe9 in lock_rec_validate_page (block=0xaeaf0968) at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/lock/lock0lock.c:4962
#11 0x08657256 in lock_validate () at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/lock/lock0lock.c:5068
#12 0x08656242 in lock_print_info_all_transactions (file=0x8e45708)
    at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/lock/lock0lock.c:4577
#13 0x0856f2d2 in srv_printf_innodb_monitor (file=0x8e45708, nowait=1, trx_start=0x0, trx_end=0x0)
    at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/srv/srv0srv.c:2243
#14 0x0856fc7e in srv_monitor_thread (arg=0x0) at /home/elenst/Percona-Server-5.5.19-src/storage/innobase/srv/srv0srv.c:2560
#15 0xb7838b25 in start_thread () from /lib/libpthread.so.0

RQG test (run on a debug version of the server):

perl runall.pl \
--queries=10M \
--duration=300 \
--mysqld=--loose-innodb-flush-log-at-trx-commit=0 \
--threads=2 \
--grammar=assert.yy \
--gendata=assert.zz \
--engine=InnoDB \
--basedir=<path to the debug server> \
--vardir=<path to vardir>

# assert.yy

query:
        UPDATE _table SET _field_no_pk = _digit ;

# end of assert.yy

# assert.zz

$tables = {
        partitions => [ 'KEY (pk) PARTITIONS 2' ],
        rows => [ 10, 100 ]
};

$fields = {
        types => [ 'int' ],
        indexes => [ 'key' ],
        charsets => ['latin1']
};

$data = {
        numbers => [ 'digit' ],
}

# end of assert.zz

[Elena Stepanova (elenst)]

Also fails on Oracle MySQL 5.5.19 and 5.5.20, but could not reproduce on 5.6.4.

[Patrick Crews (patrick-crews)]

Elena,

Did you use any special build options / scripts / etc?
I've been testing and have not been able to repeat with Percona-Server or MySQL (5.5.19 and 5.5.20).
The only difference between my test and yours is that I am starting the server(s) with kewpie vs. runall.pl.
I'll investigate this further / try to duplicate the issue with just runall.pl, but thought this might be of interest / was curious about any additional information you could offer.

Thanks,
Patrick

[Elena Stepanova (elenst)]

Patrick,

For MySQL server, I used the release packages, e.g. mysql-5.5.20-linux2.6-i686.tar.gz, only mysqld-debug binary instead of mysqld.
Percona server was built with DCMAKE_BUILD_TYPE=Debug without any other options.

I used the standard RQG with options, grammar and data file as described above. Please note innodb-flush-log-at-trx-commit=0 -- on this particular grammar and data I couldn't reproduce the failure with the default value 1 (although i've seen it with the default value on other, more complicated tests). Please make sure this option is picked up by your server startup utility.

The tests were run on a 1-core i686 machine and on a 8-core x86_64 box, both with openSUSE 11.3; in each case, the assertion would fail soon after the test start.

[sbester (sbester)]

i hit this constantly when running own tests on 5.5-debug. have filed an oracle bug for it now.

[sbester (sbester)]

FYI, Oracle Bug 13614558 - DEBUG BUILD, INNODB_LOCK_MONITOR: FAILING ASSERTION: (ULINT) INDEX == OFFSETS[3]

[Patrick Crews (patrick-crews)]

Ok, thanks for this additional input. I hope to take a deeper look soon and will try OpenSuse. I've been running on Ubuntu 64 bit for my tests so far.
I am setting the innodb-flush-log-at-trx-commit value, but not seeing this crash
Thanks again for the update.

[sbester (sbester)]

Trying running SHOW ENGINE INNODB STATUS in a loop over and over. It has same problem as lock monitor, except lock monitor only runs every 15 seconds. I repeat it reliably on windows, so OS is no problem.. If speed is an issue, put everything on ramdisk :)

[Elena Stepanova (elenst)]

Also filed as JIRA issue MDEV-109

[Elena Stepanova (elenst)]

Hi,

This bug has been hanging in 'Incomplete' for quite a while (in percona-server project). Do you expect any more information from my side? The problem still exists in current percona-server, revno 258. If you have a problem reproducing it, please try the grammar with the addition suggested by sbester above:

# assert.yy

query:
        UPDATE _table SET _field_no_pk = _digit ;

thread1:
        SHOW ENGINE INNODB STATUS ;

# end of assert.yy

Also, please try to increase the number of threads and the duration of the test, e.g.:

perl runall.pl \
--queries=10M \
--duration=600 \
--mysqld=--loose-innodb-flush-log-at-trx-commit=0 \
--threads=4 \
--grammar=assert.yy \
--gendata=assert.zz \
--engine=InnoDB \
--basedir=<path to the debug server> \
--vardir=<path to vardir>

It fails for me every time I run it.

As said before, I build percona-server as
cmake . -DCMAKE_BUILD_TYPE=Debug && make
No other build options.

[Alexey Kopytov (akopytov)]

Hi Elena,

No, I don't think this bug is waiting on you now, I'm changing the status to Confirmed, it looks like the available information should be sufficient for whoever will be working on this bug. Thank you for your help with it.

[sbester (sbester)]

i haven't been able to repeat this on official mysql 5.5.23 or higher. 5.5.21 and 5.5.22 crashed in seconds though.

[Alexey Kopytov (akopytov)]

Shane,

Thanks for the update. We should re-verify this against recent PS versions then.

[Raghavendra D Prabhu (raghavendra-prabhu)]

Crash confirmed with latest bzr trunk (290.2.6) with runall.pl and details provided above.

Creating Directories
Installing Master Database
=======================================================

TEST RESULT TIME (ms)
-------------------------------------------------------

Servers started, exiting
# 2012-09-06T01:38:09 Starting: gentest.pl --gendata=/home/raghu/assert.zz --engine=InnoDB --threads=4 --queries=10M --duration=600 --dsn=dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test --grammar=/home/raghu/assert.yy
# 2012-09-06T01:38:09 -------------------------------
# 2012-09-06T01:38:09 Configuration
# 2012-09-06T01:38:09 dsn => ['dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test']
# 2012-09-06T01:38:09 duration => 600
# 2012-09-06T01:38:09 engine => InnoDB
# 2012-09-06T01:38:09 gendata => /home/raghu/assert.zz
# 2012-09-06T01:38:09 generator => FromGrammar
# 2012-09-06T01:38:09 grammar => /home/raghu/assert.yy
# 2012-09-06T01:38:09 queries => 10M
# 2012-09-06T01:38:09 reporters => ['']
# 2012-09-06T01:38:09 seed => 1
# 2012-09-06T01:38:09 threads => 4
# 2012-09-06T01:38:09 transformers => ['']
# 2012-09-06T01:38:09 validators => ['']
# 2012-09-06T01:38:09 # Creating MySQL table: test.table10_innodb_key_pk_parts_2_int_autoinc; engine: innodb; rows: 10 .
# 2012-09-06T01:38:09 # Creating MySQL table: test.table100_innodb_key_pk_parts_2_int_autoinc; engine: innodb; rows: 100 .
# 2012-09-06T01:38:09 Loading Generator GenTest::Generator::FromGrammar.
# 2012-09-06T01:38:10 Caching schema metadata for dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test
# 2012-09-06T01:38:10 Reporters: ErrorLog, Backtrace
# 2012-09-06T01:38:10 Validators: ErrorMessageCorruption
# 2012-09-06T01:38:10 Starting 4 processes, 10M queries each, duration 600 seconds.
# 2012-09-06T01:38:10 GenTest::ErrorFilter(2627) started
# 2012-09-06T01:38:10 Loading Validator GenTest::Validator::ErrorMessageCorruption.
# 2012-09-06T01:38:10 Loading Validator GenTest::Validator::ErrorMessageCorruption.
# 2012-09-06T01:38:11 Loading Validator GenTest::Validator::ErrorMessageCorruption.
# 2012-09-06T01:38:11 Loading Validator GenTest::Validator::ErrorMessageCorruption.
# 2012-09-06T01:38:11 Started periodic reporting process...
# 2012-09-06T01:42:44 Query: SHOW ENGINE INNODB STATUS failed: 2013 Lost connection to MySQL server during query
# 2012-09-06T01:42:44 Server crash reported at dsn dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test
# 2012-09-06T01:42:44 Query: UPDATE `table100_innodb_key_pk_parts_2_int_autoinc` SET `col_int_key` = 4 failed: 2013 Lost connection to MySQL server during query
# 2012-09-06T01:42:44 Server crash reported at dsn dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test
# 2012-09-06T01:42:44 Query: UPDATE `table100_innodb_key_pk_parts_2_int_autoinc` SET `col_int_key` = 1 failed: 2013 Lost connection to MySQL server during query
# 2012-09-06T01:42:44 Server crash reported at dsn dbi:mysql:host=127.0.0.1:port=19300:user=root:database=test
# 2012-09-06T01:42:44 Query: UPDATE `table100_innodb_key_pk_parts_2_int_autoinc` SET `col_int_key` = 7 failed: 2013 Lost...

[Valerii Kravchuk (valerii-kravchuk)]

I can not reproduce the crash with debug build of current Percona Server 5.6.15:

openxs@ao756:~/bzr/randgen$ perl runall.pl --queries=10M --duration=300 --mysqld=--loose-innodb-flush-log-at-trx-commit=0 --threads=2 --grammar=/tmp/assert.yy --gendata=/tmp/assert.zz --engine=InnoDB --basedir=/home/openxs/dbs/p5.6 --vardir=/tmp/p5.6debug
# 2014-02-03T17:58:35 Copyright (c) 2008,2011 Oracle and/or its affiliates. All rights reserved. Use is subject to license terms.
# 2014-02-03T17:58:35 Please see http://forge.mysql.com/wiki/Category:RandomQueryGenerator for more information on this test framework.
# 2014-02-03T17:58:35 Starting: runall.pl --queries=10M --duration=300 --mysqld=--loose-innodb-flush-log-at-trx-commit=0 --threads=2 --grammar=/tmp/assert.yy --gendata=/tmp/assert.zz --engine=InnoDB --basedir=/home/openxs/dbs/p5.6 --vardir=/tmp/p5.6debug
# 2014-02-03T17:58:35 master_port : 19300 slave_port : 19302 master_ports : 19300 19302 MTR_BUILD_THREAD : 930
# 2014-02-03T17:58:35 /home/openxs/bzr/randgen Revno: 948
# 2014-02-03T17:58:35 /home/openxs/bzr/randgen Revision-Id: <email address hidden>
# 2014-02-03T17:58:36 /home/openxs/dbs/p5.6 does not look like a bzr branch, cannot get revision info.
# 2014-02-03T17:58:36 Running perl mysql-test-run.pl --start-and-exit --mysqld=--innodb --skip-ndb --mysqld=--core-file --mysqld=--loose-new --mysqld=--default-storage-engine=InnoDB --mysqld=--sql-mode=no_engine_substitution --mysqld=--relay-log=slave-relay-bin --mysqld=--loose-innodb --mysqld=--secure-file-priv= --mysqld=--max-allowed-packet=16Mb --mysqld=--loose-innodb-status-file=1 --mysqld=--master-retry-count=65535 --mysqld=--loose-debug-assert-if-crashed-table --mysqld=--loose-debug-assert-on-error --mysqld=--skip-name-resolve --vardir=/tmp/p5.6debug --master_port=19300 --mysqld="--loose-innodb-flush-log-at-trx-commit=0" 1st 2>&1 .
=======================================================
  WARNING: Using mysql-test-run.pl version 1!
=======================================================
Logging: lib/v1/mysql-test-run.pl --start-and-exit --mysqld=--innodb --skip-ndb --mysqld=--core-file --mysqld=--loose-new --mysqld=--default-storage-engine=InnoDB --mysqld=--sql-mode=no_engine_substitution --mysqld=--relay-log=slave-relay-bin --mysqld=--loose-innodb --mysqld=--secure-file-priv= --mysqld=--max-allowed-packet=16Mb --mysqld=--loose-innodb-status-file=1 --mysqld=--master-retry-count=65535 --mysqld=--loose-debug-assert-if-crashed-table --mysqld=--loose-debug-assert-on-error --mysqld=--skip-name-resolve --vardir=/tmp/p5.6debug --master_port=19300 --mysqld=--loose-innodb-flush-log-at-trx-commit=0 1st
2014-02-03 17:58:36 20011 [Note] Plugin 'FEDERATED' is disabled.
2014-02-03 17:58:36 20011 [Note] Binlog end
2014-02-03 17:58:36 20011 [Note] Shutting down plugin 'CSV'
2014-02-03 17:58:36 20011 [Note] Shutting down plugin 'MyISAM'
MySQL Version 5.6.15
Using dynamic switching of binlog format
Using default engine 'InnoDB'
Skipping ndbcluster
Setting mysqld to support SSL connections
Binaries are debug compiled
Using MTR_BUILD_THREAD = 930
Using MASTER_MYPORT = 19300
Using MASTER_MYPORT1 = 19301
Using SL...

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-536