Percona Server with XtraDB

InnoDB: Assertion failure in thread <nr> in file dict0dict.c line 1883 | in dict_index_remove_from_cache | on ALTER TABLE (related to Bug 897258)

Reported by Roel Van de Paar on 2012-12-04
48
This bug affects 11 people
Affects Status Importance Assigned to Milestone
Percona Server
Status tracked in 5.6
5.1
Undecided
Laurynas Biveinis
5.5
High
Laurynas Biveinis
5.6
Undecided
Laurynas Biveinis

Bug Description

============= Core file
Program terminated with signal 6, Aborted.
#0 0x00000038e260af59 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
(gdb) t 4
[Switching to thread 4 (Thread 32221)]#0 __pthread_kill (threadid=<value optimized out>, signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:75
75 return (INTERNAL_SYSCALL_ERROR_P (val, err)
(gdb) bt
#0 __pthread_kill (threadid=<value optimized out>, signo=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:75
#1 0x0000000000695e23 in handle_fatal_signal (sig=6)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/signal_handler.cc:249
#2 <signal handler called>
#3 0x00000038e1630285 in raise (sig=<value optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#4 0x00000038e1631d30 in abort () at abort.c:88
#5 0x000000000088f9b4 in dict_index_remove_from_cache (table=0x4c62798, index=0xe86e398)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/dict/dict0dict.c:1883
#6 0x00000000008958ad in dict_table_remove_from_cache (table=0x4c62798)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/dict/dict0dict.c:1253
#7 0x000000000080c471 in row_drop_table_for_mysql (name=<value optimized out>, trx=0x15a2ecb8, drop_db=<value optimized out>)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/row/row0mysql.c:3547
#8 0x00000000007edd11 in ha_innobase::delete_table (this=<value optimized out>, name=0x15071250 "./test/#sql2-4b20-a")
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/handler/ha_innodb.cc:8382
#9 0x000000000069c021 in ha_delete_table (thd=0x163a9e20, table_type=0x4dbb450, path=0x7ddd <Address 0x7ddd out of bounds>, db=0x5f1b048 "test", alias=0x15073110 "#sql2-4b20-a",
    generate_warning=false) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/handler.cc:2211
#10 0x00000000005e167d in quick_rm_table (base=0x4dbb450, db=0x5f1b048 "test", table_name=0x15073110 "#sql2-4b20-a", flags=0)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_table.cc:2409
#11 0x00000000005e3e70 in mysql_alter_table (thd=0x163a9e20, new_db=0x5f1b048 "test", new_name=0x5f1aa98 "table100_innodb_default", create_info=0x15073750, table_list=0x5f1ab20,
    alter_info=0x15073830, order_num=0, order=0x0, ignore=false)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_table.cc:6997
#12 0x00000000007bc960 in Alter_table_statement::execute (this=<value optimized out>, thd=0x163a9e20)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_alter.cc:106
#13 0x000000000057f831 in mysql_execute_command (thd=0x163a9e20)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_parse.cc:4582
#14 0x0000000000583113 in mysql_parse (thd=0x163a9e20, rawbuf=<value optimized out>, length=<value optimized out>, parser_state=0x15074df0)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_parse.cc:5811
#15 0x00000000005845da in dispatch_command (command=COM_QUERY, thd=0x163a9e20, packet=<value optimized out>, packet_length=72)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_parse.cc:1061
#16 0x0000000000584966 in do_command (thd=0x163a9e20)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_parse.cc:788
#17 0x00000000006224c1 in do_handle_one_connection (thd_arg=<value optimized out>)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_connect.cc:1484
#18 0x00000000006225b4 in handle_one_connection (arg=<value optimized out>)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_connect.cc:1391
#19 0x00000038e260677d in start_thread (arg=<value optimized out>) at pthread_create.c:301
#20 0x00000038e16d3c1d in clone () from /lib64/libc.so.6
(gdb) f 16
#16 0x0000000000584966 in do_command (thd=0x163a9e20)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_parse.cc:788
(gdb) p thd->query_string.string.str
$1 = 0x5f1a970 "ALTER TABLE `table100_innodb_default` MODIFY `c45` BLOB NULL AFTER `c4`"

============= Error log
InnoDB: Error: Waited for 600 secs for hash index ref_count (1) to drop to 0.
index: "c32" table: "test/#sql2-4b20-a"
121203 3:48:15 InnoDB: Assertion failure in thread 352803136 in file dict0dict.c line 1883
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
00:48:15 UTC - mysqld got signal 6 ;

============= Info
The error log shows the same stack trace as seen in bug 897258. The testcase there apparently did not generate the same issue anymore. However, this crash above was seen using RQG testing in release Percona-Server-5.5.28-rel29.1-359.Linux.x86_64

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

fusion1:/data/ssd/qa/102/trial12

Roel Van de Paar (roel11) wrote :

Bug is reproducible with an RQG initiating script like this:

$ cat cmd12
ps -ef | grep 'cmdrun_12' | grep -v grep | awk '{print $2}' | xargs sudo kill -9
rm -Rf /data/ssd/qa/102/cmdrun_12
mkdir /data/ssd/qa/102/cmdrun_12
cd /data/ssd/qa/102/randgen
bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=23926 --duration=600 --querytimeout=60 --short_column_names --sqltrace --reporter=Shutdown,Backtrace,QueryTimeout,ErrorLog,ErrorLogAlarm --mysqld=--log-output=none --mysqld=--sql_mode=ONLY_FULL_GROUP_BY --grammar=conf/percona_qa/percona_qa.yy --gendata=conf/percona_qa/percona_qa.zz --basedir=/data/ssd/qa/102/Percona-Server-5.5.28-rel29.1-359.Linux.x86_64 --valgrind --reporter=ValgrindErrors --validator=MarkErrorLog --threads=1 --views --mysqld=--userstat --mysqld=--innodb_lazy_drop_table=1 --mysqld=--innodb_file_per_table=1 --mtr-build-thread=784 --mask=53932 --vardir1=/data/ssd/qa/102/cmdrun_12 > /data/ssd/qa/102/cmdrun12.log 2>&1"

Versions:
randgen Revno: 792 | Revision-Id: <email address hidden>
PS Percona-Server-5.5.28-rel29.1-359.Linux.x86_64

Roel Van de Paar (roel11) wrote :
Stewart Smith (stewart) on 2012-12-10
tags: added: crash
Roel Van de Paar (roel11) wrote :

Bug still seen in Percona-Server-5.5.28-rel29.2 on 2013-01-09

Roel Van de Paar (roel11) wrote :
tags: added: xtradb

See also bug 1086700.

Przemek (pmalkowski) wrote :
Download full text (6.6 KiB)

Two more examples of this bug hit (Percona Server 5.5.28-29.3-log), one occur during optimize table, second during alter table:

-------------------------------------------------------------------------------------------------------

---TRANSACTION 18F02058A, ACTIVE 590 sec updating or deleting
mysql tables in use 2, locked 2
2 lock struct(s), heap size 376, 1 row lock(s)
MySQL thread id 121533385, OS thread handle 0x4c78b940, query id 933988129 192.168.100.179 ubt.globS3.mysql Updating
UPDATE
        P3Machine
      SET
        TamperStatus=0,
        MonitorStatus=(MonitorStatus & ~(1 | 8 | 16 | 32)),

        LastStatusUpdate=CURRENT_TIMESTAMP,
        LastHandshake=CURRENT_TIMESTAMP,
        UpgradeStatus=0
      WHERE
        Id = 30016713
      LIMIT 1
TABLE LOCK table `ubt_streamline`.`P3Machine` trx id 18F02058A lock mode IX
RECORD LOCKS space id 88886 page no 30041 n bits 80 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 18F02058A lock_mode X locks rec but not gap
---TRANSACTION 18F020587, ACTIVE 590 sec dropping table
18 lock struct(s), heap size 3112, 27 row lock(s), undo log entries 14
MySQL thread id 121519857, OS thread handle 0x4eb99940, query id 933988100 localhost root rename result table
OPTIMIZE TABLE `P3ConfigurationValue`
TABLE LOCK table `SYS_TABLES` trx id 18F020587 lock mode IS
RECORD LOCKS space id 0 page no 61095 n bits 208 index `CLUST_IND` of table `SYS_TABLES` trx id 18F020587 lock mode S
RECORD LOCKS space id 0 page no 388855 n bits 240 index `CLUST_IND` of table `SYS_TABLES` trx id 18F020587 lock mode S
TABLE LOCK table `SYS_FOREIGN` trx id 18F020587 lock mode IS
RECORD LOCKS space id 0 page no 47 n bits 176 index `FOR_IND` of table `SYS_FOREIGN` trx id 18F020587 lock mode S
TABLE LOCK table `SYS_INDEXES` trx id 18F020587 lock mode IS
RECORD LOCKS space id 0 page no 94396 n bits 288 index `CLUST_IND` of table `SYS_INDEXES` trx id 18F020587 lock mode S
TABLE LOCK table `SYS_STATS` trx id 18F020587 lock mode IX
RECORD LOCKS space id 0 page no 154305 n bits 72 index `CLUST_IND` of table `SYS_STATS` trx id 18F020587 lock_mode X
TABLE LOCK table `SYS_FIELDS` trx id 18F020587 lock mode IX
TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: Error: Waited for 590 secs for hash index ref_count (1) to drop to 0.
index: "PRIMARY" table: "devubt_streamline/#sql2-16ae-73e3ef1"
InnoDB: Error: Waited for 595 secs for hash index ref_count (1) to drop to 0.
index: "PRIMARY" table: "devubt_streamline/#sql2-16ae-73e3ef1"
130210 6:17:47 [Warning] Too many connections
InnoDB: Error: Waited for 600 secs for hash index ref_count (1) to drop to 0.
index: "PRIMARY" table: "devubt_streamline/#sql2-16ae-73e3ef1"
130210 6:17:51 InnoDB: Assertion failure in thread 1320786240 in file dict0dict.c line 1883

-------------------------------------------------------------------------------------------------------

---TRANSACTION 1AB6986D7, ACTIVE 591 sec dropping table
18 lock struct(s), heap size 3112, 29 row lock(s), undo log entries 16
MySQL thread id 73516471, OS thread handle 0x4dcf4940, query id 564000...

Read more...

Matthew Kent (mkent) wrote :

Believe we experienced the same bug here today with innodb_lazy_drop_table = 1

Routine drop table on a 3 day old database with all of 50MB of data locked up the server for 600 seconds. When it came back one of the tables was in a strange state where innodb claims it's broken.

See attached error log.

I reproduced this as well while trying to reproduce https://bugs.launchpad.net/percona-server/+bug/1086700.

I should add this was don on the current 5.5 trunk, revno 466.

Is this related to lp:1128848 and lp:1154558 - both of which seem to be related to innodb_lazy_drop_table, and in turn to adaptive hash index (AHI)?

To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers