Percona Server moved to https://jira.percona.com/projects/PS

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)

Bug #1086227 reported by Roel Van de Paar on 2012-12-04

This bug affects 11 people

	Status	Importance	Assigned to	Milestone
Percona Server moved to https://jira.percona.com/projects/PS	Invalid	Undecided	Laurynas Biveinis
5.1	Invalid	Undecided	Laurynas Biveinis
5.5	Fix Released	High	Laurynas Biveinis	Percona Server moved to https://jira.percona.com/projects/PS 5.5.30-30.2
5.6	Invalid	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

Tags:

Related branches

lp:~laurynas-biveinis/percona-server/rm-lazy-drop-table-5.5

Merged into lp:percona-server/5.5 at revision 496

Alexey Kopytov (community): Approve on 2013-04-04

Revision history for this message

Roel Van de Paar (roel11) wrote on 2012-12-04:

Error log Edit (1.4 MiB, text/plain)

Revision history for this message

Roel Van de Paar (roel11) wrote on 2012-12-04:

gdb trace Edit (42.3 KiB, text/plain)

Revision history for this message

Roel Van de Paar (roel11) wrote on 2012-12-04:

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

Revision history for this message

Roel Van de Paar (roel11) wrote on 2012-12-04:

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

Revision history for this message

Roel Van de Paar (roel11) wrote on 2012-12-04:

Ref Bug 897258

Stewart Smith (stewart) on 2012-12-10

tags:

added: crash

Revision history for this message

Roel Van de Paar (roel11) wrote on 2013-01-18:

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

Revision history for this message

Roel Van de Paar (roel11) wrote on 2013-01-22:

Ref bug 1086269

Laurynas Biveinis (laurynas-biveinis) on 2013-02-05

tags:

added: xtradb

Revision history for this message

Laurynas Biveinis (laurynas-biveinis) wrote on 2013-02-22:

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 564000147 192.168.100.183 root rename result table
ALTER TABLE `P3MessageLog` DROP FOREIGN KEY `FK_P3MessageLog_2`
TABLE LOCK table `SYS_TABLES` trx id 1AB6986D7 lock mode IS
RECORD LOCKS space id 0 page no 149827 n bits 208 index `CLUST_IND` of table `SYS_TABLES` trx id 1AB6986D7 lock mode S
RECORD LOCKS space id 0 page no 388855 n bits 240 index `CLUST_IND` of table `SYS_TABLES` trx id 1AB6986D7 lock mode S
TABLE LOCK table `SYS_FOREIGN` trx id 1AB6986D7 lock mode IS
RECORD LOCKS space id 0 page no 47 n bits 176 index `FOR_IND` of table `SYS_FOREIGN` trx id 1AB6986D7 lock mode S
TABLE LOCK table `SYS_INDEXES` trx id 1AB6986D7 lock mode IS
RECORD LOCKS space id 0 page no 97659 n bits 296 index `CLUST_IND` of table `SYS_INDEXES` trx id 1AB6986D7 lock mode S
TABLE LOCK table `SYS_STATS` trx id 1AB6986D7 lock mode IX
RECORD LOCKS space id 0 page no 154305 n bits 72 index `CLUST_IND` of table `SYS_STATS` trx id 1AB6986D7 lock_mode X
TABLE LOCK table `SYS_FIELDS` trx id 1AB6986D7 lock mode IX
TOO MANY LOCKS PRINTED FOR THIS TRX: SUPPRESSING FURTHER PRINTS
---TRANSACTION 1AB6986A5, ACTIVE 591 sec updating or deleting
mysql tables in use 2, locked 2
1695 lock struct(s), heap size 162232, 18815 row lock(s)
MySQL thread id 73516470, OS thread handle 0x4e2cb940, query id 564000093 192.168.100.179 ubt.globS3.mysql Updating
UPDATE
        P3Machine
      SET
        CoreVersion='1.9.0.8',
        WindowsVersion='Microsoft Windows NT 5.1.2600 Service Pack 3',
        InstalledPrograms='***
TABLE LOCK table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock mode IX
RECORD LOCKS space id 98133 page no 17 n bits 80 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 18 n bits 88 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 29 n bits 88 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 64 n bits 88 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 81 n bits 88 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 94 n bits 88 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 105 n bits 80 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 128 n bits 80 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
RECORD LOCKS space id 98133 page no 149 n bits 88 index `PRIMARY` of table `ubt_streamline`.`P3Machine` trx id 1AB6986A5 lock_mode X
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: "FK_P3MessageLog_1" table: "ubt_streamline/#sql2-3162-461c5b7"
InnoDB: Error: Waited for 595 secs for hash index ref_count (1) to drop to 0.
index: "FK_P3MessageLog_1" table: "ubt_streamline/#sql2-3162-461c5b7"
InnoDB: Error: Waited for 600 secs for hash index ref_count (1) to drop to 0.
index: "FK_P3MessageLog_1" table: "ubt_streamline/#sql2-3162-461c5b7"
130227  3:18:04  InnoDB: Assertion failure in thread 1305430336 in file dict0dict.c line 1883

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

Revision history for this message

Matthew Kent (mkent) wrote on 2013-03-09:

#10

drop_table_crash.txt Edit (41.7 KiB, text/plain)

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.

Revision history for this message

George Ormond Lorch III (gl-az) wrote on 2013-03-13:

#11

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

Revision history for this message

George Ormond Lorch III (gl-az) wrote on 2013-03-13:

#12

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

Revision history for this message

Raghavendra D Prabhu (raghavendra-prabhu) wrote on 2013-03-18:

#13

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)?

Revision history for this message

Shahriyar Rzayev (rzayev-sehriyar) wrote on 2018-01-25:

#14

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

Report a bug

This report contains Public information

Everyone can see this information.

Duplicates of this bug

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

Bug watches keep track of this bug in other bug trackers.