|
Could you please attach your cnf file(s) and the whole error log from server startup till the end of the crash report?
Thanks.
|
|
Files attached - the error log shows the change in crash time when I altered innodb_background_scrub_data_check_interval to be 300 in ini file - now commented out for default value
|
|
Thanks for the report and provided information, I can reproduce it.
Apparently it affects Windows, but not Linux – at least it crashes reliably for me on Windows and does not crash on Debian Jessie.
|
Test case
|
--source include/have_innodb.inc
|
--source suite/encryption/include/have_file_key_management_plugin.inc
|
|
set global innodb_background_scrub_data_uncompressed= on;
|
set global innodb_background_scrub_data_check_interval= 10;
|
set global innodb_encrypt_tables= on;
|
set global innodb_encryption_threads= 1;
|
|
create table t2 (pk int auto_increment primary key, t varchar(128)) engine=InnoDB;
|
insert into t2 values (null, 'foo'),(null, 'bar');
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
insert into t2 select null, t from t2;
|
delete from t2;
|
|
--sleep 15
|
|
set global innodb_background_scrub_data_uncompressed= DEFAULT;
|
set global innodb_background_scrub_data_check_interval= DEFAULT;
|
set global innodb_encrypt_tables= DEFAULT;
|
set global innodb_encryption_threads= DEFAULT;
|
|
10.2 b175c41cde
|
Assertion failed: index, file c:\_home\10.2\storage\innobase\include\dict0dict.ic, line 352
|
170610 23:21:51 [ERROR] mysqld got exception 0x80000003 ;
|
|
mysqld.exe!abort() Line 71 C++
|
mysqld.exe!common_assert_to_stderr<wchar_t>(const wchar_t * const expression, const wchar_t * const file_name, const unsigned int line_number) Line 149 C++
|
[Inline Frame] mysqld.exe!common_assert(const wchar_t * const return_address, const wchar_t * const) Line 383 C++
|
mysqld.exe!_wassert(const wchar_t * expression, const wchar_t * file_name, unsigned int line_number) Line 404 C++
|
mysqld.exe!dict_index_is_spatial(const dict_index_t * index) Line 352 C++
|
mysqld.exe!btr_scrub_free_page(btr_scrub_t * scrub_data, buf_block_t * block, mtr_t * mtr) Line 683 C++
|
mysqld.exe!btr_scrub_recheck_page(btr_scrub_t * scrub_data, buf_block_t * block, btr_scrub_page_allocation_status_t allocated, mtr_t * mtr) Line 720 C++
|
mysqld.exe!fil_crypt_rotate_page(const key_state_t * key_state, rotate_thread_t * state) Line 1804 C++
|
mysqld.exe!fil_crypt_rotate_pages(const key_state_t * key_state, rotate_thread_t * state) Line 1906 C++
|
mysqld.exe!fil_crypt_thread(void * arg) Line 2137 C++
|
Not reproducible on 10.1 58c56dd7f.
|
|
Here is a test case which reproduces the same failure on Linux.
It is very similar to the test case from MDEV-17596, except that this one has ENCRYPTED=YES for the table instead of --mysqld=--innodb-encrypt-tables as a startup option.
Other instructions from MDEV-17596 apply:
- The test case is non-deterministic and it uses a loop. Please don't put it into the regression suite, it's for reproducing purposes only.
- Run with --repeat=N if it doesn't fail right away. It usually fails for me within 5 attempts. Increasing the number of loops doesn't seem to increase the probability. Make sure the server is restarted between attempts (in the test case below, the commented part of the cleanup makes sure of that).
- Run with --mem or on SSD. I don't know if it's reproducible on a spinning disk, the test case takes too long.
- Remember to run with encryption options.
|
Run with
|
--mysqld=--innodb-encryption-threads=4 --mysqld=--file-key-management --mysqld=--plugin-load-add=file_key_management --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=10 --mem
|
--source include/have_innodb.inc
|
|
SET @scrub.save= @@innodb_background_scrub_data_uncompressed;
|
|
--connect (con1,localhost,root,,)
|
CREATE TABLE t1 (pk INT, a INT, PRIMARY KEY(pk)) ENGINE=InnoDB ENCRYPTED=YES;
|
INSERT INTO t1 VALUES (1,2),(2,3),(3,4),(4,5),(5,6),(6,7),(7,8),(8,9);
|
SET GLOBAL innodb_background_scrub_data_uncompressed=ON;
|
--disconnect con1
|
|
--connection default
|
--let $i= 1000
|
while ($i)
|
{
|
--eval ALTER TABLE t1 FORCE /* $i */
|
--dec $i
|
}
|
|
# Cleanup
|
--delimiter ;
|
DROP TABLE t1;
|
|
# This is intentionally commented, so that when you run with --repeat,
|
# the server is restarted every time between the runs
|
# SET GLOBAL innodb_background_scrub_data_uncompressed = @scrub.save;
|
|
10.2 41e351f6 debug
|
3 <signal handler called>
|
#4 0x00005563c0ca89f8 in dict_index_is_spatial (index=0x0) at /data/src/10.2/storage/innobase/include/dict0dict.ic:290
|
#5 0x00005563c0caa590 in btr_scrub_free_page (scrub_data=0x7fd06d7f9eb0, block=0x7fd0837a0a40, mtr=0x7fd06d7f9890) at /data/src/10.2/storage/innobase/btr/btr0scrub.cc:680
|
#6 0x00005563c0caa63d in btr_scrub_recheck_page (scrub_data=0x7fd06d7f9eb0, block=0x7fd0837a0a40, allocated=BTR_SCRUB_PAGE_FREE, mtr=0x7fd06d7f9890) at /data/src/10.2/storage/innobase/btr/btr0scrub.cc:717
|
#7 0x00005563c0d62435 in fil_crypt_rotate_page (key_state=0x7fd06d7f9e34, state=0x7fd06d7f9e40) at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:1858
|
#8 0x00005563c0d6287a in fil_crypt_rotate_pages (key_state=0x7fd06d7f9e34, state=0x7fd06d7f9e40) at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:1965
|
#9 0x00005563c0d6322e in fil_crypt_thread () at /data/src/10.2/storage/innobase/fil/fil0crypt.cc:2194
|
#10 0x00007fd08ef674a4 in start_thread (arg=0x7fd06d7fa700) at pthread_create.c:456
|
#11 0x00007fd08d4afd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Stack trace on current 10.4 (slightly different, just enough that JIRA doesn't find the bug upon search):
|
10.4 899c843f
|
#3 <signal handler called>
|
#4 0x0000556f593aec00 in dict_index_t::is_spatial (this=0x0) at /data/src/10.4/storage/innobase/include/dict0mem.h:1121
|
#5 0x0000556f59670963 in btr_scrub_free_page (scrub_data=0x7f1a96ffceb0, block=0x7f1aba486460, mtr=0x7f1a96ffc8a0) at /data/src/10.4/storage/innobase/btr/btr0scrub.cc:674
|
#6 0x0000556f59670a0a in btr_scrub_recheck_page (scrub_data=0x7f1a96ffceb0, block=0x7f1aba486460, allocated=BTR_SCRUB_PAGE_FREE, mtr=0x7f1a96ffc8a0) at /data/src/10.4/storage/innobase/btr/btr0scrub.cc:711
|
#7 0x0000556f5974cf57 in fil_crypt_rotate_page (key_state=0x7f1a96ffce34, state=0x7f1a96ffce40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2068
|
#8 0x0000556f5974d560 in fil_crypt_rotate_pages (key_state=0x7f1a96ffce34, state=0x7f1a96ffce40) at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2175
|
#9 0x0000556f5974e017 in fil_crypt_thread () at /data/src/10.4/storage/innobase/fil/fil0crypt.cc:2399
|
#10 0x00007f1ac6c984a4 in start_thread (arg=0x7f1a96ffd700) at pthread_create.c:456
|
#11 0x00007f1ac51dfd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
|
|
Here is yet another variation which will probably never get fixed, adding for a record.
# Run with
|
# --mysqld=--innodb-encrypt-tables --mysqld=--innodb-encrypt-log --mysqld=--innodb-encryption-threads=4 --mysqld=--file-key-management-filename=`pwd`/std_data/keys.txt --mysqld=--plugin-load-add=file_key_management --repeat=N
|
# with high enough repeat=N
|
|
--source include/have_innodb.inc
|
|
CREATE TABLE t1 (a VARCHAR(27126)) ENGINE=InnoDB;
|
--sleep 3
|
SET GLOBAL innodb_background_scrub_data_uncompressed= 1;
|
SHOW CREATE TABLE t1;
|
CREATE OR REPLACE TABLE t1 (b LINESTRING) ENGINE=InnoDB;
|
|
10.3 1656ea28
|
mysqld: /data/src/10.3/storage/innobase/include/mtr0log.ic:161: byte* mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte*, mtr_t*): Assertion `type == MLOG_FILE_NAME || type == MLOG_FILE_DELETE || type == MLOG_FILE_CREATE2 || type == MLOG_FILE_RENAME2 || type == MLOG_INDEX_LOAD || type == MLOG_FILE_WRITE_CRYPT_DATA || mtr->is_named_space(space_id)' failed.
|
200730 3:38:37 [ERROR] mysqld got signal 6 ;
|
|
#7 0x00007fd0ba5eef12 in __GI___assert_fail (assertion=0x5561edd53888 "type == MLOG_FILE_NAME || type == MLOG_FILE_DELETE || type == MLOG_FILE_CREATE2 || type == MLOG_FILE_RENAME2 || type == MLOG_INDEX_LOAD || type == MLOG_FILE_WRITE_CRYPT_DATA || mtr->is_named_space(spa"..., file=0x5561edd537d8 "/data/src/10.3/storage/innobase/include/mtr0log.ic", line=161, function=0x5561edd54360 <mlog_write_initial_log_record_low(mlog_id_t, unsigned long, unsigned long, unsigned char*, mtr_t*)::__PRETTY_FUNCTION__> "byte* mlog_write_initial_log_record_low(mlog_id_t, ulint, ulint, byte*, mtr_t*)") at assert.c:101
|
#8 0x00005561ed4f8c53 in mlog_write_initial_log_record_low (type=MLOG_WRITE_STRING, space_id=4278124286, page_no=4278124286, log_ptr=0x7fd094ff8b68 "\356\216\216\265\320\177", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/include/mtr0log.ic:161
|
#9 0x00005561ed4f8ec4 in mlog_write_initial_log_record_fast (ptr=0x7fd0afd228bc "s\016\fREt", type=MLOG_WRITE_STRING, log_ptr=0x7fd094ff8b68 "\356\216\216\265\320\177", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/include/mtr0log.ic:222
|
#10 0x00005561ed4fa0d2 in mlog_log_string (ptr=0x7fd0afd228bc "s\016\fREt", len=6, mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/mtr/mtr0log.cc:350
|
#11 0x00005561ed4f9f8b in mlog_write_string (ptr=0x7fd0afd228bc "s\016\fREt", str=0x5561ede44aea <_ZL11CRYPT_MAGIC> "s\016\fREt/data/src/10.3/storage/innobase/include/fil0crypt.h", len=6, mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/mtr/mtr0log.cc:323
|
#12 0x00005561ed7e5035 in fil_space_crypt_t::write_page0 (this=0x7fd058096930, space=0x7fd058096a70, page=0x7fd0afd20000 "", mtr=0x7fd094ff88e0) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:404
|
#13 0x00005561ed7e8b3f in fil_crypt_flush_space (state=0x7fd094ff8e40) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:1983
|
#14 0x00005561ed7e8f12 in fil_crypt_complete_rotate_space (state=0x7fd094ff8e40) at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:2059
|
#15 0x00005561ed7e92d4 in fil_crypt_thread () at /data/src/10.3/storage/innobase/fil/fil0crypt.cc:2162
|
#16 0x00007fd0bc5774a4 in start_thread (arg=0x7fd094ff9700) at pthread_create.c:456
|
#17 0x00007fd0ba6abd0f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
|
Reproducible on 10.2-10.4, not seen on 10.5.
|
|
I believe that the scrubbing feature never worked in its original design. MDEV-15528 deprecated and ignored most scrubbing-related parameters and laid the correct groundwork, following the tried-and-true write-ahead-logging protocol. We will first write a log record that a page will be freed, and then the normal page flushing mechanism can take care of overwriting the garbage.
Unfortunately, there was a minor problem related to MDEV-15528, and we had to disable part of it in the 10.5.4 release due to correctness concerns. That problem was addressed in the 10.5.5 release, which allowed us to finally close MDEV-8139.
Note: undo log pages were never scrubbed in the old non-working design. Also in the new design, they will not be scrubbed most of the time, because some ‘caching’ prevents them from being marked as free.
|
limelight.err
my.ini