Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.0.28, 10.0.29, 10.0.30
-
RHEL6, x86_64, VMWare, wheezy
Description
3 times now in the last 6 months or so we've had a random signal 6 crash corrupt a single ibd file by actually overwriting the top it with the error message. (which I assume was meant for the log file instead)
I've attached the corrupted file as an example. I've confirmed this occurs in 10.0.28 and 10.0.29. Here's the error data from the correct log file:
2017-02-27 01:25:07 7f50466df700 InnoDB: Assertion failure in thread 139982755723008 in file buf0lru.cc line 2245
|
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.
|
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0xb924ab]
|
/usr/sbin/mysqld(handle_fatal_signal+0x3b6)[0x739136]
|
/lib64/libpthread.so.0[0x323120f7e0]
|
/lib64/libc.so.6(gsignal+0x35)[0x3230e325e5]
|
/lib64/libc.so.6(abort+0x175)[0x3230e33dc5]
|
/usr/sbin/mysqld[0x9c86c9]
|
/usr/sbin/mysqld[0x8db7d5]
|
/usr/sbin/mysqld[0x9280e8]
|
/usr/sbin/mysqld[0x8835ff]
|
/usr/sbin/mysqld(_Z8closefrmP5TABLEb+0x3a)[0x67c43a]
|
/usr/sbin/mysqld(_Z18intern_close_tableP5TABLE+0x59)[0x59a609]
|
/usr/sbin/mysqld(_Z8tc_purgeb+0x285)[0x6e88f5]
|
/usr/sbin/mysqld(_Z19close_cached_tablesP3THDP10TABLE_LISTbm+0x8f)[0x5a317f]
|
/usr/sbin/mysqld(_Z20reload_acl_and_cacheP3THDyP10TABLE_LISTPi+0x3ce)[0x6c023e]
|
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x4889)[0x5e3899]
|
/usr/sbin/mysqld[0x5e5a97]
|
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c6c)[0x5e7e6c]
|
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6a6f13]
|
/usr/sbin/mysqld(handle_one_connection+0x42)[0x6a6fe2]
|
/lib64/libpthread.so.0[0x3231207aa1]
|
/lib64/libc.so.6(clone+0x6d)[0x3230ee8aad]
|
170227 01:25:09 mysqld_safe Number of processes running now: 0
|
170227 01:25:09 mysqld_safe mysqld restarted
|
170227 1:25:09 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB) starting as process 23465 ...
|
170227 1:25:09 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
170227 1:25:09 [Note] InnoDB: The InnoDB memory heap is disabled
|
170227 1:25:09 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
170227 1:25:09 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
|
170227 1:25:09 [Note] InnoDB: Compressed tables use zlib 1.2.3
|
170227 1:25:09 [Note] InnoDB: Using Linux native AIO
|
170227 1:25:10 [Note] InnoDB: Using CPU crc32 instructions
|
170227 1:25:10 [Note] InnoDB: Initializing buffer pool, size = 7.0G
|
170227 1:25:10 [Note] InnoDB: Completed initialization of buffer pool
|
170227 1:25:10 [Note] InnoDB: Highest supported file format is Barracuda.
|
170227 1:25:10 [Note] InnoDB: Log scan progressed past the checkpoint lsn 6877178025086
|
170227 1:25:10 [Note] InnoDB: Database was not shutdown normally!
|
170227 1:25:10 [Note] InnoDB: Starting crash recovery.
|
170227 1:25:10 [Note] InnoDB: Reading tablespace information from the .ibd files...
|
170227 1:28:01 [ERROR] InnoDB: Space id in fsp header 1851878432,but in the page header 544434535
|
170227 1:28:01 [ERROR] InnoDB: innodb-page-size mismatch in tablespace ./optometrydb/page_manager_handlers.ibd (table optometrydb/page_manager_handlers)
|
170227 1:28:01 [Note] InnoDB: Page size:1024 Pages to analyze:64
|
170227 1:28:01 [Note] InnoDB: Page size: 1024, Possible space_id count:0
|
170227 1:28:01 [Note] InnoDB: Page size:2048 Pages to analyze:64
|
170227 1:28:01 [Note] InnoDB: Page size: 2048, Possible space_id count:0
|
170227 1:28:01 [Note] InnoDB: Page size:4096 Pages to analyze:32
|
170227 1:28:01 [Note] InnoDB: Page size: 4096, Possible space_id count:0
|
170227 1:28:01 [Note] InnoDB: Page size:8192 Pages to analyze:16
|
170227 1:28:01 [Note] InnoDB: Page size: 8192, Possible space_id count:0
|
170227 1:28:01 [Note] InnoDB: Page size:16384 Pages to analyze:8
|
170227 1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:1 page_size:16384
|
170227 1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:2 page_size:16384
|
170227 1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:3 page_size:16384
|
170227 1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:4 page_size:16384
|
170227 1:28:01 [Note] InnoDB: VALID: space:1859997 page_no:5 page_size:16384
|
170227 1:28:01 [Note] InnoDB: Page size: 16384, Possible space_id count:1
|
170227 1:28:01 [Note] InnoDB: space_id:1859997, Number of pages matched: 5/5 (16384)
|
170227 1:28:01 [Note] InnoDB: Chosen space:1859997
|
|
|
170227 1:28:01 [Note] InnoDB: Restoring page 0 of tablespace 1859997
|
170227 1:28:01 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 1859997
|
2017-02-27 01:28:01 7f7346996820 InnoDB: Operating system error number 2 in a file operation.
|
InnoDB: The error means the system cannot find the path specified.
|
InnoDB: If you are installing InnoDB, remember that you must create
|
InnoDB: directories yourself, InnoDB does not create them.
|
InnoDB: Error: could not open single-table tablespace file ./optometrydb/page_manager_handlers.ibd
|
InnoDB: We do not continue the crash recovery, because the table may become
|
InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.
|
InnoDB: To fix the problem and start mysqld:
|
InnoDB: 1) If there is a permission problem in the file and mysqld cannot
|
InnoDB: open the file, you should modify the permissions.
|
InnoDB: 2) If the table is not needed, or you can restore it from a backup,
|
InnoDB: then you can remove the .ibd file, and InnoDB will do a normal
|
InnoDB: crash recovery and ignore that table.
|
InnoDB: 3) If the file system or the disk is broken, and you cannot remove
|
InnoDB: the .ibd file, you can set innodb_force_recovery > 0 in my.cnf
|
InnoDB: and force InnoDB to continue crash recovery here.
|
170227 01:28:01 mysqld_safe mysqld from pid file /var/lib/mysqldata/mysql/DATABASES/whsqlprd05.pid ended
|
Attachments
Issue Links
Activity
flush [error] log, will reopen the file descriptor but not necessary the same one will come back. Maybe. Another thread could open a file which becomes FD 2.
LOCK_error_log isn't held in reopen_fstreams for stderr.
I'm not sure what you mean by "the start of the file" - what is attached is the entire file as copied from the data directory before I started on recovery. Just run it through less and you see this at the top:
170227 1:25:07 [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 https://mariadb.com/kb/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: 10.0.29-MariaDB
|
key_buffer_size=134217728
|
read_buffer_size=131072
|
max_used_connections=211
|
max_threads=5002
|
thread_count=12
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 11114545 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7f50b8c25008
|
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 = 0x7f50466ded30 thread_stack 0x48000
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7f507e2be020): is an invalid pointer
|
Connection ID (thread ID): 12720053
|
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
|
|
|
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.
|
|
|
We think the query pointer is invalid, but we will try to print it anyway.
|
Query: FLUSH /*!40101 LOCAL */ TABLES
|
|
And then the rest is binary through the EOF.
eshicks4, sorry that I overlooked the file attachment. Can you share more details? Do you have a server error log from immediately before the crash?
What was the last message timestamp in the server error log? Do you have an idea if any other maintenance commands were issued close to the statement FLUSH LOCAL TABLES that was mentioned at the end of the MySQL crash output (FLUSH LOCAL TABLES)?
How many InnoDB files do you have, and have you configured innodb_open_files or table_cache (or table_open_cache)? These parameters affect the fil_system->max_n_open and the fil_system->LRU (closing of rarely accessed data files) in InnoDB.
danblack has a promising-looking hypothesis. Maybe fil_node_open_file() in InnoDB opened a data file at a very unfortunate moment as file descriptor 2 (STDERR_FILENO) which happened to be available at that point of time.
Side note: All of the output that corrupted the .ibd file was written by the server core, not InnoDB.
fdmain.c - an approach using dup2 to ensure that stdout(or another fd) isn't closed - generating a race condition but still redirecting it to another object.
open("/tmp/xx.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
|
dup2(3, 1) = 1
|
close(3) = 0
|
fcntl(1, F_GETFL) = 0x8001 (flags O_WRONLY|O_LARGEFILE)
|
fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
|
write(1, "hi\n", 3) = 3
|
exit_group(0) = ?
|
|
|
$ more /tmp/xx.txt
|
hi
|
Note 1: during testing I fclose(stdout) after dup2 and the fprintf(stdout..) generated a segfault which seems closer like this bug report.
looking at freopen is seems the syscalls are quite similar anyway.
open("/tmp/xx.txt", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
|
dup3(3, 1, 0) = 1
|
close(3) = 0
|
fstat(1, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
|
There indeed are a few calls to freopen(), mostly during the server initialization. I tested starting mysqld with all of stdin, stdout, stderr closed, and my_freopen() is being called by reopen_fstreams() and init_server_components() before the InnoDB storage engine is initialized:
break my_freopen
|
break innobase_start_or_create_for_mysql
|
run <&- >&- 2>&-
|
continue
|
continue
|
break open
|
continue
|
At this startup, we have fileno(srv_monitor_file)==1 (STDOUT_FILENO) and fileno(srv_dict_tmpfile)==2 (STDERR_FILENO).
A possible solution for this startup problem could be to allocate a dummy file to the STDERR_FILENO before starting up storage engines, or refuse startup outright if STDERR_FILENO is not open.
I will for now assume that the standard error stream was properly open during the startup.
Like danblack pointed out, flush_error_log() is calling redirect_std_streams(), which calls freopen() via my_freopen(). Assuming that the main() function of storage/mroonga/vendor/groonga/src/groonga.c is not compiled in, flush_error_log() seems to be the only caller of freopen() while the server is running.
The only caller of flush_error_log() is reload_acl_and_cache(), when REFRESH_LOG or REFRESH_ERROR_LOG are set. The callers that use one of those flags are:
- The SIGHUP handler (after calling mysql_print_status())
- FLUSH LOGS
- FLUSH ERROR LOGS
The calls to fdopen() seem to be OK.
The function mysqld_main() is calling close(stdin), which seems OK. On a normal startup (without all of stdin, stdout, stderr being open), there is no call to close() with the argument STDOUT_FILENO or STDERR_FILENO.
There is nothing in the error logs for days leading up to the crash. I am now noticing that 1:25AM is when we kick off the nightly backup of the primary database. (around 570 databases) Having crashed only 7 seconds after the script was kicked off it looks like a pretty good candidate for the triggering event.
The first thing the backup script does is build a config file (not sure why - not my script) and then executes 'show databases' to get a list:
mysql --defaults-file=$TMPFILE.cnf --disable-pager --batch --disable-tee \
|
--execute='show databases' --host=$DATASERVER --user=$OPERUSER --database=mysql
|
The generated config file only includes is a [client] section with password, port, and optional socket.
It then creates a directory for each database (excluding binlog, relay, innodb, and information_schema) and places into it 2 SQL files:
echo "SET FOREIGN_KEY_CHECKS=0;" >$BACKUPDIR/$DATABASE/$DATABASE.ddl.$DATE.sql
|
mysqldump --defaults-file=$TMPFILE.cnf --host=$DATASERVER --user=$OPERUSER \
|
--skip-lock-tables --single-transaction --hex-blob --master-data=2 --allow-keywords \
|
--add-drop-table --quick --add-locks --create-options --complete-insert --extended-insert \
|
--force --databases --no-data $DATABASE \
|
2>$TMPFILE >>$BACKUPDIR/$DATABASE/$DATABASE.ddl.$DATE.sql
|
echo "SET FOREIGN_KEY_CHECKS=0;" >$BACKUPDIR/$DATABASE/$DATABASE.full.$DATE.sql
|
mysqldump --defaults-file=$TMPFILE.cnf --host=$DATASERVER --user=$OPERUSER \
|
--skip-lock-tables --single-transaction --hex-blob --master-data=2 --allow-keywords \
|
--add-drop-table --quick --add-locks --create-options --complete-insert --extended-insert \
|
--force --database --no-create-info --master-data=2 --flush-logs $DATABASE \
|
2>$TMPFILE >>$BACKUPDIR/$DATABASE/$DATABASE.full.$DATE.sql
|
Afterward it tars everything up.
I don't have innodb_open_files but I do have a fair amount of customizations to make it production-level responsive and as VM-friendly as is possible for a DBMS:
max_connections=5000
|
max_connect_errors=4294967295
|
table_cache=1000
|
max_heap_table_size=268435456
|
tmp_table_size=268435456
|
open_files_limit=9076
|
symbolic-links=0
|
query_cache_type=1
|
query_cache_size=32M
|
max_allowed_packet=32M
|
slow-query-log=ON
|
default_storage_engine=InnoDB
|
transaction-isolation=READ-COMMITTED
|
thread_cache_size=4
|
query_cache_limit=10485760
|
table_open_cache=16384
|
table_definition_cache=16384
|
join_buffer_size=512K
|
|
|
wait_timeout=900
|
interactive_timeout=900
|
net_read_timeout=300
|
net_write_timeout=600
|
|
|
innodb_buffer_pool_size=7G
|
innodb_log_file_size=1G
|
innodb_flush_neighbors=0
|
innodb_autoinc_lock_mode=2
|
innodb_data_file_path=ibdata1:256M;ibdata2:256M;ibdata3:256M:autoextend
|
innodb_large_prefix=1
|
innodb_file_per_table=1
|
innodb_file_format=Barracuda
|
innodb_file_format_max=Barracuda
|
innodb_random_read_ahead=1
|
innodb_stats_auto_recalc=1
|
If you need anything else then let me know. Thanks
The same just happened to me on 10.0.29 using Debian Wheezy packages from MariaDB.
Here is what i have on my error log :
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0xb9f46b]
|
/usr/sbin/mysqld(handle_fatal_signal+0x3b6)[0x7461f6]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x7fb8deced0a0]
|
/usr/sbin/mysqld(_ZN4JOIN14optimize_innerEv+0x1640)[0x63b310]
|
/usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x9e)[0x63cade]
|
/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x28d)[0x64038d]
|
/usr/sbin/mysqld[0x5e5886]
|
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x503d)[0x5f0e9d]
|
/usr/sbin/mysqld[0x5f28f7]
|
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c6e)[0x5f4cce]
|
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6b3fa3]
|
/usr/sbin/mysqld(handle_one_connection+0x42)[0x6b4072]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7fb8dece4b50]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fb8dd3eefbd]
|
170328 03:55:04 mysqld_safe Number of processes running now: 0
|
170328 03:55:04 mysqld_safe mysqld restarted
|
170328 3:55:04 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB-1~wheezy) starting as process 8742 ...
|
/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later
|
170328 3:55:05 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
170328 3:55:05 [Note] InnoDB: The InnoDB memory heap is disabled
|
170328 3:55:05 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
170328 3:55:05 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
|
170328 3:55:05 [Note] InnoDB: Compressed tables use zlib 1.2.7
|
170328 3:55:05 [Note] InnoDB: Using Linux native AIO
|
170328 3:55:05 [Note] InnoDB: Using CPU crc32 instructions
|
170328 3:55:05 [Note] InnoDB: Initializing buffer pool, size = 8.0G
|
170328 3:55:05 [Note] InnoDB: Completed initialization of buffer pool
|
170328 3:55:05 [Note] InnoDB: Highest supported file format is Barracuda.
|
170328 3:55:05 [Note] InnoDB: Log scan progressed past the checkpoint lsn 39835474231511
|
170328 3:55:05 [Note] InnoDB: Database was not shutdown normally!
|
170328 3:55:05 [Note] InnoDB: Starting crash recovery.
|
170328 3:55:05 [Note] InnoDB: Reading tablespace information from the .ibd files...
|
170328 3:55:06 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./otherdb/#sql-ib7991104-2285190905.ibd (table otherdb/#sql-ib7991104-2285190905)
|
170328 3:55:06 [Note] InnoDB: Page size:1024 Pages to analyze:64
|
170328 3:55:06 [Note] InnoDB: Page size: 1024, Possible space_id count:0
|
170328 3:55:06 [Note] InnoDB: Page size:2048 Pages to analyze:32
|
170328 3:55:06 [Note] InnoDB: Page size: 2048, Possible space_id count:0
|
170328 3:55:06 [Note] InnoDB: Page size:4096 Pages to analyze:16
|
170328 3:55:06 [Note] InnoDB: Page size: 4096, Possible space_id count:0
|
170328 3:55:06 [Note] InnoDB: Page size:8192 Pages to analyze:8
|
170328 3:55:06 [Note] InnoDB: Page size: 8192, Possible space_id count:0
|
170328 3:55:06 [Note] InnoDB: Page size:16384 Pages to analyze:4
|
170328 3:55:06 [Note] InnoDB: Page size: 16384, Possible space_id count:0
|
2017-03-28 03:55:06 7f1fb88bc760 InnoDB: Operating system error number 2 in a file operation.
|
InnoDB: The error means the system cannot find the path specified.
|
InnoDB: If you are installing InnoDB, remember that you must create
|
InnoDB: directories yourself, InnoDB does not create them.
|
InnoDB: Error: could not open single-table tablespace file ./otherdb/#sql-ib7991104-2285190905.ibd
|
170328 3:55:07 [ERROR] InnoDB: Space id in fsp header 1851878432,but in the page header 544434535
|
170328 3:55:07 [ERROR] InnoDB: checksum mismatch in tablespace ./database/wp_term_relationships.ibd (table database/wp_term_relationships)
|
170328 3:55:07 [Note] InnoDB: Page size:1024 Pages to analyze:64
|
170328 3:55:07 [Note] InnoDB: Page size: 1024, Possible space_id count:0
|
170328 3:55:07 [Note] InnoDB: Page size:2048 Pages to analyze:56
|
170328 3:55:07 [Note] InnoDB: Page size: 2048, Possible space_id count:0
|
170328 3:55:07 [Note] InnoDB: Page size:4096 Pages to analyze:28
|
170328 3:55:07 [Note] InnoDB: Page size: 4096, Possible space_id count:0
|
170328 3:55:07 [Note] InnoDB: Page size:8192 Pages to analyze:14
|
170328 3:55:07 [Note] InnoDB: Page size: 8192, Possible space_id count:0
|
170328 3:55:07 [Note] InnoDB: Page size:16384 Pages to analyze:7
|
170328 3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:1 page_size:16384
|
170328 3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:2 page_size:16384
|
170328 3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:3 page_size:16384
|
170328 3:55:07 [Note] InnoDB: VALID: space:8763257 page_no:4 page_size:16384
|
170328 3:55:07 [Note] InnoDB: Page size: 16384, Possible space_id count:1
|
170328 3:55:07 [Note] InnoDB: space_id:8763257, Number of pages matched: 4/4 (16384)
|
170328 3:55:07 [Note] InnoDB: Chosen space:8763257
|
|
|
170328 3:55:07 [Note] InnoDB: Restoring page 0 of tablespace 8763257
|
170328 3:55:07 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 8763257
|
2017-03-28 03:55:07 7f1fb88bc760 InnoDB: Operating system error number 2 in a file operation.
|
InnoDB: The error means the system cannot find the path specified.
|
InnoDB: If you are installing InnoDB, remember that you must create
|
InnoDB: directories yourself, InnoDB does not create them.
|
InnoDB: Error: could not open single-table tablespace file ./database/wp_term_relationships.ibd
|
InnoDB: We do not continue the crash recovery, because the table may become
|
InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.
|
InnoDB: To fix the problem and start mysqld:
|
InnoDB: 1) If there is a permission problem in the file and mysqld cannot
|
InnoDB: open the file, you should modify the permissions.
|
InnoDB: 2) If the table is not needed, or you can restore it from a backup,
|
InnoDB: then you can remove the .ibd file, and InnoDB will do a normal
|
InnoDB: crash recovery and ignore that table.
|
InnoDB: 3) If the file system or the disk is broken, and you cannot remove
|
InnoDB: and force InnoDB to continue crash recovery here.
|
170328 03:55:07 mysqld_safe mysqld from pid file /var/run/mysqld/mysqld.pid ended
|
170328 03:58:47 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
|
170328 3:58:47 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB-1~wheezy) starting as process 9173 ...
|
/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later
|
/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later
|
170328 3:58:48 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
170328 3:58:48 [Note] InnoDB: The InnoDB memory heap is disabled
|
170328 3:58:48 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
170328 3:58:48 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
|
170328 3:58:48 [Note] InnoDB: Compressed tables use zlib 1.2.7
|
170328 3:58:48 [Note] InnoDB: Using Linux native AIO
|
170328 3:58:48 [Note] InnoDB: Using CPU crc32 instructions
|
170328 3:58:48 [Note] InnoDB: Initializing buffer pool, size = 8.0G
|
170328 3:58:48 [Note] InnoDB: Completed initialization of buffer pool
|
170328 3:58:48 [Note] InnoDB: Highest supported file format is Barracuda.
|
170328 3:58:48 [Note] InnoDB: Log scan progressed past the checkpoint lsn 39835474231511
|
170328 3:58:48 [Note] InnoDB: Database was not shutdown normally!
|
170328 3:58:48 [Note] InnoDB: Starting crash recovery.
|
170328 3:58:48 [Note] InnoDB: Reading tablespace information from the .ibd files...
|
170328 3:58:49 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./otherdb/#sql-ib7991104-2285190905.ibd (table otherdb/#sql-ib7991104-2285190905)
|
170328 3:58:49 [Note] InnoDB: Page size:1024 Pages to analyze:64
|
170328 3:58:49 [Note] InnoDB: Page size: 1024, Possible space_id count:0
|
170328 3:58:49 [Note] InnoDB: Page size:2048 Pages to analyze:32
|
170328 3:58:49 [Note] InnoDB: Page size: 2048, Possible space_id count:0
|
170328 3:58:49 [Note] InnoDB: Page size:4096 Pages to analyze:16
|
170328 3:58:49 [Note] InnoDB: Page size: 4096, Possible space_id count:0
|
170328 3:58:49 [Note] InnoDB: Page size:8192 Pages to analyze:8
|
170328 3:58:49 [Note] InnoDB: Page size: 8192, Possible space_id count:0
|
170328 3:58:49 [Note] InnoDB: Page size:16384 Pages to analyze:4
|
170328 3:58:49 [Note] InnoDB: Page size: 16384, Possible space_id count:0
|
2017-03-28 03:58:49 7f4edc6dd760 InnoDB: Operating system error number 2 in a file operation.
|
InnoDB: The error means the system cannot find the path specified.
|
InnoDB: If you are installing InnoDB, remember that you must create
|
InnoDB: directories yourself, InnoDB does not create them.
|
InnoDB: Error: could not open single-table tablespace file ./otherdb/#sql-ib7991104-2285190905.ibd
|
170328 3:58:49 [ERROR] InnoDB: Space id in fsp header 1851878432,but in the page header 544434535
|
170328 3:58:49 [ERROR] InnoDB: checksum mismatch in tablespace ./database/wp_term_relationships.ibd (table database/wp_term_relationships)
|
[...]
|
And at the beginning of the idb file :
170328 3:55:01 [ERROR] mysqld got signal 11 ;
|
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 https://mariadb.com/kb/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: 10.0.29-MariaDB-1~wheezy
|
key_buffer_size=4294967292
|
read_buffer_size=131072
|
max_used_connections=64
|
max_threads=311
|
thread_count=8
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4877184 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7fb2d2e51008
|
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 = 0x7fb5877b5e20 thread_stack 0x48000
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7fb42ed1b020): is an invalid pointer
|
Connection ID (thread ID): 24769909
|
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
|
|
|
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.
|
|
|
We think the query pointer is invalid, but we will try to print it anyway.
|
Query: SELECT m.name, COUNT(DISTINCT p.id_product) nbr, m.id_manufacturer , m.name, psi.price_min, psi.price_max
|
|
|
FROM `ps_category_product` cp
|
INNER JOIN `ps_category` c ON (c.id_category = cp.id_category)
|
INNER JOIN ps_product p ON (p.id_product = cp.id_product)
|
INNER JOIN ps_manufacturer m ON (m.id_manufacturer = p.id_manufacturer) INNER JOIN ps_product_shop product_shop
|
ON (product_shop.id_product = p.id_product AND product_shop.id_shop = 1)
|
|
|
INNER JOIN `ps_layered_price_index` psi
|
ON (psi.id_product = p.id_product AND psi.id_currency = 1)
|
WHERE
|
c.nleft >= 4
|
AND c.nright <= 5
|
AND c.active = 1
|
AND product_shop.active = 1 AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 15 OR fp.`id_feature_value` = 18 OR fp.`id_feature_value` = 23) AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 68) AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 62)
|
AND p.id_product IN (SELECT pa.`id_product`
|
FROM `ps_product_attribute_combination` pac
|
LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)
|
WHERE pac.`id_attribute` = 34)
|
AND p.id_product IN (SELECT pa.`id_product`
|
FROM `ps_product_attribute_combination` pac
|
LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)
|
WHERE pac.`id_attribute` = 39 OR pac.`id_attribute` = 41 OR pac.`id_attribute` = 53 OR pac.`id_attribute` = 98)
|
GROUP BY p.id_manufacturer
|
What is intersting in Jean's log is that the ibfile contains half of the crash, but the stack trace continues
in the error log file. Another interesting thing is that the ibfile contains the first stderr print after a failure.
Wonder if it's the crash that triggers stderr to be using the wrong file.
I noticed that on windows, we call reopen_fstreams after innodb is opened, which could in theory cause some issues if innodb crashed in a background thread during this reopen.
We should at least move this reopen_fstreams before init_server_components
Unfortunately this doesn't explain this crash as Jean's crash is not on windows.
How atomic is writing to stderr if freopen() is called ?
What I don't understand is how it's possible that stderr could, possible as part of freopen(), use the file descriptor to the innodb file?
One FreeBSD we did have a bug like this a long time ago when freopen was not thread safe and another thread could get the same file descriptor as used by stderr:
https://bugs.mysql.com/bug.php?id=51023
This bug happens apparently on wheezy. Wonder on which other OS this problem has appeared?
Regards,
Monty
Some additional notes on my crash : The server is on an OpenVZ container running kernel 2.6.32-openvz-042stab116.2-amd64 (Jun 24 2016), the server was up since the 17/02 and there are 4 OpenVZ container containing each a MariaDB server on this server.
On the error log backlog there is a similar crash that happened on the 17/02 on the same query but with all the log on the error log :
170216 16:58:16 [ERROR] mysqld got signal 11 ;
|
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 https://mariadb.com/kb/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: 10.0.29-MariaDB-1~wheezy
|
key_buffer_size=4294967292
|
read_buffer_size=131072
|
max_used_connections=47
|
max_threads=311
|
thread_count=3
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4877184 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
|
Thread pointer: 0x7f574ca5c008
|
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 = 0x7f57bd0d9e20 thread_stack 0x48000
|
/usr/sbin/mysqld(my_print_stacktrace+0x2b)[0xb9f46b]
|
/usr/sbin/mysqld(handle_fatal_signal+0x3b6)[0x7461f6]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf0a0)[0x7f5b065880a0]
|
/usr/sbin/mysqld(_Z30setup_sj_materialization_part2P13st_join_table+0x57)[0x6e10c7]
|
/usr/sbin/mysqld(_ZN4JOIN14optimize_innerEv+0x1710)[0x63b3e0]
|
/usr/sbin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x9e)[0x63cade]
|
/usr/sbin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x28d)[0x64038d]
|
/usr/sbin/mysqld[0x5e5886]
|
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x503d)[0x5f0e9d]
|
/usr/sbin/mysqld[0x5f28f7]
|
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1c6e)[0x5f4cce]
|
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x453)[0x6b3fa3]
|
/usr/sbin/mysqld(handle_one_connection+0x42)[0x6b4072]
|
/lib/x86_64-linux-gnu/libpthread.so.0(+0x6b50)[0x7f5b0657fb50]
|
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f5b04c89fbd]
|
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7f5644414020): is an invalid pointer
|
Connection ID (thread ID): 519012
|
Status: NOT_KILLED
|
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on
|
|
|
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.
|
|
|
We think the query pointer is invalid, but we will try to print it anyway.
|
Query: SELECT m.name, COUNT(DISTINCT p.id_product) nbr, m.id_manufacturer , m.name, psi.price_min, psi.price_max
|
|
|
FROM `ps_category_product` cp
|
INNER JOIN `ps_category` c ON (c.id_category = cp.id_category)
|
INNER JOIN ps_product p ON (p.id_product = cp.id_product)
|
INNER JOIN ps_manufacturer m ON (m.id_manufacturer = p.id_manufacturer) INNER JOIN ps_product_shop product_shop
|
ON (product_shop.id_product = p.id_product AND product_shop.id_shop = 1)
|
|
|
INNER JOIN `ps_layered_price_index` psi
|
ON (psi.id_product = p.id_product AND psi.id_currency = 1)
|
WHERE
|
c.nleft >= 4
|
AND c.nright <= 5
|
AND c.active = 1
|
AND product_shop.active = 1 AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 23) AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 68) AND p.id_product IN (SELECT id_product FROM ps_feature_product fp WHERE fp.`id_feature_value` = 62)
|
AND p.id_product IN (SELECT pa.`id_product`
|
FROM `ps_product_attribute_combination` pac
|
LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)
|
WHERE pac.`id_attribute` = 35 OR pac.`id_attribute` = 36)
|
AND p.id_product IN (SELECT pa.`id_product`
|
FROM `ps_product_attribute_combination` pac
|
LEFT JOIN `ps_product_attribute` pa ON (pa.`id_product_attribute` = pac.`id_product_attribute`)
|
WHERE pac.`id_attribute` = 14)
|
GROUP BY p.id_manufacturer
|
|
|
170216 16:58:19 mysqld_safe Number of processes running now: 0
|
170216 16:58:19 mysqld_safe mysqld restarted
|
170216 16:58:19 [Note] /usr/sbin/mysqld (mysqld 10.0.29-MariaDB-1~wheezy) starting as process 12920 ...
|
/usr/sbin/mysqld: Query cache is disabled (resize or similar command in progress); repeat this command later
|
170216 16:58:20 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
170216 16:58:20 [Note] InnoDB: The InnoDB memory heap is disabled
|
170216 16:58:20 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
170216 16:58:20 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
|
170216 16:58:20 [Note] InnoDB: Compressed tables use zlib 1.2.7
|
170216 16:58:20 [Note] InnoDB: Using Linux native AIO
|
170216 16:58:20 [Note] InnoDB: Using CPU crc32 instructions
|
170216 16:58:20 [Note] InnoDB: Initializing buffer pool, size = 8.0G
|
170216 16:58:20 [Note] InnoDB: Completed initialization of buffer pool
|
170216 16:58:20 [Note] InnoDB: Highest supported file format is Barracuda.
|
170216 16:58:20 [Note] InnoDB: Log scan progressed past the checkpoint lsn 39776728170240
|
170216 16:58:20 [Note] InnoDB: Database was not shutdown normally!
|
170216 16:58:20 [Note] InnoDB: Starting crash recovery.
|
170216 16:58:20 [Note] InnoDB: Reading tablespace information from the .ibd files...
|
170216 16:58:20 [ERROR] InnoDB: space header page consists of zero bytes in tablespace ./otherdb/#sql-ib7991104-2285190905.ibd (table otherdb/#sql-ib7991104-2285190905)
|
170216 16:58:20 [Note] InnoDB: Page size:1024 Pages to analyze:64
|
170216 16:58:20 [Note] InnoDB: Page size: 1024, Possible space_id count:0
|
170216 16:58:20 [Note] InnoDB: Page size:2048 Pages to analyze:32
|
170216 16:58:20 [Note] InnoDB: Page size: 2048, Possible space_id count:0
|
170216 16:58:20 [Note] InnoDB: Page size:4096 Pages to analyze:16
|
170216 16:58:20 [Note] InnoDB: Page size: 4096, Possible space_id count:0
|
170216 16:58:20 [Note] InnoDB: Page size:8192 Pages to analyze:8
|
170216 16:58:20 [Note] InnoDB: Page size: 8192, Possible space_id count:0
|
170216 16:58:20 [Note] InnoDB: Page size:16384 Pages to analyze:4
|
170216 16:58:20 [Note] InnoDB: Page size: 16384, Possible space_id count:0
|
2017-02-16 16:58:20 7fb8df10b760 InnoDB: Operating system error number 2 in a file operation.
|
InnoDB: The error means the system cannot find the path specified.
|
InnoDB: If you are installing InnoDB, remember that you must create
|
InnoDB: directories yourself, InnoDB does not create them.
|
InnoDB: Error: could not open single-table tablespace file ./otherdb/#sql-ib7991104-2285190905.ibd
|
170216 16:58:24 [Note] InnoDB: Restoring possible half-written data pages
|
170216 16:58:24 [Note] InnoDB: from the doublewrite buffer...
|
InnoDB: Doing recovery: scanned up to log sequence number 39776728204895
|
170216 16:58:25 [Note] InnoDB: Starting an apply batch of log records to the database...
|
InnoDB: Progress in percent: 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
|
InnoDB: Apply batch completed
|
170216 16:58:27 [Note] InnoDB: 128 rollback segment(s) are active.
|
170216 16:58:27 [Note] InnoDB: Waiting for purge to start
|
170216 16:58:27 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.34-79.1 started; log sequence number 39776728204895
|
170216 16:58:27 [Note] Plugin 'FEEDBACK' is disabled.
|
170216 16:58:27 [Note] Server socket created on IP: '::'.
|
170216 16:58:27 [Note] Server socket created on IP: '::'.
|
170216 16:58:27 [ERROR] mysqld: Table './mysql/user' is marked as crashed and should be repaired
|
170216 16:58:27 [Warning] Checking table: './mysql/user'
|
170216 16:58:27 [ERROR] mysql.user: 1 client is using or hasn't closed the table properly
|
170216 16:58:27 [Note] /usr/sbin/mysqld: ready for connections.
|
Version: '10.0.29-MariaDB-1~wheezy' socket: '/var/run/mysqld/mysqld.sock' port: 3306 mariadb.org binary distribution
|
Configuration :
[client]
|
port = 3306
|
socket = /var/run/mysqld/mysqld.sock
|
[mysqld_safe]
|
socket = /var/run/mysqld/mysqld.sock
|
nice = 0
|
[mysqld]
|
user = mysql
|
pid-file = /var/run/mysqld/mysqld.pid
|
socket = /var/run/mysqld/mysqld.sock
|
port = 3306
|
basedir = /usr
|
datadir = /var/lib/mysql
|
tmpdir = /tmpfs
|
skip-external-locking
|
key_buffer_size = 4G
|
max_allowed_packet = 64M
|
thread_cache_size = 24
|
myisam-recover-options = BACKUP
|
max_connections = 300
|
table_open_cache = 10000
|
table_definition_cache = 10000
|
query_cache_limit = 1M
|
query_cache_size = 64M
|
query_cache_min_res_unit = 2048
|
query_cache_type = OFF
|
local-infile = 0
|
open_files_limit = 65535
|
skip-name-resolve
|
max_delayed_threads = 1
|
wait_timeout = 60
|
interactive_timeout = 60
|
join_buffer_size = 2M
|
read_rnd_buffer_size = 1M
|
tmp_table_size = 64M
|
max_heap_table_size = 64M
|
max_connect_errors = 1000
|
bulk_insert_buffer_size = 32M
|
myisam_sort_buffer_size = 32M
|
default_storage_engine = InnoDB
|
innodb_file_format = Barracuda
|
innodb_buffer_pool_size = 8G
|
innodb_log_file_size = 128M
|
innodb_flush_log_at_trx_commit = 2
|
innodb_log_buffer_size = 8M
|
innodb_file_per_table = 1
|
innodb_open_files = 400
|
innodb_io_capacity = 400
|
innodb_flush_method = O_DIRECT
|
join_cache_level = 6
|
key_cache_segments = 6
|
innodb_old_blocks_time = 1000
|
extra_port = 3307
|
extra-max-connections = 10
|
log_error = /var/log/mysql/error.log
|
slow_query_log_file = /var/log/mysql/mysql-slow.log
|
slow_query_log = 1
|
long_query_time = 4
|
[mysqldump]
|
quick
|
quote-names
|
max_allowed_packet = 64M
|
[mysql]
|
[isamchk]
|
key_buffer = 64M
|
!includedir /etc/mysql/conf.d/
|
# egrep -v "^$|^#" /etc/mysql/conf.d/*
|
/etc/mysql/conf.d/mariadb.cnf:[client]
|
/etc/mysql/conf.d/mariadb.cnf:[mysqld]
|
/etc/mysql/conf.d/mysqld_safe_syslog.cnf.dpkg-dist:[mysqld_safe]
|
/etc/mysql/conf.d/mysqld_safe_syslog.cnf.dpkg-dist:skip_log_error
|
/etc/mysql/conf.d/mysqld_safe_syslog.cnf.dpkg-dist:syslog
|
/etc/mysql/conf.d/tokudb.cnf:[mariadb]
|
MariaDB [information_schema]> SELECT COUNT(*) FROM tables;
|
+----------+
|
| COUNT(*) |
|
+----------+
|
| 88955 |
|
+----------+
|
1 row in set (0.88 sec)
|
|
|
MariaDB [information_schema]> SELECT COUNT(DISTINCT table_schema) FROM tables;
|
+------------------------------+
|
| COUNT(DISTINCT table_schema) |
|
+------------------------------+
|
| 967 |
|
+------------------------------+
|
1 row in set (0.94 sec)
|
Ours is:
$ uname -a
|
Linux dbserver 2.6.32-642.13.1.el6.x86_64 #1 SMP Wed Nov 23 16:03:01 EST 2016 x86_64 x86_64 x86_64 GNU/Linux
|
$ cat /etc/redhat-release
|
Red Hat Enterprise Linux Server release 6.8 (Santiago)
|
We had another event last night which was triggered by the disk running out of free space. The crash was therefore not a surprise; however, in the process another ibd file was corrupted. You can add 10.0.30 to the list of affected versions.
Unfortunately I cannot attach it this time as it holds potentially sensitive info; however, this time the top of the overwritten file only contained the string "pure virtual method called".
2017-03-29 08:14:05 7f05ac913700 InnoDB: Error: Write to file ./database/table.ibd failed at offset 131072.
|
InnoDB: 32768 bytes should have been written, only 0 were written.
|
InnoDB: Operating system error number 28.
|
InnoDB: Check that your OS and file system support files of this size.
|
InnoDB: Check also that the disk is not full or a disk quota exceeded.
|
InnoDB: Error number 28 means 'No space left on device'.
|
InnoDB: Some operating system error numbers are described at
|
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/operating-system-error-codes.html
|
FAIL170329 8:14:05 [ERROR] mysqld: The table 'table' is full
|
FAIL170329 8:14:05 [ERROR] mysqld: The table 'table' is full
|
FAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAIL170329 8:14:07 [ERROR] mysqld: The table 'table' is full
|
FAIL170329 8:14:07 [ERROR] mysqld: The table 'table' is full
|
FAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILFAILInnoDB: Fatal error (Out of disk space) in rollback.
|
InnoDB: Out of tablespace.
|
InnoDB: Consider increasing your tablespace.
|
FAILFAILFAILFAIL170329 08:14:12 mysqld_safe Number of processes running now: 0
|
170329 08:14:12 mysqld_safe mysqld restarted
|
170329 8:14:12 [Note] /usr/sbin/mysqld (mysqld 10.0.30-MariaDB) starting as process 9407 ...
|
170329 8:14:13 [Note] InnoDB: Using mutexes to ref count buffer pool pages
|
170329 8:14:13 [Note] InnoDB: The InnoDB memory heap is disabled
|
170329 8:14:13 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
170329 8:14:13 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
|
170329 8:14:13 [Note] InnoDB: Compressed tables use zlib 1.2.3
|
170329 8:14:13 [Note] InnoDB: Using Linux native AIO
|
170329 8:14:13 [Note] InnoDB: Using CPU crc32 instructions
|
170329 8:14:13 [Note] InnoDB: Initializing buffer pool, size = 7.0G
|
170329 8:14:13 [Note] InnoDB: Completed initialization of buffer pool
|
170329 8:14:13 [Note] InnoDB: Highest supported file format is Barracuda.
|
170329 8:14:13 [Note] InnoDB: Log scan progressed past the checkpoint lsn 7020651191165
|
170329 8:14:13 [Note] InnoDB: Database was not shutdown normally!
|
170329 8:14:13 [Note] InnoDB: Starting crash recovery.
|
170329 8:14:13 [Note] InnoDB: Reading tablespace information from the .ibd files...
|
170329 8:16:28 [ERROR] InnoDB: Space id in fsp header 876228913,but in the page header 540555825
|
170329 8:16:28 [ERROR] InnoDB: checksum mismatch in tablespace ./meddb/anothertable.ibd (table meddb/anothertable)
|
170329 8:16:28 [Note] InnoDB: Page size:1024 Pages to analyze:64
|
170329 8:16:28 [Note] InnoDB: Page size: 1024, Possible space_id count:0
|
170329 8:16:28 [Note] InnoDB: Page size:2048 Pages to analyze:64
|
170329 8:16:28 [Note] InnoDB: Page size: 2048, Possible space_id count:0
|
170329 8:16:28 [Note] InnoDB: Page size:4096 Pages to analyze:56
|
170329 8:16:28 [Note] InnoDB: Page size: 4096, Possible space_id count:0
|
170329 8:16:28 [Note] InnoDB: Page size:8192 Pages to analyze:28
|
170329 8:16:28 [Note] InnoDB: Page size: 8192, Possible space_id count:0
|
170329 8:16:28 [Note] InnoDB: Page size:16384 Pages to analyze:14
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:1 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:2 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:3 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:4 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:5 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:6 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:7 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:8 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:9 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:10 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:11 page_size:16384
|
170329 8:16:28 [Note] InnoDB: VALID: space:1894080 page_no:12 page_size:16384
|
170329 8:16:28 [Note] InnoDB: Page size: 16384, Possible space_id count:1
|
170329 8:16:28 [Note] InnoDB: space_id:1894080, Number of pages matched: 12/12 (16384)
|
170329 8:16:28 [Note] InnoDB: Chosen space:1894080
|
|
|
170329 8:16:28 [Note] InnoDB: Restoring page 0 of tablespace 1894080
|
170329 8:16:28 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 1894080
|
2017-03-29 08:16:28 7f1ca3eec820 InnoDB: Operating system error number 2 in a file operation.
|
InnoDB: The error means the system cannot find the path specified.
|
InnoDB: If you are installing InnoDB, remember that you must create
|
InnoDB: directories yourself, InnoDB does not create them.
|
InnoDB: Error: could not open single-table tablespace file ./meddb/anothertable.ibd
|
InnoDB: We do not continue the crash recovery, because the table may become
|
InnoDB: corrupt if we cannot apply the log records in the InnoDB log to it.
|
InnoDB: To fix the problem and start mysqld:
|
InnoDB: 1) If there is a permission problem in the file and mysqld cannot
|
InnoDB: open the file, you should modify the permissions.
|
InnoDB: 2) If the table is not needed, or you can restore it from a backup,
|
InnoDB: then you can remove the .ibd file, and InnoDB will do a normal
|
InnoDB: crash recovery and ignore that table.
|
InnoDB: 3) If the file system or the disk is broken, and you cannot remove
|
InnoDB: the .ibd file, you can set innodb_force_recovery > 0 in my.cnf
|
InnoDB: and force InnoDB to continue crash recovery here.
|
170329 08:16:28 mysqld_safe mysqld from pid file /var/lib/mysqldata/mysql/DATABASES/whsqlprd05.pid ended
|
mysqld_safe starts mysqld with with "1" and "2" file descriptors closed. This was introduced in https://github.com/MariaDB/server/commit/7497ebf8a49bfe30bb4110f2ac20a30f804b7946
This means that descriptors "1" and "2" are free for use for any file.
But then signal handler writes it's messages to a hardcoded file descriptor STDERR_FILENO (which is "2").
In both reports InnoDB data file header was overrider exactly with signal handler messages.
I'm reassigning to serg and raising priority to critical, since it causes data loss.
Please also note that early server error messages (before freopen(stderr)) may also go to undesired location.
Same for setups where log_error is not defined.
It looks like the file optometrydb/page_manager_handlers.ibd must have been overwritten with some ASCII text:
544434535 == 0x20736967 == " sig"
1851878432 == 0x6e616c20 == "nal "
Can you please share what was written to the start of the file? Anything like "mysqld got signal", by any chance?
In the past (while I worked as a MySQL developer) I have suspected that maybe if the mysqld process is started without file descriptor 2 (stderr) being assigned, it is possible that a data file gets opened as file descriptor 2. Then, when some code attempts to report something to stderr, it would overwrite the data file that happens to be associated with file descriptor 2.
This hypothesis should be fairly easy to test by an invocation similar to the following:
mysqld 2>&-