[MDEV-14140] IMPORT TABLESPACE must not go beyond FSP_FREE_LIMIT Created: 2017-10-26  Updated: 2017-11-06  Resolved: 2017-11-06

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Storage Engine - XtraDB, Tests
Affects Version/s: 10.0, 10.1, 10.2, 10.3
Fix Version/s: 10.0.34, 10.1.29, 10.2.11, 10.3.3

Type: Bug Priority: Major
Reporter: Alice Sherepa Assignee: Marko Mäkelä
Resolution: Fixed Votes: 0
Labels: None

Attachments: File wl5522_debug_zip.test    
Issue Links:
Relates
relates to MDEV-8819 Failing assertion: block->page.space ... Closed
relates to MDEV-13625 Merge InnoDB test cases from MySQL 5.6 Closed
Sprint: 10.1.29

 Description   

Test imported from MariaDB 10.2.
1) innodb_zip.wl5522_debug_zip '4k,innodb_plugin' fails in 10.0, assertion: block->page.space == page_get_space_id(page_align(ptr)) in file buf0buf.cc line 2394

2) innodb_zip.wl5522_debug_zip '16k,innodb_plugin' --line 516: query 'ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE' succeeded - should have failed with errno 1815...

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
 
innodb_zip.wl5522_debug_zip '4k,innodb_plugin' [ fail ]
 
        Test ended at 2017-10-26 12:53:23
 
 
 
CURRENT_TEST: innodb_zip.wl5522_debug_zip
 
mysqltest: At line 424: query 'ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
FROM information_schema.innodb_metrics
 
WHERE name = 'ibuf_merges_inserts' AND count > 0;
 
name
 
SET GLOBAL innodb_disable_background_merge=OFF;
 
COMMIT;
 
DROP TABLE test_wl5522.t1;
 
CREATE TABLE test_wl5522.t1 (
 
c1 BIGINT NOT NULL AUTO_INCREMENT PRIMARY KEY,
 
c2 BIGINT,
 
c3 VARCHAR(2048),
 
c4 VARCHAR(2048),
 
INDEX idx1(c2),
 
INDEX idx2(c3(512)),
 
INDEX idx3(c4(512))) Engine=InnoDB
 
ROW_FORMAT=COMPRESSED;
 
SELECT c1, c2 FROM test_wl5522.t1;
 
c1	c2
 
ALTER TABLE test_wl5522.t1 DISCARD TABLESPACE;
 
restore: t1 .ibd and .cfg files
 
ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE;


2017-10-26 12:57:52 7fca76524700  InnoDB: Assertion failure in thread 140507545224960 in file buf0buf.cc line 2394
 
InnoDB: Failing assertion: block->page.space == page_get_space_id(page_align(ptr))
 
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.
 
171026 12:57:52 [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.33-MariaDB-debug
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=2
 
max_threads=153
 
thread_count=1
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62856 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7fca687a3070
 
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 = 0x7fca76523e28 thread_stack 0x48000
 
mysys/stacktrace.c:267(my_print_stacktrace)[0xea597d]
 
sql/signal_handler.cc:161(handle_fatal_signal)[0x864df0]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7fca75672390]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7fca74390428]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fca7439202a]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x9b37e)[0x7fca6ca7637e]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x9b43a)[0x7fca6ca7643a]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x1d651d)[0x7fca6cbb151d]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x19d33d)[0x7fca6cb7833d]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x1a63f4)[0x7fca6cb813f4]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x23186c)[0x7fca6cc0c86c]
 
/home/alice/aliska/10.0/mysql-test/var/plugins/ha_innodb.so(+0x160c89)[0x7fca6cb3bc89]
 
sql/handler.cc:4196(handler::ha_discard_or_import_tablespace(char))[0x86f25c]
 
sql/sql_table.cc:5640(mysql_discard_or_import_tablespace(THD*, TABLE_LIST*, bool))[0x716653]
 
sql/sql_alter.cc:346(Sql_cmd_discard_import_tablespace::execute(THD*))[0x78f6df]
 
sql/sql_parse.cc:5123(mysql_execute_command(THD*))[0x66112a]
 
sql/sql_parse.cc:6578(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x664ade]
 
sql/sql_parse.cc:1307(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x656be7]
 
sql/sql_parse.cc:999(do_command(THD*))[0x655e74]
 
sql/sql_connect.cc:1377(do_handle_one_connection(THD*))[0x78a76c]
 
sql/sql_connect.cc:1293(handle_one_connection)[0x78a4ba]
 
perfschema/pfs.cc:1862(pfs_spawn_thread)[0xa58902]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7fca756686ba]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7fca744623dd]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7fca5fcf8088): ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE
 
Connection ID (thread ID): 2
 
Status: NOT_KILLED


Thread 1 (Thread 0x7fca76524700 (LWP 31457)):
 
#0  __pthread_kill (threadid=<optimized out>, signo=6) at ../sysdeps/unix/sysv/linux/pthread_kill.c:62
 
#1  0x0000000000ea5a83 in my_write_core (sig=6) at /home/alice/aliska/10.0/mysys/stacktrace.c:478
 
#2  0x0000000000865171 in handle_fatal_signal (sig=6) at /home/alice/aliska/10.0/sql/signal_handler.cc:285
 
#3  <signal handler called>
 
#4  0x00007fca74390428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
 
#5  0x00007fca7439202a in __GI_abort () at abort.c:89
 
#6  0x00007fca6ca7637e in buf_block_align_instance (buf_pool=0x7fca73827978, ptr=0x7fca6c6c2000 "") at /home/alice/aliska/10.0/storage/innobase/buf/buf0buf.cc:2393
 
#7  0x00007fca6ca7643a in buf_block_align (ptr=0x7fca6c6c2000 "") at /home/alice/aliska/10.0/storage/innobase/buf/buf0buf.cc:2425
 
#8  0x00007fca6cbb151d in mtr_memo_contains_page (mtr=0x7fca765213a0, ptr=0x7fca6c6c2000 "", type=2) at /home/alice/aliska/10.0/storage/innobase/mtr/mtr0mtr.cc:420
 
#9  0x00007fca6cb7833d in ibuf_bitmap_page_get_bits_low (page=0x7fca6c6c2000 "", page_no=2050, zip_size=2048, latch_type=2, mtr=0x7fca765213a0, bit=3) at /home/alice/aliska/10.0/storage/innobase/ibuf/ibuf0ibuf.cc:728
 
#10 0x00007fca6cb813f4 in ibuf_check_bitmap_on_import (trx=0x7fca5fd48278, space_id=10) at /home/alice/aliska/10.0/storage/innobase/ibuf/ibuf0ibuf.cc:5134
 
#11 0x00007fca6cc0c86c in row_import_for_mysql (table=0x7fca5fd3ed78, prebuilt=0x7fca5fe89078) at /home/alice/aliska/10.0/storage/innobase/row/row0import.cc:3658
 
#12 0x00007fca6cb3bc89 in ha_innodb::discard_or_import_tablespace (this=0x7fca5fc76888, discard=0 '\000') at /home/alice/aliska/10.0/storage/innobase/handler/ha_innodb.cc:10586
 
#13 0x000000000086f25c in handler::ha_discard_or_import_tablespace (this=0x7fca5fc76888, discard=0 '\000') at /home/alice/aliska/10.0/sql/handler.cc:4195
 
#14 0x0000000000716653 in mysql_discard_or_import_tablespace (thd=0x7fca687a3070, table_list=0x7fca5fcf81a0, discard=false) at /home/alice/aliska/10.0/sql/sql_table.cc:5640
 
#15 0x000000000078f6df in Sql_cmd_discard_import_tablespace::execute (this=0x7fca5fcf8780, thd=0x7fca687a3070) at /home/alice/aliska/10.0/sql/sql_alter.cc:345
 
#16 0x000000000066112a in mysql_execute_command (thd=0x7fca687a3070) at /home/alice/aliska/10.0/sql/sql_parse.cc:5123
 
#17 0x0000000000664ade in mysql_parse (thd=0x7fca687a3070, rawbuf=0x7fca5fcf8088 "ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE", length=44, parser_state=0x7fca76523670) at /home/alice/aliska/10.0/sql/sql_parse.cc:6578
 
#18 0x0000000000656be7 in dispatch_command (command=COM_QUERY, thd=0x7fca687a3070, packet=0x7fca6e1f3071 "ALTER TABLE test_wl5522.t1 IMPORT TABLESPACE", packet_length=44) at /home/alice/aliska/10.0/sql/sql_parse.cc:1305
 
#19 0x0000000000655e74 in do_command (thd=0x7fca687a3070) at /home/alice/aliska/10.0/sql/sql_parse.cc:999
 
#20 0x000000000078a76c in do_handle_one_connection (thd_arg=0x7fca687a3070) at /home/alice/aliska/10.0/sql/sql_connect.cc:1377
 
#21 0x000000000078a4ba in handle_one_connection (arg=0x7fca687a3070) at /home/alice/aliska/10.0/sql/sql_connect.cc:1292
 
#22 0x0000000000a58902 in pfs_spawn_thread (arg=0x7fca686c33f0) at /home/alice/aliska/10.0/storage/perfschema/pfs.cc:1860
 
#23 0x00007fca756686ba in start_thread (arg=0x7fca76524700) at pthread_create.c:333
 
#24 0x00007fca744623dd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109



 Comments   
Comment by Marko Mäkelä [ 2017-10-31 ]

I can repeat this on 10.0 as follows:

cp {../10.2/,}mysql-test/suite/innodb_zip/t/wl5522_debug_zip.test
 
./mtr --mysqld=--innodb-file-format=1 --mem innodb_zip.wl5522_debug_zip,4k

The problem here is that the 2nd change buffer bitmap page (tablespace id 10, page number 2049) is filled with all zeroes.
At the time of the crash, there is no page 2048 for this tablespace, but I can look at the file mysql-test/var/log/innodb_zip.wl5522_debug_zip-4k,xtradb/tmp/t1.ibd (which uses the original tablespace ID 9) to see what is going on.
The file size is 4096*2048 bytes. One might expect pages 2048 and 2049 to contain valid bitmaps for the last 2048 pages. But, if the page header says that less than 2048 pages are actually used, then the bitmap pages are not required to exist.

It turns out that the last used page in the file starts at offset 0x123000 (page number 582).
One problem would seem to be that the file is unnecessarily large (almost 4 times the payload size).
Another problem would seem to be that IMPORT insists that the bitmap pages be initialized.
The first page of the t1.ibd file starts as follows:

000000 1e c3 fd 49 00 00 00 00 00 00 00 00 00 00 00 00
 
000010 00 00 00 00 00 47 77 99 00 08 00 00 00 00 00 00
 
000020 00 00 00 00 00 09 00 00 00 09 00 00 00 00 00 00
 
000030 10 00 00 00 04 00 00 00 00 e5 00 00 00 f0 00 00
 
000040 00 01 00 00 00 00 01 a6 00 00 00 00 01 a6 00 00
 
000050 00 01 00 00 00 00 00 9e 00 00 00 00 00 9e 00 00

At 0x26 we have the FSP_SPACE_ID which is equal to the FIL_PAGE_SPACE_ID right before it (9).
At 0x2e we have the FSP_SIZE: 0x1000 (4096) pages.
At 0x32 we have the FSP_FREE_LIMIT: 0x400 (2048). So, clearly the bitmap pages 2048 or 2049 should not be expected to be valid.

This is a bug in ibuf_check_bitmap_on_import(): it should not iterate all FSP_SIZE pages of the tablespace, but only the pages up to the FSP_FREE_LIMIT.

Comment by Marko Mäkelä [ 2017-11-06 ]

Actually the test exists in 10.0 already, with a different name: innodb.innodb-wl5522-debug-zip.
But, that test only allows innodb_page_size=16k.

I think that the correct solution is to replace the 10.0 test with the test from 10.2, with suitable adjustments.

Comment by Marko Mäkelä [ 2017-11-06 ]

I pushed to 10.0 and merged to 10.1 (with some conflicts resolved) so far.
The merge to 10.2 may require some effort.

Generated at Thu Feb 08 08:11:14 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.