Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
10.2.2, 10.3.0
Description
MDEV-9977 is back?
The last comment there says
Hi,
It looks like this is back again. I'm working with some tables in the 15-20GB range and the test instructions in this bug report reproduce the issue. 32-bit 10.2.x is affected? x64 is fine.
Error log:
2017-12-30 21:47:01 2376 [ERROR] [FATAL] InnoDB: Trying to read page number 1196032 in space 102, space name test/tinno, which is outside the tablespace bounds. Byte offset 0, len 16384171230 21:47:01 [ERROR] mysqld got exception 0x80000003 ;This could be because you hit a bug. It is also possible that this binaryor 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-bugsWe will try our best to scrape up some info that will hopefully helpdiagnose the problem, but since we have already crashed,something is definitely wrong and this may fail.Server version: 10.2.11-MariaDBkey_buffer_size=16777216read_buffer_size=262144max_used_connections=1max_threads=65537thread_count=7It is possible that mysqld could use up tokey_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 24849 K bytes of memoryHope that's ok; if not, decrease some variables in the equation.Thread pointer: 0x1f940138Attempting backtrace. You can use the following information to find outwhere mysqld died. If you see no messages after this, something wentterribly wrong...mysqld.exe!my_parameter_handler()[my_init.c:255]mysqld.exe!raise()[signal.cpp:516]mysqld.exe!abort()[abort.cpp:64]mysqld.exe!ib::fatal::~fatal()[ut0ut.cc:791]mysqld.exe!fil_report_invalid_page_access()[fil0fil.cc:5005]mysqld.exe!fil_io()[fil0fil.cc:5146]mysqld.exe!buf_read_page_low()[buf0rea.cc:192]mysqld.exe!buf_read_page()[buf0rea.cc:462]mysqld.exe!buf_page_get_gen()[buf0buf.cc:4320]mysqld.exe!flst_add_last()[fut0lst.cc:131]mysqld.exe!fsp_free_extent()[fsp0fsp.cc:1629]mysqld.exe!fseg_free_extent()[fsp0fsp.cc:3296]mysqld.exe!fseg_free_step_func()[fsp0fsp.cc:3369]mysqld.exe!btr_free_but_not_root()[btr0btr.cc:1387]mysqld.exe!btr_free_if_exists()[btr0btr.cc:1438]mysqld.exe!dict_drop_index_tree()[dict0crea.cc:1048]mysqld.exe!row_upd_clust_step()[row0upd.cc:3103]mysqld.exe!row_upd()[row0upd.cc:3261]mysqld.exe!row_upd_step()[row0upd.cc:3407]mysqld.exe!que_thr_step()[que0que.cc:1035]mysqld.exe!que_run_threads_low()[que0que.cc:1115]mysqld.exe!que_run_threads()[que0que.cc:1157]mysqld.exe!que_eval_sql()[que0que.cc:1232]mysqld.exe!row_drop_table_for_mysql()[row0mysql.cc:3998]mysqld.exe!ha_innobase::delete_table()[ha_innodb.cc:13670]mysqld.exe!handler::ha_delete_table()[handler.cc:4335]mysqld.exe!ha_delete_table()[handler.cc:2350]mysqld.exe!mysql_rm_table_no_locks()[sql_table.cc:2466]mysqld.exe!mysql_rm_table()[sql_table.cc:2086]mysqld.exe!mysql_execute_command()[sql_parse.cc:4739]mysqld.exe!mysql_parse()[sql_parse.cc:7887]mysqld.exe!dispatch_command()[sql_parse.cc:1804]mysqld.exe!do_command()[sql_parse.cc:1359]mysqld.exe!threadpool_process_request()[threadpool_common.cc:366]mysqld.exe!tp_callback()[threadpool_common.cc:192]mysqld.exe!work_callback()[threadpool_win.cc:451]ntdll.dll!LdrRegisterDllNotification()ntdll.dll!TpCallbackIndependent()kernel32.dll!BaseThreadInitThunk()ntdll.dll!RtlInitializeExceptionChain()ntdll.dll!RtlInitializeExceptionChain()Trying to get some variables.Some pointers may be invalid and cause the dump to abort.Query (0x1fa1d548): drop table tinnoConnection ID (thread ID): 8Status: NOT_KILLEDOptimizer 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,orderby_uses_equalities=on,condition_pushdown_for_derived=onThe manual page at http://dev.mysql.com/doc/mysql/en/crashing.html containsinformation that should help you find out what is causing the crash.
Attachments
Issue Links
- relates to
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
Activity
Here is some analysis from the core dump:
(gdb) p *space
|
$1 = {name = 0xc9d5b70 "test/tinno", id = 4, max_lsn = 0, stop_ios = false, stop_new_ops = false, is_being_truncated = false, redo_skipped_count = 0,
|
purpose = FIL_TYPE_TABLESPACE, chain = {count = 1, start = 0xc9e7818, end = 0xc9e7818, node = &fil_node_t::chain, init = 51966},
|
size = 42496, size_in_header = 304640, free_len = 0, free_limit = 301056, recv_size = 0, flags = 33, n_reserved_extents = 0,
|
…
|
(gdb) p *space->chain.start
|
$3 = {space = 0xc9e7658, name = 0xc9e7878 "./test/tinno.ibd", handle = {m_file = 16, m_psi = 0x0}, sync_event = 0xc9e7890, is_raw_disk = false,
|
size = 42496, init_size = 0, max_size = 4294967294, n_pending = 0, n_pending_flushes = 0, being_extended = false, modification_counter = 0,
|
flush_counter = 0, chain = {prev = 0x0, next = 0x0}, LRU = {prev = 0x0, next = 0xc9e6810}, atomic_write = true, block_size = 0, magic_n = 89389}
|
Most notably, the fil_space_t::size and fil_node_t::size fields are way too small, only 42496 pages of srv_page_size=16384 bytes. The size_in_header and free_limit correspond both to the actual file size and to the FSP_SIZE and FSP_FREE_LIMIT fields in the first page (both inside the file and inside the buffer pool copy of the page 4:0 in the core dump).
The problem is that fil_space_t::size and fil_node_t::size are either initialized wrong at database startup, or they are updated wrong when file is being extended.
The crash occurs when trying to access page number 250476. This should be an acceptable page number to read, because it is below the free_limit of 301056.
By the way, the last initialized page in the data file is 301033, not too much below free_limit, but 59,080,704 bytes below size_in_header. This issue (InnoDB files are unnecessarily large) has already been reported as MDEV-13013.
It seems to me that the error is the division of os_offset_t by ulint in the last hunk of my suggested patch below. This would be a division of a 64-bit number by a 32-bit number, converted to 32-bit. The machine code in the apparently unoptimized x86 build uses the GCC library routine __udivdi3(), which appears to truncate the 64-bit number to 32 bits first. I was not able to repeat this with a self-built test program, but I can reproduce this on the system:
(gdb) p size_bytes
|
$30 = 4991221760
|
(gdb) n
|
710 node->size = static_cast<ulint>(size_bytes / psize);
|
1: x/i $pc
|
=> 0x8ab01be <fil_node_open_file(fil_node_t*)+2591>: mov -0x348(%ebp),%eax
|
(gdb) n
|
Hardware watchpoint 3: $26->size
|
|
|
Old value = 0
|
New value = 42496
|
Before MDEV-11849, the division issued a warning. A type cast was added in MDEV-11849.
diff --git a/storage/innobase/fil/fil0fil.cc b/storage/innobase/fil/fil0fil.cc
|
index 3b496e3959f..6cf2d076ac9 100644
|
--- a/storage/innobase/fil/fil0fil.cc
|
+++ b/storage/innobase/fil/fil0fil.cc
|
@@ -1,7 +1,7 @@
|
/*****************************************************************************
|
|
Copyright (c) 1995, 2017, Oracle and/or its affiliates. All Rights Reserved.
|
-Copyright (c) 2014, 2017, MariaDB Corporation.
|
+Copyright (c) 2014, 2018, MariaDB Corporation.
|
|
This program is free software; you can redistribute it and/or modify it under
|
the terms of the GNU General Public License as published by the Free Software
|
@@ -566,7 +566,6 @@ bool
|
fil_node_open_file(
|
fil_node_t* node)
|
{
|
- os_offset_t size_bytes;
|
bool success;
|
bool read_only_mode;
|
fil_space_t* space = node->space;
|
@@ -611,7 +610,7 @@ fil_node_open_file(
|
return(false);
|
}
|
|
- size_bytes = os_file_get_size(node->handle);
|
+ os_offset_t size_bytes = os_file_get_size(node->handle);
|
ut_a(size_bytes != (os_offset_t) -1);
|
|
ut_a(space->purpose != FIL_TYPE_LOG);
|
@@ -707,7 +706,8 @@ fil_node_open_file(
|
extent_size);
|
}
|
|
- node->size = static_cast<ulint>(size_bytes / psize);
|
+ node->size = static_cast<ulint>(size_bytes
|
+ / os_offset_t(psize));
|
space->size += node->size;
|
}
|
} |
Even with my patch applied, the compiled machine code is almost identical (some addresses of local variables relative to the stack frame changed).
Most notably, the division operation is identical. Actually, the problem is in a preceding operation that will reset the most significant 32 bits of size_bytes:
if (size_bytes >= extent_size) { |
size_bytes = ut_2pow_round(size_bytes,
|
extent_size);
|
}
|
It was broken in MySQL 5.7.6 and broken in MariaDB since 10.2.2 by the merge of MySQL 5.7.9.
Reproducible with 10.2.12 and current 10.2 tree pretty much as described in
MDEV-9977, only to get it crash after restart I need to do another INSERT into the table, SHOW or SELECT don't cause it.Couldn't reproduce on 10.1.30.
# Restart the server10.2 028e2ddc549fb7573b11392c87b9e8faf1cbf38b debug
2018-01-13 13:29:17 2180430704 [ERROR] [FATAL] InnoDB: Trying to read page number 250476 in space 4, space name test/tinno, which is outside the tablespace bounds. Byte offset 0, len 16384180113 13:29:17 [ERROR] mysqld got signal 6 ;#7 0x00c2c3ca in abort () from /lib/libc.so.6#8 0x089d0a53 in ib::fatal::~fatal (this=0x81f675dc, __in_chrg=<value optimized out>) at /home/buildbot/mariadb-10.2.13/storage/innobase/ut/ut0ut.cc:791#9 0x08abcbdb in fil_report_invalid_page_access (block_offset=250476, space_id=4, space_name=0xc9d5b70 "test/tinno", byte_offset=0, len=16384, is_read=true) at /home/buildbot/mariadb-10.2.13/storage/innobase/fil/fil0fil.cc:5004#10 0x08abd226 in fil_io (type=..., sync=true, page_id=..., page_size=..., byte_offset=0, len=16384, buf=0x9e004000, message=0x9d68a9d0, ignore_missing_space=false) at /home/buildbot/mariadb-10.2.13/storage/innobase/fil/fil0fil.cc:5144#11 0x08a591b3 in buf_read_page_low (err=0x81f67b04, sync=true, type=0, mode=132, page_id=..., page_size=..., unzip=false, ignore_missing_space=false) at /home/buildbot/mariadb-10.2.13/storage/innobase/buf/buf0rea.cc:194#12 0x08a59b01 in buf_read_page (page_id=..., page_size=...) at /home/buildbot/mariadb-10.2.13/storage/innobase/buf/buf0rea.cc:460#13 0x08a2eac9 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=1, guess=0x0, mode=10, file=0x8ee4db4 "/home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc", line=2615, mtr=0x81f686ac, err=0x81f68420) at /home/buildbot/mariadb-10.2.13/storage/innobase/buf/buf0buf.cc:4320#14 0x089f7fa1 in btr_cur_search_to_nth_level (index=0x82028898, level=0, tuple=0x82028228, mode=PAGE_CUR_LE, latch_mode=2, cursor=0x81f68cd0, has_search_latch=0, file=0x8ee4db4 "/home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc", line=2615, mtr=0x81f686ac, autoinc=2424797) at /home/buildbot/mariadb-10.2.13/storage/innobase/btr/btr0cur.cc:1109#15 0x088d6c9d in btr_pcur_open_low (index=0x82028898, level=0, tuple=0x82028228, mode=PAGE_CUR_LE, latch_mode=2, cursor=0x81f68cd0, file=0x8ee4db4 "/home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc", line=2615, autoinc=2424797, mtr=0x81f686ac) at /home/buildbot/mariadb-10.2.13/storage/innobase/include/btr0pcur.ic:459#16 0x088dc8bf in row_ins_clust_index_entry_low (flags=0, mode=2, index=0x82028898, n_uniq=1, entry=0x82028228, n_ext=0, thr=0x82022fd8, dup_chk_only=false) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc:2615#17 0x088de172 in row_ins_clust_index_entry (index=0x82028898, entry=0x82028228, thr=0x82022fd8, n_ext=0, dup_chk_only=false) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc:3202#18 0x088de5cb in row_ins_index_entry (index=0x82028898, entry=0x82028228, thr=0x82022fd8) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc:3314#19 0x088dead6 in row_ins_index_entry_step (node=0x820202d8, thr=0x82022fd8) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc:3464#20 0x088dee5c in row_ins (node=0x820202d8, thr=0x82022fd8) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc:3606#21 0x088df464 in row_ins_step (thr=0x82022fd8) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0ins.cc:3843#22 0x088fb769 in row_insert_for_mysql (mysql_rec=0x8201ea08 "\376\335\377$", prebuilt=0x8201fe38) at /home/buildbot/mariadb-10.2.13/storage/innobase/row/row0mysql.cc:1469#23 0x087c5e81 in ha_innobase::write_row (this=0x8201c2e0, record=0x8201ea08 "\376\335\377$") at /home/buildbot/mariadb-10.2.13/storage/innobase/handler/ha_innodb.cc:8595#24 0x0859654b in handler::ha_write_row (this=0x8201c2e0, buf=0x8201ea08 "\376\335\377$") at /home/buildbot/mariadb-10.2.13/sql/handler.cc:6001#25 0x08312098 in write_record (thd=0x82005d70, table=0x8201e078, info=0x81f69b40) at /home/buildbot/mariadb-10.2.13/sql/sql_insert.cc:1929#26 0x0830feb2 in mysql_insert (thd=0x82005d70, table_list=0x82013708, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/buildbot/mariadb-10.2.13/sql/sql_insert.cc:1057#27 0x08335cd8 in mysql_execute_command (thd=0x82005d70) at /home/buildbot/mariadb-10.2.13/sql/sql_parse.cc:4411#28 0x08340943 in mysql_parse (thd=0x82005d70, rawbuf=0x82013628 "insert into tinno(c1) values(repeat('a',2000))", length=46, parser_state=0x81f6a7fc, is_com_multi=false, is_next_command=false) at /home/buildbot/mariadb-10.2.13/sql/sql_parse.cc:7891#29 0x0832ea2b in dispatch_command (command=COM_QUERY, thd=0x82005d70, packet=0x8200b139 "insert into tinno(c1) values(repeat('a',2000))", packet_length=46, is_com_multi=false, is_next_command=false) at /home/buildbot/mariadb-10.2.13/sql/sql_parse.cc:1806#30 0x0832d5f9 in do_command (thd=0x82005d70) at /home/buildbot/mariadb-10.2.13/sql/sql_parse.cc:1360#31 0x08462255 in do_handle_one_connection (connect=0xca6b158) at /home/buildbot/mariadb-10.2.13/sql/sql_connect.cc:1335#32 0x08461fe3 in handle_one_connection (arg=0xca6b158) at /home/buildbot/mariadb-10.2.13/sql/sql_connect.cc:1241#33 0x001a9a09 in start_thread () from /lib/libpthread.so.0#34 0x00cdd43e in clone () from /lib/libc.so.6