[MDEV-5887] Crash: page number outside the tablespace bounds - JIRA

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Not a Bug
Affects Version/s: 5.5.35
Fix Version/s: 5.5.39
Component/s: None
Labels:
None
Environment:
- Server DELL PowerEdge 2950 32 GB RAM, 2 x Intel Xeon CPU E5420@2.50GHz
- Linux Debian 7.4 (wheezy), ext4 filesystem
- Defined as a MySQL Slave using MIXED binlog format

Description

I had a crash on a MariaDB 5.5.35 slave with the following error (see below).

I have not much information about what was running at this moment, but wonder if someone have some tips or any known issues regarding such error trace ("access page [...] is outside the tablespace bounds").

Don't know if it may be related but I noticed I had a quite large sort_buffer_size in my.cnf (16MB, restored to its default value since). I recreated the slave instance and did not reproduced the problem though.

140311 14:46:06 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.5.35-MariaDB-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MariaDB Server
InnoDB: Error: trying to access page number 4294503295 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
140311 14:47:31  InnoDB: Assertion failure in thread 140687496423168 in file fil0fil.c line 5462
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.
140311 14:47:31 [ERROR] 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.

To report this bug, see http://kb.askmonty.org/en/reporting-bugs

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.

Server version: 5.5.35-MariaDB-log
key_buffer_size=536870912
read_buffer_size=1048576
max_used_connections=19
max_threads=502
thread_count=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 9272059 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x0
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 = 0x0 thread_stack 0x40000
mysys/stacktrace.c:247(my_print_stacktrace)[0xaed74e]
sql/signal_handler.cc:153(handle_fatal_signal)[0x6da40c]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf030)[0x7ff8feb9f030]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7ff8fdc6b475]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x7ff8fdc6e6f0]
fil/fil0fil.c:5512(_fil_io)[0x9a4266]
buf/buf0rea.c:239(buf_read_page_low)[0x97a59f]
buf/buf0rea.c:455(buf_read_page)[0x97b7c9]
buf/buf0buf.c:2577(buf_page_get_gen)[0x967cf1]
include/fut0fut.ic:53(fut_get_ptr)[0x9bb8fb]
fsp/fsp0fsp.c:2044(fsp_free_seg_inode)[0x9af565]
fsp/fsp0fsp.c:3603(fseg_free_step)[0x9b6c18]
trx/trx0purge.c:493(trx_purge_free_segment)[0x9285ef]
trx/trx0purge.c:655(trx_purge_truncate_history)[0x92a16a]
row/row0purge.c:749(row_purge)[0xa0fd26]
que/que0que.c:1259(que_thr_step)[0xa0533c]
trx/trx0purge.c:1229(trx_purge)[0x928c8b]
srv/srv0srv.c:4192(srv_purge_thread)[0x91c4dc]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7ff8feb96b50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7ff8fdd150ed]
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.
140311 14:47:32 mysqld_safe Number of processes running now: 0
140311 14:47:32 mysqld_safe mysqld restarted
140311 14:47:32 InnoDB: The InnoDB memory heap is disabled
140311 14:47:32 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140311 14:47:32 InnoDB: Compressed tables use zlib 1.2.3
140311 14:47:32 InnoDB: Using Linux native AIO
140311 14:47:32 InnoDB: Initializing buffer pool, size = 16.0G
140311 14:47:34 InnoDB: Completed initialization of buffer pool
140311 14:47:34 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
140311 14:47:34  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 65074994, file name mysql-bin.001125
InnoDB: and relay log file
InnoDB: position 65075278, file name ./relay-bin.000245
InnoDB: Last MySQL binlog file position 0 4668, file name /data/inetlog/mysql/mysql-bin.000005
140311 14:47:35  InnoDB: Waiting for the background threads to start
140311 14:47:36 Percona XtraDB (http://www.percona.com) 5.5.35-MariaDB-33.0 started; log sequence number 865880510567
140311 14:47:36 [Note] Plugin 'FEEDBACK' is disabled.
140311 14:47:36 [Note] Recovering after a crash using /data/inetlog/mysql/mysql-bin
140311 14:47:36 [Note] Starting crash recovery...
140311 14:47:36 [Note] Crash recovery finished.
140311 14:47:36 [Note] Server socket created on IP: '0.0.0.0'.
140311 14:47:36 [Warning] 'user' entry 'root@maroc' ignored in --skip-name-resolve mode.
140311 14:47:36 [Warning] 'proxies_priv' entry '@ root@maroc' ignored in --skip-name-resolve mode.
140311 14:47:36 [Note] Event Scheduler: Loaded 0 events
140311 14:47:36 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.5.35-MariaDB-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MariaDB Server
InnoDB: Error: trying to access page number 4294503295 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
140311 14:49:04  InnoDB: Assertion failure in thread 139631139989248 in file fil0fil.c line 5462
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.
140311 14:49:04 [ERROR] 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.

To report this bug, see http://kb.askmonty.org/en/reporting-bugs

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.

Server version: 5.5.35-MariaDB-log
key_buffer_size=536870912
read_buffer_size=1048576
max_used_connections=16
max_threads=502
thread_count=5
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 9272059 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x0
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 = 0x0 thread_stack 0x40000
mysys/stacktrace.c:247(my_print_stacktrace)[0xaed74e]
sql/signal_handler.cc:153(handle_fatal_signal)[0x6da40c]
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf030)[0x7f030aee5030]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7f0309fb1475]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x180)[0x7f0309fb46f0]
fil/fil0fil.c:5512(_fil_io)[0x9a4266]
buf/buf0rea.c:239(buf_read_page_low)[0x97a59f]
buf/buf0rea.c:455(buf_read_page)[0x97b7c9]
buf/buf0buf.c:2577(buf_page_get_gen)[0x967cf1]
include/fut0fut.ic:53(fut_get_ptr)[0x9bb8fb]
fsp/fsp0fsp.c:2044(fsp_free_seg_inode)[0x9af565]
fsp/fsp0fsp.c:3603(fseg_free_step)[0x9b6c18]
trx/trx0purge.c:493(trx_purge_free_segment)[0x9285ef]
trx/trx0purge.c:655(trx_purge_truncate_history)[0x92a16a]
row/row0purge.c:749(row_purge)[0xa0fd26]
que/que0que.c:1259(que_thr_step)[0xa0533c]
trx/trx0purge.c:1229(trx_purge)[0x928c8b]
srv/srv0srv.c:4192(srv_purge_thread)[0x91c4dc]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7f030aedcb50]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f030a05b0ed]
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.
140311 14:49:05 mysqld_safe Number of processes running now: 0
140311 14:49:05 mysqld_safe mysqld restarted
140311 14:49:05 InnoDB: The InnoDB memory heap is disabled
140311 14:49:05 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140311 14:49:05 InnoDB: Compressed tables use zlib 1.2.3
140311 14:49:05 InnoDB: Using Linux native AIO
140311 14:49:05 InnoDB: Initializing buffer pool, size = 16.0G
140311 14:49:07 InnoDB: Completed initialization of buffer pool
140311 14:49:07 InnoDB: highest supported file format is Barracuda.
InnoDB: The log sequence number in ibdata files does not match
InnoDB: the log sequence number in the ib_logfiles!
140311 14:49:07  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: In a MySQL replication slave the last master binlog file
InnoDB: position 65074994, file name mysql-bin.001125
InnoDB: and relay log file
InnoDB: position 65075278, file name ./relay-bin.000245
InnoDB: Last MySQL binlog file position 0 4668, file name /data/inetlog/mysql/mysql-bin.000005
140311 14:49:08  InnoDB: Waiting for the background threads to start
140311 14:49:09 Percona XtraDB (http://www.percona.com) 5.5.35-MariaDB-33.0 started; log sequence number 865880510717
140311 14:49:09 [Note] Plugin 'FEEDBACK' is disabled.
140311 14:49:09 [Note] Recovering after a crash using /data/inetlog/mysql/mysql-bin
140311 14:49:09 [Note] Starting crash recovery...
140311 14:49:09 [Note] Crash recovery finished.
140311 14:49:09 [Note] Server socket created on IP: '0.0.0.0'.
140311 14:49:09 [Warning] 'user' entry 'root@maroc' ignored in --skip-name-resolve mode.
140311 14:49:09 [Warning] 'proxies_priv' entry '@ root@maroc' ignored in --skip-name-resolve mode.
140311 14:49:10 [Note] Event Scheduler: Loaded 0 events
140311 14:49:10 [Note] /usr/local/mysql/bin/mysqld: ready for connections.
Version: '5.5.35-MariaDB-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MariaDB Server

Gliffy Diagrams

Attachments

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Elena Stepanova added a comment - 2014-03-17 16:28

Hi Nicolas,
What is the value of innodb_force_recovery in the server where you had the crashes?

Show

Elena Stepanova added a comment - 2014-03-17 16:28 Hi Nicolas, What is the value of innodb_force_recovery in the server where you had the crashes?

Hide

Permalink

Nicolas Payart added a comment - 2014-03-17 17:34

innodb_force_recovery was set to 0 (default).

We tried values from 1 to 3 without success (still crashing with innodb_force_recovery = 1 or 2 while server did not start with innodb_force_recovery = 3)

Show

Nicolas Payart added a comment - 2014-03-17 17:34 innodb_force_recovery was set to 0 (default). We tried values from 1 to 3 without success (still crashing with innodb_force_recovery = 1 or 2 while server did not start with innodb_force_recovery = 3)

Hide

Permalink

Elena Stepanova added a comment - 2014-03-17 20:37

Nicolas,

Was there any preceding story, e.g. you moved the datadir (or ib* files) from another machine, or modified config file, had disk/power problems, etc.?
Could you please attach your cnf file(s) and the complete error log, or at least the part from the last server start before the first time you observed the crash?

Thanks.

Show

Elena Stepanova added a comment - 2014-03-17 20:37 Nicolas, Was there any preceding story, e.g. you moved the datadir (or ib* files) from another machine, or modified config file, had disk/power problems, etc.? Could you please attach your cnf file(s) and the complete error log, or at least the part from the last server start before the first time you observed the crash? Thanks.

Hide

Permalink

Nicolas Payart added a comment - 2014-03-18 11:06

Unfortunately the datadir has been removed (slave has been rebuilt from scratch).
The error log from my first post is the only log trace I have...

From what I know there have been no system modification in the hours/days preceding the crash, nor dell omsa alert. I just noticed this error message in dmesg (PERC 6/i controller):

[   31.640010] megaraid_sas 0000:01:00.0: vpd r/w failed.  This is likely a firmware bug on this device.  Contact the card vendor for a firmware update.

Here is my.cnf :

[client]
port		= 3306
socket		= /var/run/mysqld/mysqld.sock


# This was formally known as [safe_mysqld]. Both versions are currently parsed.
[mysqld_safe]
socket          = /var/run/mysqld/mysqld.sock
nice            = 0


# The MariaDB server
[mysqld]
#
# * Basic Settings
#
user            = mysql
port		= 3306
socket		= /var/run/mysqld/mysqld.sock
pid-file        = /var/run/mysqld/mysqld.pid
basedir         = /usr/local/mysql
datadir         = /data/inetbase/mysql
tmpdir          = /data/inetlog/mysql
lc-messages-dir = /usr/local/mysql/share
lc-messages     = en_US
skip-external-locking
skip-name-resolve
max_connections = 500
connect_timeout = 10

#
# * Fine Tuning
#
tmp_table_size          = 256M
max_heap_table_size     = 256M
max_allowed_packet      = 16M
table_open_cache        = 4096
table_definition_cache  = 2048
sort_buffer_size        = 16M
read_buffer_size        = 1M
read_rnd_buffer_size    = 2M
thread_cache_size       = 64
thread_concurrency      = 8
thread_stack            = 256K
table_cache             = 65534
open_files_limit        = 65000
optimizer_switch        = engine_condition_pushdown=on


#
# * MyISAM Tuning
#
key_buffer_size         = 512M
key_cache_segments      = 32
key_cache_block_size    = 4K
myisam_sort_buffer_size = 128M
myisam-recover          = BACKUP

#
# * InnoDB Tuning
#
innodb_file_per_table
innodb_buffer_pool_size        = 16G
innodb_buffer_pool_instances   = 4
innodb_flush_log_at_trx_commit = 2
innodb_log_file_size           = 1G
innodb_log_files_in_group      = 2
innodb_log_buffer_size         = 128M
innodb_io_capacity             = 400
innodb_max_dirty_pages_pct     = 25
innodb_support_xa              = 0
innodb_stats_update_need_lock  = 0
innodb_thread_concurrency      = 128
innodb_open_files              = 8192

#
# * Query Cache Configuration
#
query_cache_type = 0
query_cache_size = 0

#
# * Logging and Replication
#
read-only
server-id	  = 3122
binlog_format     = MIXED
binlog_cache_size = 10M
max_binlog_size   = 100M
log-bin           = /data/inetlog/mysql/mysql-bin.log
relay-log         = relay-bin
expire_logs_days  = 3
skip-slave-start
log-slow-slave-statements
general_log_file        = /data/inetlog/mysql/mysql.log
general-log             = 0
slow_query_log_file     = /data/inetlog/mysql/mysql-slow.log
slow-query-log          = 1
long_query_time         = 0.250

[mysqldump]
quick
max_allowed_packet = 16M


[myisamchk]
key_buffer_size = 128M
sort_buffer_size = 128M
read_buffer = 2M
write_buffer = 2M


[mysqlhotcopy]
interactive-timeout

Show

Nicolas Payart added a comment - 2014-03-18 11:06 Unfortunately the datadir has been removed (slave has been rebuilt from scratch). The error log from my first post is the only log trace I have... From what I know there have been no system modification in the hours/days preceding the crash, nor dell omsa alert. I just noticed this error message in dmesg (PERC 6/i controller): [ 31.640010] megaraid_sas 0000:01:00.0: vpd r/w failed. This is likely a firmware bug on this device. Contact the card vendor for a firmware update. Here is my.cnf : [client] port = 3306 socket = /var/run/mysqld/mysqld.sock # This was formally known as [safe_mysqld]. Both versions are currently parsed. [mysqld_safe] socket = /var/run/mysqld/mysqld.sock nice = 0 # The MariaDB server [mysqld] # # * Basic Settings # user = mysql port = 3306 socket = /var/run/mysqld/mysqld.sock pid-file = /var/run/mysqld/mysqld.pid basedir = /usr/local/mysql datadir = /data/inetbase/mysql tmpdir = /data/inetlog/mysql lc-messages-dir = /usr/local/mysql/share lc-messages = en_US skip-external-locking skip-name-resolve max_connections = 500 connect_timeout = 10 # # * Fine Tuning # tmp_table_size = 256M max_heap_table_size = 256M max_allowed_packet = 16M table_open_cache = 4096 table_definition_cache = 2048 sort_buffer_size = 16M read_buffer_size = 1M read_rnd_buffer_size = 2M thread_cache_size = 64 thread_concurrency = 8 thread_stack = 256K table_cache = 65534 open_files_limit = 65000 optimizer_switch = engine_condition_pushdown=on # # * MyISAM Tuning # key_buffer_size = 512M key_cache_segments = 32 key_cache_block_size = 4K myisam_sort_buffer_size = 128M myisam-recover = BACKUP # # * InnoDB Tuning # innodb_file_per_table innodb_buffer_pool_size = 16G innodb_buffer_pool_instances = 4 innodb_flush_log_at_trx_commit = 2 innodb_log_file_size = 1G innodb_log_files_in_group = 2 innodb_log_buffer_size = 128M innodb_io_capacity = 400 innodb_max_dirty_pages_pct = 25 innodb_support_xa = 0 innodb_stats_update_need_lock = 0 innodb_thread_concurrency = 128 innodb_open_files = 8192 # # * Query Cache Configuration # query_cache_type = 0 query_cache_size = 0 # # * Logging and Replication # read-only server-id = 3122 binlog_format = MIXED binlog_cache_size = 10M max_binlog_size = 100M log-bin = /data/inetlog/mysql/mysql-bin.log relay-log = relay-bin expire_logs_days = 3 skip-slave-start log-slow-slave-statements general_log_file = /data/inetlog/mysql/mysql.log general-log = 0 slow_query_log_file = /data/inetlog/mysql/mysql-slow.log slow-query-log = 1 long_query_time = 0.250 [mysqldump] quick max_allowed_packet = 16M [myisamchk] key_buffer_size = 128M sort_buffer_size = 128M read_buffer = 2M write_buffer = 2M [mysqlhotcopy] interactive-timeout

Hide

Permalink

Elena Stepanova added a comment - 2014-05-22 22:55

Passing it to Jan Lindström to see if it looks any familiar.

Show

Elena Stepanova added a comment - 2014-05-22 22:55 Passing it to Jan Lindström to see if it looks any familiar.

Hide

Permalink

Jan Lindström added a comment - 2014-07-22 20:42

Possible reason: hw error. Please reopen if repeatable with 5.5.39.

Show

Jan Lindström added a comment - 2014-07-22 20:42 Possible reason: hw error. Please reopen if repeatable with 5.5.39.

People

Assignee:

Jan Lindström

Reporter:

Nicolas Payart

Votes:

0 Vote for this issue

Watchers:

5 Start watching this issue

Dates

Created:

2014-03-17 16:11

Updated:

2014-07-22 20:42

Resolved:

2014-07-22 20:42

Agile

View on Board