InnoDB: Assertion failure in thread <nr> in file buf0buf.c line 2608 (Sig6 in buf_page_get_gen / btr_copy_blob_prefix)

[Roel Van de Paar]

(gdb) bt
#0 0x00000038e260bd72 in pthread_kill () from /lib64/libpthread.so.0
#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 () from /lib64/libc.so.6
#4 0x00000038e1631d30 in abort () from /lib64/libc.so.6
#5 0x0000000000874fa4 in buf_page_get_gen (space=148, zip_size=0, offset=49, rw_latch=1, guess=0x0, mode=10,
    file=0xa9fac8 "/home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/btr/btr0cur.c", line=5179,
    mtr=0x40af21a0) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/buf/buf0buf.c:2608
#6 0x0000000000858929 in btr_copy_blob_prefix (buf=0x149d4ef0 "", len=11312, space_id=148, page_no=49, offset=38)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/btr/btr0cur.c:5179
#7 0x000000000086196e in btr_copy_externally_stored_field_prefix_low (offset=128, page_no=18446744073709551615, space_id=6, zip_size=<optimized out>, len=11312,
    buf=0x30d <Address 0x30d out of bounds>)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/btr/btr0cur.c:5389
#8 btr_copy_externally_stored_field (heap=<optimized out>, local_len=0, zip_size=<optimized out>, data=<optimized out>, len=<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/btr/btr0cur.c:5495
#9 btr_rec_copy_externally_stored_field (rec=<optimized out>, offsets=<optimized out>, zip_size=0, no=<optimized out>, len=0x40af2740, heap=<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/btr/btr0cur.c:5549
#10 0x0000000000813d4d in row_sel_store_mysql_rec (mysql_rec=0x143e42b8 "\200?\024\002", prebuilt=0x143f5398, rec=0x2aaab0dda268 "", rec_clust=0, offsets=0x40af2d70)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/row/row0sel.c:2761
#11 0x00000000008161cf in row_search_for_mysql (buf=0x143e42b8 "\200?\024\002", mode=2, prebuilt=0x143f5398, match_mode=1, direction=0)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/storage/innobase/row/row0sel.c:4610
#12 0x00000000007e797b in ha_innobase::index_read (this=0x14b370c0, buf=0x143e42b8 "\200?\024\002", key_ptr=<optimized out>, key_len=<optimized out>, find_flag=HA_READ_KEY_EXACT)
    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:6765
#13 0x0000000000696911 in handler::index_read_idx_map (this=0x14b370c0, buf=0x143e42b8 "\200?\024\002", index=<optimized out>, key=0x40af31d0 "",
    keypart_map=18446744073709551615, find_flag=HA_READ_KEY_EXACT)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/handler.cc:4959
#14 0x000000000056792f in write_record (thd=0x1470ba70, table=0x14a7bd30, info=0x40af3870)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_insert.cc:1612
#15 0x000000000056e464 in mysql_insert (thd=0x1470ba70, table_list=0x1413d5e0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_UPDATE, ignore=true)
    at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_insert.cc:956
#16 0x000000000057ee0c in mysql_execute_command (thd=0x1470ba70)
    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:3065
#17 0x0000000000583113 in mysql_parse (thd=0x1470ba70, rawbuf=<optimized out>, length=<optimized out>, parser_state=0x40af4df0)
    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
#18 0x00000000005845da in dispatch_command (command=COM_QUERY, thd=0x1470ba70, packet=<optimized out>, packet_length=129)
    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
#19 0x0000000000584966 in do_command (thd=0x1470ba70)
    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
#20 0x00000000006224c1 in do_handle_one_connection (thd_arg=<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
#21 0x00000000006225b4 in handle_one_connection (arg=<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
#22 0x00000038e260677d in start_thread () from /lib64/libpthread.so.0
#23 0x00000038e16d3c1d in clone () from /lib64/libc.so.6
#24 0x0000000000000000 in ?? ()
(gdb) frame 19
#19 0x0000000000584966 in do_command (thd=0x1470ba70)
    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
788 /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.1/sql/sql_parse.cc: No such file or directory.
(gdb) p thd->query_string.string.str
$1 = 0x1413d3a0 "INSERT IGNORE INTO `view_table500_innodb_dynamic` ( `c10` ) VALUES ( 'then' ) ON DUPLICATE KEY UPDATE `c5` = 9967591875277750272"

[Roel Van de Paar (roel11)]

Related to bug 1086680 and/or bug 1083058 ?

[Roel Van de Paar (roel11)]

Note to self: fusion1 - 104 - 478

[Roel Van de Paar (roel11)]

Error log:

121204 5:04:23 [Note] /data/ssd/qa/Percona-Server-5.5.28-rel29.1-359.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.5.28-rel29.1-log' socket: '/data/ssd/qa/104/current1_6/tmp/master.sock' port: 13100 Percona Server with XtraDB (GPL), Release rel29.1, Revision 359
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "test/table500_innodb_dynamic_int_autoinc"
[... above message repeated 3x ...]
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "c34" table: "test/table500_innodb_dynamic"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "c34" table: "test/table500_innodb_dynamic"
121204 5:06:23 InnoDB: Error: trying to access tablespace 148 page no. 49,
InnoDB: but the tablespace does not exist or is just being dropped.
[... above message repeated many times ...]
121204 5:06:23 InnoDB: Error: trying to access tablespace 148 page no. 49,
InnoDB: but the tablespace does not exist or is just being dropped.
InnoDB: Error: Unable to read tablespace 148 page no 49 into the buffer pool after 100 attempts
InnoDB: The most probable cause of this error may be that the table has been corrupted.
InnoDB: You can try to fix this problem by using innodb_force_recovery.
InnoDB: Please see reference manual for more details.
InnoDB: Aborting...
121204 5:06:23 InnoDB: Assertion failure in thread 1085233472 in file buf0buf.c line 2608
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.
02:06:23 UTC - mysqld got signal 6 ;

[Roel Van de Paar (roel11)]

PS: Percona-Server-5.5.28-rel29.1
RQG: 794 <email address hidden>

[Roel Van de Paar (roel11)]

Script that was used (to be tested for reproducibility):

bash -c "set -o pipefail; perl runall.pl --queries=100000000 --seed=random --duration=300 --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/Percona-Server-5.5.28-rel29.1-359.Linux.x86_64 --threads=1 --views --notnull --validator=Transformer --mysqld=--slow_query_log --mysqld=--innodb_lazy_drop_table=1 --mysqld=--innodb_file_per_table=1 --mysqld=--innodb_file_format=barracuda --mtr-build-thread=310 --mask=34693 --vardir1=/data/ssd/qa/104/current1_6 > /data/ssd/qa/1

[Roel Van de Paar (roel11)]

seed => 5646

[Laurynas Biveinis (laurynas-biveinis)]

As this is with lazy drop table, one way this could be occurring that page->was_being_deleted is not checked in some place it should be.

[Valerii Kravchuk (valerii-kravchuk)]

Is this fixed in 5.5.28-29.2, by any chance?

[Stewart Smith (stewart)]

Valerii Kravchuk <email address hidden> writes:
> Is this fixed in 5.5.28-29.2, by any chance?

No. Unless it's been unexpectedly fixed by another change.
--
Stewart Smith

[Roel Van de Paar (roel11)]

Had another occurrence:

===============
130122 11:11:05 [Note] /ssd/Percona-Server-5.5.28-rel29.3-415.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.5.29-rel29.3-log' socket: '/tmp/bug2/tmp/master.sock' port: 13100 Percona Server with XtraDB (GPL), Release rel29.3, Revision 415
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "test/table500_innodb_dynamic_int_autoinc"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "test/table500_innodb_dynamic_int_autoinc"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "test/table500_innodb_dynamic_int_autoinc"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "test/table500_innodb_dynamic_int_autoinc"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "c34" table: "test/table500_innodb_dynamic"
InnoDB: Warning: hash index ref_count (2) is not zero after fil_discard_tablespace().
index: "c34" table: "test/table500_innodb_dynamic"
130122 11:27:25 InnoDB: Error: trying to access tablespace 148 page no. 49,
InnoDB: but the tablespace does not exist or is just being dropped.
130122 11:27:25 InnoDB: Error: trying to access tablespace 148 page no. 49,
InnoDB: but the tablespace does not exist or is just being dropped.
[.... same ....]
130122 11:27:25 InnoDB: Error: trying to access tablespace 148 page no. 49,
InnoDB: but the tablespace does not exist or is just being dropped.
InnoDB: Error: Unable to read tablespace 148 page no 49 into the buffer pool after 100 attempts
InnoDB: The most probable cause of this error may be that the table has been corrupted.
InnoDB: You can try to fix this problem by using innodb_force_recovery.
InnoDB: Please see reference manual for more details.
InnoDB: Aborting...
130122 11:27:25 InnoDB: Assertion failure in thread 140277794035456 in file buf0buf.c line 2612
===============

=============== +bt
#0 0x0000003da180c60c in pthread_kill () from /lib64/libpthread.so.0
#1 0x000000000069386f in handle_fatal_signal (sig=6) at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/sql/signal_handler.cc:249
#2 <signal handler called>
#3 0x0000003da1435935 in raise () from /lib64/libc.so.6
#4 0x0000003da14370e8 in abort () from /lib64/libc.so.6
#5 0x000000000086cb0e in buf_page_get_gen (space=148, zip_size=zip_size@entry=0, offset=offset@entry=49, rw_latch=rw_latch@entry=1, guess=<optimized out>, guess@entry=0x0, mode=mode@entry=10, file=file@entry=0xa72430 "/ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/storage/innobase/btr/btr0cur.c", line=line@entry=5181
, mtr=mtr@entry=0x7f94f8152210) at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/storage/innobase/buf/buf0buf.c:2612
#6 0x000000000084ef19 in btr_copy_blob_prefix (buf=0x7f94da417620 "", len=len@entry=11312, space_id=space_id@entry=148, page_no=page_no@entry=49, offset=38) at /ssd/QA-16274-5.5/Percona-Server-5.5.28-rel29.3/storage/innobase/btr/btr0cur.c:5181
#7 0x000000000085bf0f in btr_copy_externally_stored_field_prefix_low (off...

[Roel Van de Paar (roel11)]

Another occurrence - but note the slightly different asserting location

===============
130122 12:00:15 InnoDB: Error: trying to access tablespace 148 page no. 49,
InnoDB: but the tablespace does not exist or is just being dropped.
InnoDB: Error: Unable to read tablespace 148 page no 49 into the buffer pool after 100 attempts
InnoDB: The most probable cause of this error may be that the table has been corrupted.
InnoDB: You can try to fix this problem by using innodb_force_recovery.
InnoDB: Please see reference manual for more details.
InnoDB: Aborting...
130122 12:00:15 InnoDB: Assertion failure in thread 140452384491264 in file buf0buf.c line 2608
===============

[Roel Van de Paar (roel11)]

(Bug is single threaded reproducible, and last two occurrences above are confirmed single threaded)

[Roel Van de Paar (roel11)]

See bug 1116447

[Eric H (eric-hardway)]

I ran into this bug on both Percona 5.1.66 and Percona 5.1.67

From my testing I believe this bug happens when I have innodb_lazy_drop_table enabled and I issue a drop schema after the buffer pool is warmed up. I have been able to duplicate the bug twice by using pt-archiver to warm up buffer pool then issuing a drop database command.

When I issue the drop schema command the instance freezes with the exception that you can still do a show process list but you cannot do anything else including read from MyISAM tables. The drop schema command sticks on checking permissions.

| 16 | sanitized | sanitized:44918 | archive_sanitized | Query | 529 | checking permissions | drop schema archive_sanitized

The only way I can get out of this frozen state is to shutdown mysql. Then I have corrupted innodb table space and I am unable to clear the error the innodb recovery techniques outlined in manual. The only way I am able to recover is to dump out my innodb tables and delete ibdata and ib_logfiles and re-import my data.

Version: '5.1.66rel14.2-log' socket: '/san/analytics/analytics.sock' port: 3306 Percona Server with XtraDB (GPL), Release rel14.2, Revision 501
130208 22:00:56 InnoDB: Completed reading buffer pool pages (requested: 229486, read: 229474)
InnoDB: Warning: hash index ref_count (6467) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Warning: hash index ref_count (22975) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 5 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 10 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 15 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 20 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 25 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 30 secs for hash index ref_count (161) to drop to 0.
index: "idx_sanitized_date_created" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 35 secs for hash index ref_count (161) to drop to 0.

Version: '5.1.67rel14.3-log' socket: '/san/analytics/analytics.sock' port: 3306 Percona Server with XtraDB (GPL), Release rel14.3, Revision 50
6
InnoDB: Warning: hash index ref_count (4715) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 5 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 10 secs for hash index ref_count (4715) to drop to 0.
index: "PRIMARY" table: "archive_sanitized/sanitized_2004"
InnoDB: Error: Waited for 15 ...

[Teodor Milkov (tm-del)]

We are seing something very similar here with 5.5.29-rel29.4:

InnoDB: error in sec index entry update in
InnoDB: index "expire" of table "drupal"."cache_views"
InnoDB: tuple DATA TUPLE: 2 fields;
 0: len 4; hex 80000000; asc ;;
 1: len 13; hex 76696577735f646174613a656e; asc views_data:en;;

InnoDB: record PHYSICAL RECORD: n_fields 2; compact format; info bits 32
 0: len 4; hex 80000000; asc ;;
 1: len 30; hex 756e7061636b5f6f7074696f6e733a656265646361623631656562316138; asc unpack_options:ebedcab61eeb1a8; (total 50 bytes);

TRANSACTION 2AA58139, ACTIVE 0 sec updating or deleting
mysql tables in use 1, locked 1
18 lock struct(s), heap size 1024, 50 row lock(s), undo log entries 40
MySQL thread id 249170, OS thread handle 0xb64ffb70, query id 58302445 localhost qpbonbou updating
DELETE FROM cache_views

InnoDB: Submit a detailed bug report to http://bugs.mysql.com
InnoDB: Warning: hash index ref_count (10) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "drupal/cache_field"
InnoDB: Warning: hash index ref_count (1) is not zero after fil_discard_tablespace().
index: "expire" table: "drupal/cache_views"
InnoDB: Warning: hash index ref_count (3) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "drupal/cache"
InnoDB: Warning: hash index ref_count (1) is not zero after fil_discard_tablespace().
index: "PRIMARY" table: "drupal/cache_bootstrap"

...

Query (aa67380): SELECT cid, data, created, expire, serialized FROM cache WHERE cid IN ('entity_info:en')

Unfortunatelly, I've no scriptable way to reproduce it, but with this somewhat heavy Drupal site, it crashes 3-4 times daily.

[Teodor Milkov (tm-del)]

Also isn't this related to https://bugs.launchpad.net/percona-server/+bug/1086227

[Shahriyar Rzayev (rzayev-sehriyar)]

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