Details
-
Bug
-
Status: Closed (View Workflow)
-
Major
-
Resolution: Fixed
-
10.2(EOL), 10.3(EOL), 10.4(EOL)
Description
|
10.2 845e3c9801d |
mysqld: /home/elenst/MDEV-23439/10.2/storage/innobase/buf/buf0rea.cc:296: ulint buf_read_ahead_random(page_id_t, const page_size_t&, ulint): Assertion `size == space->size' failed.
|
200810 10:58:31 [ERROR] mysqld got signal 6 ;
|
|
|
#3 0x00007f1d678274a2 in __GI___assert_fail (assertion=0x5648a81141e1 "size == space->size", file=0x5648a8114580 "/home/elenst/MDEV-23439/10.2/storage/innobase/buf/buf0rea.cc",
|
line=296,
|
function=0x5648a8115000 <buf_read_ahead_random(page_id_t, page_size_t const&, unsigned long)::__PRETTY_FUNCTION__> "ulint buf_read_ahead_random(page_id_t, const page_size_t&, ulint)") at assert.c:101
|
#4 0x00005648a7ba04e9 in buf_read_ahead_random (page_id=..., page_size=..., inside_ibuf=0) at /home/elenst/MDEV-23439/10.2/storage/innobase/buf/buf0rea.cc:296
|
#5 0x00005648a7b7757a in buf_page_get_low (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10,
|
file=0x5648a8135fe0 "/home/elenst/MDEV-23439/10.2/storage/innobase/fil/fil0fil.cc", line=4497, mtr=0x7f1d2c0a86d0, err=0x0)
|
at /home/elenst/MDEV-23439/10.2/storage/innobase/buf/buf0buf.cc:4390
|
#6 0x00005648a7b78c49 in buf_page_get_gen (page_id=..., page_size=..., rw_latch=2, guess=0x0, mode=10,
|
file=0x5648a8135fe0 "/home/elenst/MDEV-23439/10.2/storage/innobase/fil/fil0fil.cc", line=4497, mtr=0x7f1d2c0a86d0, err=0x0)
|
at /home/elenst/MDEV-23439/10.2/storage/innobase/buf/buf0buf.cc:4908
|
#7 0x00005648a7c012e0 in fsp_flags_try_adjust (space_id=1918, flags=41) at /home/elenst/MDEV-23439/10.2/storage/innobase/fil/fil0fil.cc:4495
|
#8 0x00005648a7c015d0 in fil_space_for_table_exists_in_mem (id=1918, name=0x7f1ce00d2f90 "test/#sql2-20ea-e", table_flags=41)
|
at /home/elenst/MDEV-23439/10.2/storage/innobase/fil/fil0fil.cc:4555
|
#9 0x00005648a7a4e32d in row_drop_single_table_tablespace (space_id=1918, tablename=0x7f1ce00d2f90 "test/#sql2-20ea-e", filepath=0x7f1ce00f5b50 "./test/#sql2-20ea-e.ibd",
|
table_flags=41) at /home/elenst/MDEV-23439/10.2/storage/innobase/row/row0mysql.cc:3253
|
#10 0x00005648a7a4f65c in row_drop_table_for_mysql (name=0x7f1d2c0a94f0 "test/#sql2-20ea-e", trx=0x7f1d650a1268, sqlcom=SQLCOM_ALTER_TABLE, create_failed=false, nonatomic=true)
|
at /home/elenst/MDEV-23439/10.2/storage/innobase/row/row0mysql.cc:3740
|
#11 0x00005648a792a488 in ha_innobase::delete_table (this=0x7f1ce0013590, name=0x7f1d2c0aacf0 "./test/#sql2-20ea-e", sqlcom=SQLCOM_ALTER_TABLE)
|
at /home/elenst/MDEV-23439/10.2/storage/innobase/handler/ha_innodb.cc:13304
|
#12 0x00005648a7914ff8 in ha_innobase::delete_table (this=0x7f1ce0013590, name=0x7f1d2c0aacf0 "./test/#sql2-20ea-e")
|
at /home/elenst/MDEV-23439/10.2/storage/innobase/handler/ha_innodb.cc:13429
|
#13 0x00005648a7712d1e in handler::ha_delete_table (this=0x7f1ce0013590, name=0x7f1d2c0aacf0 "./test/#sql2-20ea-e") at /home/elenst/MDEV-23439/10.2/sql/handler.cc:4473
|
#14 0x00005648a770d441 in ha_delete_table (thd=0x7f1ce0000d50, table_type=0x5648ab13fa00, path=0x7f1d2c0aacf0 "./test/#sql2-20ea-e", db=0x7f1ce0011b30 "test",
|
alias=0x7f1d2c0ab0d0 "#sql2-20ea-e", generate_warning=false) at /home/elenst/MDEV-23439/10.2/sql/handler.cc:2442
|
#15 0x00005648a75545ff in quick_rm_table (thd=0x7f1ce0000d50, base=0x5648ab13fa00, db=0x7f1ce0011b30 "test", table_name=0x7f1d2c0ab0d0 "#sql2-20ea-e", flags=3, table_path=0x0)
|
at /home/elenst/MDEV-23439/10.2/sql/sql_table.cc:2734
|
#16 0x00005648a7567ac8 in mysql_alter_table (thd=0x7f1ce0000d50, new_db=0x7f1ce0011b30 "test", new_name=0x0, create_info=0x7f1d2c0ac2c0, table_list=0x7f1ce0011518,
|
alter_info=0x7f1d2c0ac210, order_num=0, order=0x0, ignore=true) at /home/elenst/MDEV-23439/10.2/sql/sql_table.cc:9876
|
#17 0x00005648a75e390b in Sql_cmd_alter_table::execute (this=0x7f1ce0011b60, thd=0x7f1ce0000d50) at /home/elenst/MDEV-23439/10.2/sql/sql_alter.cc:333
|
#18 0x00005648a7496537 in mysql_execute_command (thd=0x7f1ce0000d50) at /home/elenst/MDEV-23439/10.2/sql/sql_parse.cc:5964
|
#19 0x00005648a749b4cf in mysql_parse (thd=0x7f1ce0000d50,
|
rawbuf=0x7f1ce0011338 "ALTER /* QNO 122120 CON_ID 15 */ IGNORE TABLE alt_t5 /* 100301 WAIT 1 */ /*!100200 DROP CONSTRAINT IF EXISTS k */ /* COMMENT 'Skipped DROP CONSTRAINT' */",
|
length=153, parser_state=0x7f1d2c0ad640, is_com_multi=false, is_next_command=false) at /home/elenst/MDEV-23439/10.2/sql/sql_parse.cc:7733
|
#20 0x00005648a74897db in dispatch_command (command=COM_QUERY, thd=0x7f1ce0000d50, packet=0x7f1ce0008b11 "", packet_length=153, is_com_multi=false, is_next_command=false)
|
at /home/elenst/MDEV-23439/10.2/sql/sql_parse.cc:1823
|
#21 0x00005648a7488258 in do_command (thd=0x7f1ce0000d50) at /home/elenst/MDEV-23439/10.2/sql/sql_parse.cc:1377
|
#22 0x00005648a75de491 in do_handle_one_connection (connect=0x5648abc8afe0) at /home/elenst/MDEV-23439/10.2/sql/sql_connect.cc:1336
|
#23 0x00005648a75de1fc in handle_one_connection (arg=0x5648abc8afe0) at /home/elenst/MDEV-23439/10.2/sql/sql_connect.cc:1241
|
#24 0x00007f1d6852e6db in start_thread (arg=0x7f1d2c0ae700) at pthread_create.c:463
|
#25 0x00007f1d67918a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
|
A test case for the reference is attached, although I don't know how useful it is for debugging, it is very big in size. Execution time in shm is actually not that bad, it fails for me on 10.2 debug in 2-3 min, but on disk it can take almost an hour. The test case is to be run with
--mem --mysqld=--innodb --mysqld=--default-storage-engine=InnoDB --mysqld=--partition --mysqld=--loose-innodb-stats-persistent=on --mysqld=--character-set-server=utf8 --mysqld=--max-allowed-packet=128M --mysqld=--innodb-buffer-pool-size=128M --mysqld=--innodb-log-file-size=48M --mysqld=--log_bin_trust_function_creators=OFF --mysqld=--key_buffer_size=128M --mysqld=--performance-schema=OFF --mysqld=--log_output=FILE --mysqld=--max-statement-time=20 --mysqld=--loose-max-statement-time=10 --mysqld=--innodb-lock-wait-timeout=3 --mysqld=--lock-wait-timeout=5
|
(not all options are important, but these has been used successfully).
Only reproducible with this test case on 10.2, but the failure has been seen on 10.2-10.4. No observations for 10.5.
rr profile is available.
Attachments
Issue Links
- relates to
-
MDEV-15053 Reduce buf_pool_t::mutex contention
-
- Closed
-
-
-
- Closed
-
Activity
The file was originally test/alt_t5.ibd, and at the time of the assertion failure, it had been renamed to test/#sql2-fe54-e.ibd, apparently during the final part of an ALTER TABLE…ALGORITHM=COPY operation.
In the rr replay trace, right before the assertion failure os_file_get_size() reports 65536 bytes, which converts to 8 pages (ROW_FORMAT=COMPRESSED using 8192-byte pages), while space->size is 6 pages. Much earlier, there was an os_file_set_size() call for 65536 bytes. I suspect that something is wrong right at the clustered index creation:
|
10.2 845e3c9801d17905bf2392f27cda66669c00f75f |
#0 os_file_set_size (name=0x7f954414fb60 "./test/alt_t5.ibd", file=54,
|
size=65536, is_sparse=false)
|
at /home/mariadb/MDEV-23439/10.2/storage/innobase/os/os0file.cc:5400
|
#1 0x000055bdbeef566e in fil_space_extend_must_retry (space=0x7f95440cfdf0,
|
node=0x7f95442255e0, size=6, success=0x7f95840f3aef)
|
at /home/mariadb/MDEV-23439/10.2/storage/innobase/fil/fil0fil.cc:968
|
#2 0x000055bdbeef5e68 in fil_space_extend (space=0x7f95440cfdf0, size=6)
|
at /home/mariadb/MDEV-23439/10.2/storage/innobase/fil/fil0fil.cc:1146
|
#3 0x000055bdbef11591 in fsp_try_extend_data_file_with_pages (
|
space=0x7f95440cfdf0, page_no=5, header=0x7f95b5b64026 "",
|
mtr=0x7f95840f3f10)
|
at /home/mariadb/MDEV-23439/10.2/storage/innobase/fsp/fsp0fsp.cc:861
|
#4 0x000055bdbef16f9a in fsp_reserve_free_pages (space=0x7f95440cfdf0,
|
space_header=0x7f95b5b64026 "", size=4, mtr=0x7f95840f3f10, n_pages=2)
|
at /home/mariadb/MDEV-23439/10.2/storage/innobase/fsp/fsp0fsp.cc:2688
|
#5 0x000055bdbef171d0 in fsp_reserve_free_extents (n_reserved=0x7f95840f3ca8,
|
space_id=1918, n_ext=2, alloc_type=FSP_NORMAL, mtr=0x7f95840f3f10,
|
n_pages=2)
|
at /home/mariadb/MDEV-23439/10.2/storage/innobase/fsp/fsp0fsp.cc:2763
|
#6 0x000055bdbef14d60 in fseg_create_general (space_id=1918, page=3,
|
…
|
The file size is being bloated on purpose in fil_space_extend_must_retry():
/* fil_read_first_page() expects UNIV_PAGE_SIZE bytes. |
fil_node_open_file() expects at least 4 * UNIV_PAGE_SIZE bytes.*/
|
os_offset_t new_size = std::max(
|
os_offset_t(size - file_start_page_no) * page_size,
|
os_offset_t(FIL_IBD_FILE_INITIAL_SIZE * UNIV_PAGE_SIZE));
|
|
|
*success = os_file_set_size(node->name, node->handle, new_size,
|
FSP_FLAGS_HAS_PAGE_COMPRESSION(space->flags));
|
Without that std::max(), we would attempt to expand the file to 49152 bytes (6 pages) instead of 65536 bytes (4*innodb_page_size).
I believe that the least disruptive fix is to relax the debug assertion to account for this.
The debug assertion had been removed in 10.5 in MDEV-15053. I think that it is simplest to remove the assertion in older versions as well.
MDEV-23190recently changed something in this area. With an rr replay trace, it should be possible to diagnose and fix this properly.When it comes to the fsp_flags_try_adjust() call, I noted the following in
MDEV-16115last week:Without debugging an rr replay trace, I cannot confirm that the mismatch would be completely avoided by avoiding that call.