Bug #69993 innodb tries to access tablespace that does not exist or is just being dropped
Submitted: 12 Aug 2013 10:36 Modified: 19 Nov 2013 13:48
Reporter: Michael Ivanov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Memcached Severity:S2 (Serious)
Version:5.6.13 OS:Linux (CentOS 5)
Assigned to: CPU Architecture:Any
Tags: mysql crash memcached innodb tablespace

[12 Aug 2013 10:36] Michael Ivanov
Description:
MySQL server with innodb memcached plugin installed crashes once in a several days with the following error message:

2013-08-10 01:45:41 2bb44b4c3940  InnoDB: Error: trying to access tablespace 1933194298 page no. 578381153,
InnoDB: but the tablespace does not exist or is just being dropped.

...skip same error 100 times ...

2013-08-10 01:45:41 2bb44b4c3940  InnoDB: Error: trying to access tablespace 1933194298 page no. 578381153,
InnoDB: but the tablespace does not exist or is just being dropped.
InnoDB: Error: Unable to read tablespace 1933194298 page no 578381153 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...
2013-08-10 01:45:41 2bb44b4c3940  InnoDB: Assertion failure in thread 48053357394240 in file buf0buf.cc line 2565

... skip ...

Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x907a15]
/usr/sbin/mysqld(handle_fatal_signal+0x3e8)[0x670408]
/lib64/libpthread.so.0[0x31f0e0eca0]
/lib64/libc.so.6(gsignal+0x35)[0x31f0630265]
/lib64/libc.so.6(abort+0x110)[0x31f0631d10]
/usr/sbin/mysqld[0xa2f3ac]
/usr/sbin/mysqld[0xa10c8a]
/usr/sbin/mysqld[0xa15ae9]
/usr/sbin/mysqld[0xa00ea2]
/usr/sbin/mysqld[0xa010f7]
/usr/lib64/mysql/plugin//innodb_engine.so(innodb_api_search+0x119)[0x2bb448031c39]
/usr/lib64/mysql/plugin//innodb_engine.so[0x2bb448030337]
/usr/lib64/mysql/plugin/libmemcached.so[0x2ba1abd7de8a]
/usr/lib64/mysql/plugin/libmemcached.so[0x2ba1abd81a0a]
/usr/lib64/mysql/plugin/libmemcached.so[0x2ba1abd83832]
/usr/lib64/mysql/plugin/libmemcached.so(conn_parse_cmd+0x11)[0x2ba1abd84311]
/usr/lib64/mysql/plugin/libmemcached.so[0x2ba1abd7a92e]
/usr/lib64/mysql/plugin/libmemcached.so(event_base_loop+0x379)[0x2ba1abd8acc9]
/usr/lib64/mysql/plugin/libmemcached.so[0x2ba1abd88112]
/lib64/libpthread.so.0[0x31f0e0683d]
/lib64/libc.so.6(clone+0x6d)[0x31f06d4f8d]

As a side note I need to mention that the MySql data is located on RAID-10 with battery backup so the hardware IO corruption is not likely to be the case.

Here is my.cnf
[mysqld]
socket                          = /var/lib/mysql/mysql.sock
skip-name-resolve
sql-mode                        = NO_ENGINE_SUBSTITUTION
event-scheduler                 = 1

log_warnings                    = 0

max_connect_errors              = 10000
open-files-limit                = 65535
optimizer_search_depth          = 15

## Cache
thread-cache-size               = 16
table-open-cache                = 25K
table-definition-cache          = 2048
query-cache-size                = 0 
query-cache-limit               = 128K
loose-daemon_memcached_option   = "-m 30720"

## Per-thread Buffers
sort-buffer-size                = 16M
read-buffer-size                = 2M
read-rnd-buffer-size            = 8M
join-buffer-size                = 2M

## Temp Tables
tmp-table-size                  = 64M 
max-heap-table-size             = 64M 

## Networking
back-log                        = 100
open-files-limit                = 65535
max-connections                 = 500
max-connect-errors              = 10000
max-allowed-packet              = 128M
interactive-timeout             = 600
wait-timeout                    = 100

### Storage Engines
default-storage-engine          = InnoDB
innodb                          = FORCE

## MyISAM
key-buffer-size                 = 1G
myisam-sort-buffer-size         = 256M

## InnoDB
innodb_buffer_pool_size         = 70G
innodb_additional_mem_pool_size = 128M
innodb_log_file_size            = 1G
innodb_log_files_in_group       = 8
innodb_log_buffer_size          = 16M
innodb_file_per_table           = 1
innodb_open_files               = 8K
innodb_read_io_threads          = 64
innodb_write_io_threads         = 64
innodb_flush_method             = O_DIRECT
innodb_flush_log_at_trx_commit  = 2
innodb_use_native_aio           = 0
innodb_buffer_pool_instances    = 1

And the structure of memcached container:

CREATE TABLE `memcached` (
  `c1` varchar(255) NOT NULL DEFAULT '',
  `c2` mediumtext,
  `c3` int(11) DEFAULT NULL,
  `c4` bigint(20) unsigned DEFAULT NULL,
  `c5` int(11) DEFAULT NULL,
  PRIMARY KEY (`c1`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8

select * from containers;
+------+-----------+-----------+-------------+---------------+-------+------------+--------------------+------------------------+
| name | db_schema | db_table  | key_columns | value_columns | flags | cas_column | expire_time_column | unique_idx_name_on_key |
+------+-----------+-----------+-------------+---------------+-------+------------+--------------------+------------------------+
| aaa  | memcached | memcached | c1          | c2            | c3    | c4         | c5                 | PRIMARY                |
+------+-----------+-----------+-------------+---------------+-------+------------+--------------------+------------------------+

select * from cache_policies;
+--------------+------------+------------+---------------+--------------+
| policy_name  | get_policy | set_policy | delete_policy | flush_policy |
+--------------+------------+------------+---------------+--------------+
| cache_policy | caching    | caching    | caching       | caching      |
+--------------+------------+------------+---------------+--------------+

How to repeat:
Install MySQL with memcached plugin and use the settings above. Generate read/write intensive workload for long period of time.
[19 Aug 2013 10:08] Michael Ivanov
After upgrading to 5.6.13 the above crash seems gone for a week. But today I got a different crash. Here is the error log:

2013-08-19 03:49:25 2b6cc855d940  InnoDB: Assertion failure in thread 47746217531712 in file rem0rec.cc line 575

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x908fa5]
/usr/sbin/mysqld(handle_fatal_signal+0x3e8)[0x670848]
/lib64/libpthread.so.0[0x31f0e0eca0]
/lib64/libc.so.6(gsignal+0x35)[0x31f0630265]
/lib64/libc.so.6(abort+0x110)[0x31f0631d10]
/usr/sbin/mysqld[0xa05456]
/usr/sbin/mysqld[0xa73e62]
/usr/sbin/mysqld[0xa74287]
/usr/lib64/mysql/plugin//innodb_engine.so(innodb_api_search+0x11f)[0x2b6cc5b4edcf]
/usr/lib64/mysql/plugin//innodb_engine.so[0x2b6cc5b4d4a7]
/usr/lib64/mysql/plugin/libmemcached.so[0x2b5a28e99e8a]
/usr/lib64/mysql/plugin/libmemcached.so[0x2b5a28e9da0a]
/usr/lib64/mysql/plugin/libmemcached.so[0x2b5a28e9f832]
/usr/lib64/mysql/plugin/libmemcached.so(conn_parse_cmd+0x11)[0x2b5a28ea0311]
/usr/lib64/mysql/plugin/libmemcached.so[0x2b5a28e9692e]
/usr/lib64/mysql/plugin/libmemcached.so(event_base_loop+0x379)[0x2b5a28ea6cc9]
/usr/lib64/mysql/plugin/libmemcached.so[0x2b5a28ea4112]
/lib64/libpthread.so.0[0x31f0e0683d]
/lib64/libc.so.6(clone+0x6d)[0x31f06d4f8d]
[28 Aug 2013 3:05] KyungHoon Baek
got similar problem
when i tried set 1000count/sec it happend..

2013-08-27 23:50:50 7f0fd3486700  InnoDB: Assertion failure in thread 139705945974528 in file rem0rec.cc line 575
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
03:50:50 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked 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=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68229 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0 thread_stack 0x40000
/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x35)[0xa63680]
/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x3b0)[0x706ccc]
/lib64/libpthread.so.0[0x3275a0f500]
/lib64/libc.so.6(gsignal+0x35)[0x32752328a5]
/lib64/libc.so.6(abort+0x175)[0x3275234085]
/usr/local/mysql/bin/mysqld[0xbf52c4]
/usr/local/mysql/bin/mysqld[0xcb395e]
/usr/local/mysql/bin/mysqld[0xcb6007]
/usr/local/mysql/lib/plugin//innodb_engine.so(innodb_api_search+0x224)[0x7f0fd989a9dd]
/usr/local/mysql/lib/plugin//innodb_engine.so(innodb_api_store+0xa1)[0x7f0fd989c5b6]
/usr/local/mysql/lib/plugin//innodb_engine.so(+0xb65e)[0x7f0fd989965e]
/usr/local/mysql/lib/plugin/libmemcached.so(+0xa0f2)[0x7f12008640f2]
/usr/local/mysql/lib/plugin/libmemcached.so(+0x11bd9)[0x7f120086bbd9]
/usr/local/mysql/lib/plugin/libmemcached.so(+0x11c6a)[0x7f120086bc6a]
/usr/local/mysql/lib/plugin/libmemcached.so(conn_nread+0xaf)[0x7f1200872558]
/usr/local/mysql/lib/plugin/libmemcached.so(+0x19763)[0x7f1200873763]
/usr/local/mysql/lib/plugin/libmemcached.so(+0x22025)[0x7f120087c025]
/usr/local/mysql/lib/plugin/libmemcached.so(event_base_loop+0x1ec)[0x7f120087c3c1]
/usr/local/mysql/lib/plugin/libmemcached.so(+0x1e842)[0x7f1200878842]
/lib64/libpthread.so.0[0x3275a07851]
/lib64/libc.so.6(clone+0x6d)[0x32752e890d]
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
130827 23:50:50 mysqld_safe Number of processes running now: 0
130827 23:50:50 mysqld_safe mysqld restarted
[2 Sep 2013 12:42] Michael Ivanov
I confirmed the 1st type of error still exists on MySQL 5.6.13 resulting in crash

2013-08-22 12:47:05 2b5a787c6940  InnoDB: Error: trying to access tablespace 1667379511 page no. 825713969,
InnoDB: but the tablespace does not exist or is just being dropped
2013-08-22 12:47:05 2b5a787c6940  InnoDB: Assertion failure in thread 47667568470336 in file buf0buf.cc line 2565
[2 Sep 2013 13:09] KyungHoon Baek
setting memcached with 1 thread is ok.. but 2+ thread is problem
centos 5.3 / mysql 5.6.13
[2 Sep 2013 13:48] MySQL Verification Team
Within 5 minutes, I could repeat it easily enough on 5.6.13. I will do further tests and see about a simple testcase.

Version: '5.6.13'  socket: '/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)
 InnoDB_Memcached: failed to locate entry in config table 'containers' in database 'innodb_memcache'
 InnoDB_Memcached: failed to locate entry in config table 'containers' in database 'innodb_memcache'
 InnoDB_Memcached: failed to locate entry in config table 'containers' in database 'innodb_memcache'
 InnoDB_Memcached: failed to locate entry in config table 'containers' in database 'innodb_memcache'
 InnoDB_Memcached: failed to locate entry in config table 'containers' in database 'innodb_memcache'
InnoDB: Error: trying to access tablespace 66 page no. 12501,
InnoDB: but the tablespace does not exist or is just being dropped.
2

(gdb) bt
#0  in raise () from /lib64/libc.so.6
#1  in abort () from /lib64/libc.so.6
#2  in buf_page_get_gen  at ./storage/innobase/buf/buf0buf.cc:2565
#3  in btr_block_get_func  at ./storage/innobase/include/btr0btr.ic:60
#4  in btr_pcur_move_to_next_page  at ./storage/innobase/btr/btr0pcur.cc:432
#5  in btr_pcur_move_to_next  at ./storage/innobase/include/btr0pcur.ic:360
#6  in row_search_for_mysql  at ./storage/innobase/row/row0sel.cc:4967
#7  in ib_cursor_moveto  at ./storage/innobase/api/api0api.cc:2232
#8  in innodb_api_search at ./plugin/innodb_memcached/innodb_memcache/src/innodb_api.c:553
#9  in innodb_api_store at ./plugin/innodb_memcached/innodb_memcache/src/innodb_api.c:1457
#10 in innodb_store  at ./plugin/innodb_memcached/innodb_memcache/src/innodb_engine.c:1544
#11 in complete_nread  at ./plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:1078
#12 in conn_nread  at ./plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:5348
#13 in event_handler at ./plugin/innodb_memcached/daemon_memcached/daemon/memcached.c:5654
#14 in event_process_active at ./libevent/event.c:392
#15 in event_base_loop at ./libevent/event.c:544
#16 in worker_libevent at ./plugin/innodb_memcached/daemon_memcached/daemon/thread.c:304
#17 in start_thread () from /lib64/libpthread.so.0
#18 in clone () from /lib64/libc.so.6
(gdb)
[2 Sep 2013 13:51] MySQL Verification Team
In my case, crashes immediately if you simply run an insert thread into demo_test via the memcached plugin, then in a sql query run "truncate demo_test".
[2 Sep 2013 13:55] Michael Ivanov
Thanks for verification Shane. Though I do not run TRUNCATE operation on my memcached containter table. The only query I use is DELETE for deleting expired rows.
[2 Sep 2013 14:42] MySQL Verification Team
run in two threads, crashes instantly.

Attachment: bug69993.php (application/octet-stream, text), 2.27 KiB.

[2 Sep 2013 14:42] MySQL Verification Team
gdb output

Attachment: bug69993_5.6.15-debug.txt (text/plain), 68.16 KiB.

[3 Sep 2013 5:10] KyungHoon Baek
when i changed key and value column type varchar to char error is gone
[19 Nov 2013 13:48] Erlend Dahl
This has been fixed in 5.6.16 and 5.7.4.