[MDEV-12905] InnoDB occasionally skips the doublewrite buffer write for some pages Created: 2017-05-24  Updated: 2021-04-27  Resolved: 2021-04-27

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB, Tests
Affects Version/s: 10.1, 10.2
Fix Version/s: 10.2.15, 10.3.6

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: need_rr, sporaric
Environment:

Windows


Attachments: Zip Archive case1.zip     Zip Archive case1_16k.zip     Zip Archive case2_8k.zip     Zip Archive case3_2.zip     File doublewrite.test     Zip Archive doublewrite.zip     Zip Archive ibdata1.zip     Zip Archive ibdata1_2.zip     File mysqld.1.err     File mysqld.1.err     Zip Archive var.zip    
Issue Links:
Duplicate
is duplicated by MDEV-15325 Incomplete validation of missing tabl... Closed
is duplicated by MDEV-16273 innodb.alter_kill fails in buildbot w... Closed
Relates
relates to MDEV-11688 fil_crypt_threads_end() tries to crea... Closed
relates to MDEV-11799 InnoDB can abort if the doublewrite b... Closed
relates to MDEV-12600 crash during install_db with innodb_p... Closed
relates to MDEV-13143 Server crashes in srv_init_abort_low(... Closed
relates to MDEV-14049 InnoDB fails to refuse startup when a... Closed
relates to MDEV-10217 innodb.innodb_bug59641 fails sporadic... Closed
relates to MDEV-11125 Introduce a reduced doublewrite mode,... Closed
relates to MDEV-16763 SIGNAL 6 ERROR Closed
Sprint: 5.5.59, 10.3.6-1

 Description   

https://internal.askmonty.org/buildbot/builders/win32-debug/builds/3945/steps/test/logs/stdio

innodb.doublewrite 'innodb_plugin'       w2 [ fail ]
        Test ended at 2017-05-20 15:15:56
 
CURRENT_TEST: innodb.doublewrite
mysqltest: At line 220: query 'set global innodb_fil_make_page_dirty_debug = @space_id' failed: 2013: Lost connection to MySQL server during query
 
The result from queries just before the failure was:
< snip >
f1	f2
1	############
2	++++++++++++
3	////////////
4	------------
5	............
# Test End
# ---------------------------------------------------------------
# Test Begin: Test if recovery works if 2nd page of user
# tablespace is corrupted.
select space from information_schema.innodb_sys_tables
where name = 'test/t1' into @space_id;
# Ensure that dirty pages of table t1 is flushed.
flush tables t1 for export;
unlock tables;
begin;
insert into t1 values (6, repeat('%', 400));
# Make the 2nd page dirty for table t1
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = @space_id;
 
More results from queries before failure can be found in D:\win32-debug\build\mysql-test\var\2\log\doublewrite.log
 
 
Server [mysqld.1 - pid: 5132, winpid: 5132, exit: 768] failed during test run
Server log from this test:
----------SERVER LOG START-----------
----------SERVER LOG END-------------



 Comments   
Comment by Jan Lindström (Inactive) [ 2017-07-20 ]

Another fail case:

innodb.doublewrite '16k,innodb_plugin'   w5 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2017-07-20 10:27:29
line
170720 10:27:26 [ERROR] mysqld got signal 11 ;
Attempting backtrace. You can use the following information to find out
^ Found warnings in /dev/shm/5/log/mysqld.1.err
ok
 
 - saving '/dev/shm/5/log/innodb.doublewrite-16k,innodb_plugin/' to '/dev/shm/log/innodb.doublewrite-16k,innodb_plugin/'
 - found 'core' (0/5)
 
Trying 'dbx' to get a backtrace
 
Trying 'gdb' to get a backtrace from coredump /dev/shm/log/innodb.doublewrite-16k,innodb_plugin/mysqld.1/data/core
Core generated by '/home/jan/mysql/10.1-tmp/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New LWP 4838]
[New LWP 4835]
[New LWP 4834]
[New LWP 4836]
[New LWP 4837]
[New LWP 4839]
[New LWP 4804]
[New LWP 4877]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/home/jan/mysql/10.1-tmp/sql/mysqld --defaults-group-suffix=.1 --defaults-file='.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007fac6946bc7b in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
[Current thread is 1 (Thread 0x7fac5cffb700 (LWP 4838))]
#0  0x00007fac6946bc7b in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#1  0x00007fac6946d618 in _Unwind_Backtrace () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2  0x00007fac691b3c6f in __GI___backtrace (array=<optimized out>, size=<optimized out>) at ../sysdeps/x86_64/backtrace.c:110
#3  0x00005627a70f13e4 in my_print_stacktrace (stack_bottom=0x0, thread_stack=295936) at /home/jan/mysql/10.1-tmp/mysys/stacktrace.c:267
#4  0x00005627a6a8e835 in handle_fatal_signal (sig=11) at /home/jan/mysql/10.1-tmp/sql/signal_handler.cc:166
#5  <signal handler called>
#6  0x00007fac62380f54 in ?? ()
#7  0x00007fac624f1838 in ?? ()
#8  0x0000000000000100 in ?? ()
#9  0x0000000000000000 in ?? ()
 
Thread 8 (Thread 0x7fac6be2bb00 (LWP 4877)):
#0  0x00007fac6946b2a5 in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#1  0x00007fac6946bdef in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2  0x00007fac6946d02b in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#3  0x00007fac6946d364 in _Unwind_ForcedUnwind () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#4  0x00007fac6bb53d60 in __GI___pthread_unwind (buf=<optimized out>) at unwind.c:121
#5  0x00007fac6bb4c585 in __do_cancel () at pthreadP.h:283
#6  __pthread_exit (value=<optimized out>) at pthread_exit.c:28
#7  0x00005627a678664c in unireg_end () at /home/jan/mysql/10.1-tmp/sql/mysqld.cc:2007
#8  0x00005627a6786540 in kill_server (sig_ptr=0x0) at /home/jan/mysql/10.1-tmp/sql/mysqld.cc:1929
#9  0x00005627a6786568 in kill_server_thread (arg=0x7fac6bebf050) at /home/jan/mysql/10.1-tmp/sql/mysqld.cc:1952
#10 0x00005627a6db36a1 in pfs_spawn_thread (arg=0x7fac5a4290f0) at /home/jan/mysql/10.1-tmp/storage/perfschema/pfs.cc:1860
#11 0x00007fac6bb4b494 in start_thread (arg=0x7fac6be2bb00) at pthread_create.c:333
#12 0x00007fac691a6aff in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:97
 
Thread 7 (Thread 0x7fac6bec4600 (LWP 4804)):
#0  0x00007fac691a2597 in madvise () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007fac6a814c6e in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#2  0x00007fac6a80f8b5 in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#3  0x00007fac6a8113cd in ?? () from /usr/lib/x86_64-linux-gnu/libjemalloc.so.1
#4  0x00005627a6d89489 in pfs_free (ptr=0x7fac63c06000) at /home/jan/mysql/10.1-tmp/storage/perfschema/pfs_global.cc:103
#5  0x00005627a6d89b2a in cleanup_host () at /home/jan/mysql/10.1-tmp/storage/perfschema/pfs_host.cc:121
#6  0x00005627a6d92dcd in cleanup_performance_schema () at /home/jan/mysql/10.1-tmp/storage/perfschema/pfs_server.cc:181
#7  0x00005627a6d92e06 in shutdown_performance_schema () at /home/jan/mysql/10.1-tmp/storage/perfschema/pfs_server.cc:194
#8  0x00005627a678692d in mysqld_exit (exit_code=0) at /home/jan/mysql/10.1-tmp/sql/mysqld.cc:2076
#9  0x00005627a678e137 in mysqld_main (argc=148, argv=0x7fac67c960c0) at /home/jan/mysql/10.1-tmp/sql/mysqld.cc:5960
#10 0x00005627a6783160 in main (argc=24, argv=0x7ffeb00ef7c8) at /home/jan/mysql/10.1-tmp/sql/main.cc:25
 
Thread 6 (Thread 0x7fac5c7fa700 (LWP 4839)):
#0  0x00007fac6aec76ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007fac62380f54 in ?? ()
#2  0x00007fac624f1838 in ?? ()
#3  0x0000000000000100 in ?? ()
#4  0x0000000000000001 in ?? ()
#5  0x00007fac637ff150 in ?? ()
#6  0x0000000100000007 in ?? ()
#7  0x0000000067c0e850 in ?? ()
#8  0x00007fac61113000 in ?? ()
#9  0x00007fac6bf62000 in ?? ()
#10 0x0000000000000100 in ?? ()
#11 0x0000000000000200 in ?? ()
#12 0x00007fac5c7f9c50 in ?? ()
#13 0x00007fac62384327 in ?? ()
#14 0x0000000000000000 in ?? ()
 
Thread 5 (Thread 0x7fac5d7fc700 (LWP 4837)):
#0  0x00007fac6aec76ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007fac62380f54 in ?? ()
#2  0x00007fac624f1838 in ?? ()
#3  0x0000000000000100 in ?? ()
#4  0x0000000000000001 in ?? ()
#5  0x00007fac637ff060 in ?? ()
#6  0x0000000100000007 in ?? ()
#7  0x0000000067c0e730 in ?? ()
#8  0x00007fac63bdd000 in ?? ()
#9  0x00007fac6bf76000 in ?? ()
#10 0x0000000000000100 in ?? ()
#11 0x0000000000000200 in ?? ()
#12 0x00007fac5d7fbc50 in ?? ()
#13 0x00007fac62384327 in ?? ()
#14 0x0000000000000000 in ?? ()
 
Thread 4 (Thread 0x7fac5dffd700 (LWP 4836)):
#0  0x00007fac6aec76ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007fac62380f54 in ?? ()
#2  0x00007fac624f1838 in ?? ()
#3  0x0000000000000100 in ?? ()
#4  0x0000000000000000 in ?? ()
 
Thread 3 (Thread 0x7fac5efff700 (LWP 4834)):
#0  0x00007fac6aec76ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007fac62380f54 in ?? ()
#2  0x00007fac624f1838 in ?? ()
#3  0x0000000000000100 in ?? ()
#4  0x0000000000000000 in ?? ()
 
Thread 2 (Thread 0x7fac5e7fe700 (LWP 4835)):
#0  0x00007fac6aec76ca in ?? () from /lib/x86_64-linux-gnu/libaio.so.1
#1  0x00007fac62380f54 in ?? ()
#2  0x00007fac624f1838 in ?? ()
#3  0x0000000000000100 in ?? ()
#4  0x0000000000000000 in ?? ()
 
Thread 1 (Thread 0x7fac5cffb700 (LWP 4838)):
#0  0x00007fac6946bc7b in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#1  0x00007fac6946d618 in _Unwind_Backtrace () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2  0x00007fac691b3c6f in __GI___backtrace (array=<optimized out>, size=<optimized out>) at ../sysdeps/x86_64/backtrace.c:110
#3  0x00005627a70f13e4 in my_print_stacktrace (stack_bottom=0x0, thread_stack=295936) at /home/jan/mysql/10.1-tmp/mysys/stacktrace.c:267
#4  0x00005627a6a8e835 in handle_fatal_signal (sig=11) at /home/jan/mysql/10.1-tmp/sql/signal_handler.cc:166
#5  <signal handler called>
#6  0x00007fac62380f54 in ?? ()
#7  0x00007fac624f1838 in ?? ()
#8  0x0000000000000100 in ?? ()
#9  0x0000000000000000 in ?? ()

Comment by Marko Mäkelä [ 2017-08-10 ]

Is it possible to get fully resolved stack traces (with function names and arguments for each thread) or a core dump?

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

10.1.26:

 	[External Code]	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
>	ha_innodb.dll!os_cond_wait_timed(_RTL_CONDITION_VARIABLE * cond, os_fast_mutex_t * fast_mutex, unsigned long time_in_ms) Line 156	C++
 	ha_innodb.dll!os_event_wait_time_low(os_event * event, unsigned long time_in_usec, __int64 reset_sig_count) Line 698	C++
 	ha_innodb.dll!recv_writer_thread(void * arg) Line 353	C++
 	[External Code]	
 	[External Code]	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
>	mysqld.exe!pthread_cond_timedwait(pthread_cond_t * cond, _RTL_CRITICAL_SECTION * mutex, const timespec * abstime) Line 298	C
 	mysqld.exe!inline_mysql_cond_timedwait(st_mysql_cond * that, st_mysql_mutex * mutex, const timespec * abstime, const char * src_file, unsigned int src_line) Line 1191	C
 	mysqld.exe!timer_handler(void * arg) Line 293	C
 	mysqld.exe!pfs_spawn_thread(void * arg) Line 1860	C++
 	mysqld.exe!pthread_start(void * p) Line 60	C
 	mysqld.exe!invoke_thread_procedure(unsigned int(__stdcall*)(void *) procedure, void * const context) Line 92	C++
 	mysqld.exe!thread_start<unsigned int (__stdcall*)(void *)>(void * const parameter) Line 115	C++
  	[External Code]	
 	[Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]	
>	ha_innodb.dll!os_aio_windows_handle(unsigned long segment, unsigned long pos, fil_node_t * * message1, void * * message2, unsigned long * type) Line 5041	C++
 	ha_innodb.dll!fil_aio_wait(unsigned long segment) Line 6162	C++
 	ha_innodb.dll!io_handler_thread(void * arg) Line 556	C++	
	[External Code]	
 	ha_innodb.dll!issue_debug_notification(const wchar_t * const message) Line 125	C++
 	ha_innodb.dll!__acrt_report_runtime_error(const wchar_t * message) Line 142	C++
 	ha_innodb.dll!abort() Line 51	C++
>	ha_innodb.dll!buf_block_align_instance(buf_pool_t * buf_pool, const unsigned char * ptr) Line 2864	C++
 	ha_innodb.dll!buf_block_align(const unsigned char * ptr) Line 2894	C++
 	ha_innodb.dll!mtr_memo_contains_page(mtr_t * mtr, const unsigned char * ptr, unsigned long type) Line 420	C++
 	ha_innodb.dll!ibuf_bitmap_page_get_bits_low(const unsigned char * page, unsigned long page_no, unsigned long zip_size, unsigned long latch_type, mtr_t * mtr, unsigned long bit) Line 740	C++
 	ha_innodb.dll!ibuf_merge_or_delete_for_page(buf_block_t * block, unsigned long space_id, unsigned long page_no, unsigned long zip_size, unsigned long update_ibuf_bitmap) Line 4638	C++
 	ha_innodb.dll!buf_page_io_complete(buf_page_t * bpage, bool evict) Line 4941	C++
 	ha_innodb.dll!buf_read_page_low(dberr_t * err, bool sync, unsigned long mode, unsigned long space, unsigned long zip_size, unsigned long unzip, __int64 tablespace_version, unsigned long offset) Line 228	C++
 	ha_innodb.dll!buf_read_page(unsigned long space_id, unsigned long zip_size, unsigned long offset) Line 449	C++
 	ha_innodb.dll!buf_page_get_gen(unsigned long space, unsigned long zip_size, unsigned long offset, unsigned long rw_latch, buf_block_t * guess, unsigned long mode, const char * file, unsigned long line, mtr_t * mtr, dberr_t * err) Line 3186	C++
 	ha_innodb.dll!btr_cur_search_to_nth_level(dict_index_t * index, unsigned long level, const dtuple_t * tuple, unsigned long mode, unsigned long latch_mode, btr_cur_t * cursor, unsigned long has_search_latch, const char * file, unsigned long line, mtr_t * mtr) Line 612	C++
 	ha_innodb.dll!btr_pcur_open_low(dict_index_t * index, unsigned long level, const dtuple_t * tuple, unsigned long mode, unsigned long latch_mode, btr_pcur_t * cursor, const char * file, unsigned long line, mtr_t * mtr) Line 439	C++
 	ha_innodb.dll!btr_pcur_open_on_user_rec_func(dict_index_t * index, const dtuple_t * tuple, unsigned long mode, unsigned long latch_mode, btr_pcur_t * cursor, const char * file, unsigned long line, mtr_t * mtr) Line 589	C++
 	ha_innodb.dll!dict_load_indexes(dict_table_t * table, mem_block_info_t * heap, dict_err_ignore_t ignore_err) Line 1837	C++
 	ha_innodb.dll!dict_load_sys_table(dict_table_t * table) Line 2765	C++
 	ha_innodb.dll!dict_boot() Line 479	C++
 	ha_innodb.dll!innobase_start_or_create_for_mysql() Line 2548	C++
 	ha_innodb.dll!innobase_init(void * p) Line 3970	C++
 	mysqld.exe!ha_initialize_handlerton(st_plugin_int * plugin) Line 513	C++
 	mysqld.exe!plugin_initialize(st_mem_root * tmp_root, st_plugin_int * plugin, int * argc, char * * argv, bool options_only) Line 1406	C++
 	mysqld.exe!plugin_init(int * argc, char * * argv, int flags) Line 1683	C++
 	mysqld.exe!init_server_components() Line 5148	C++
 	mysqld.exe!win_main(int argc, char * * argv) Line 5737	C++
 	mysqld.exe!mysql_service(void * p) Line 5981	C++
 	mysqld.exe!mysqld_main(int argc, char * * argv) Line 6175	C++
 	mysqld.exe!main(int argc, char * * argv) Line 25	C++
	
	
 	[External Code]	
 	[Frames below may be incorrect and/or missing, no symbols loaded for kernel32.dll]	
 
	Locals:
	
	-		block	0x08a90898 {page={space=0 offset=1 buf_fix_count=1 ...} frame=0x08b10000 "" unzip_LRU={prev=0x00000000 <NULL> ...} ...}	buf_block_t *
+		page	{space=0 offset=1 buf_fix_count=1 ...}	buf_page_t
+		frame	0x08b10000 ""	unsigned char *
+		unzip_LRU	{prev=0x00000000 <NULL> next=0x00000000 <NULL> }	ut_list_node<buf_block_t>
		in_unzip_LRU_list	0	unsigned long
+		mutex	{event=0x081c2950 {handle=0xcdcdcdcd os_mutex={mutex={DebugInfo=0xffffffff {Type=??? CreatorBackTraceIndex=...} ...} ...} ...} ...}	ib_mutex_t
+		lock	{lock_word=0 waiters=0 recursive=1 ...}	rw_lock_t
		lock_hash_val	2325	unsigned int
		check_index_page_at_flush	0	unsigned long
		modify_clock	0	unsigned __int64
		n_hash_helps	0	unsigned long
		n_fields	1	unsigned long
		n_bytes	0	unsigned long
		left_side	1	unsigned long
		n_pointers	0	unsigned long
		curr_n_fields	0	unsigned int
		curr_n_bytes	0	unsigned int
		curr_left_side	0	unsigned int
+		index	0x00000000 <NULL>	dict_index_t *
+		debug_latch	{lock_word=1048575 waiters=0 recursive=0 ...}	rw_lock_t
-		block->page	{space=0 offset=1 buf_fix_count=1 ...}	buf_page_t
		space	0	unsigned int
		offset	1	unsigned int
		buf_fix_count	1	unsigned int
		io_fix	0	unsigned int
		state	5	unsigned int
		flush_type	0	unsigned int
		buf_pool_index	0	unsigned int
+		zip	{data=0x00000000 <NULL> m_start=0 m_external=false ...}	page_zip_des_t
		write_size	0	unsigned long
		encrypted	false	bool
		real_size	0	unsigned long
+		slot	0x00000000 <NULL>	buf_tmp_buffer_t *
+		hash	0x00000000 <NULL>	buf_page_t *
		in_page_hash	1	unsigned long
		in_zip_hash	0	unsigned long
+		list	{prev=0x00000000 <NULL> next=0x00000000 <NULL> }	ut_list_node<buf_page_t>
		in_flush_list	1	unsigned long
		in_free_list	0	unsigned long
		newest_modification	3282542	unsigned __int64
		oldest_modification	3282536	unsigned __int64
+		LRU	{prev=0x00000000 <NULL> next=0x08a906e0 {space=0 offset=11 buf_fix_count=0 ...} }	ut_list_node<buf_page_t>
		in_LRU_list	1	unsigned long
		old	0	unsigned int
		freed_page_clock	0	unsigned int
		access_time	3416551707	unsigned int
		file_page_was_freed	0	unsigned long
		block->page.offset	1	unsigned int
		block->page.space	0	unsigned int
-		ptr	0x08b10000 ""	const unsigned char *
			0 '\0'	const unsigned char
0x08B10000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 32 16 6b 00 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  .....................2.k........................
0x08B10030  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10060  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10090  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B100C0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B100F0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10120  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10150  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10180  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B101B0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B101E0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10210  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10240  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10270  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B102A0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B102D0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10300  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10330  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10360  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10390  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B103C0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B103F0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10420  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10450  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10480  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B104B0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B104E0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10510  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10540  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10570  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B105A0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B105D0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10600  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10630  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10660  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10690  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B106C0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B106F0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10720  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10750  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10780  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B107B0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B107E0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10810  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10840  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10870  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B108A0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B108D0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10900  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10930  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10960  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B10990  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................
0x08B109C0  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

Error log

2017-08-10 13:15:27 1840 [Note] InnoDB: Rollback of trx with id 95492 completed
2017-08-10 13:15:27 1840 [Note] InnoDB: Rollback of non-prepared transactions completed
2017-08-10 13:15:27 7496 [Note] InnoDB: 5.6.36 started; log sequence number 3280849
2017-08-10 13:15:28 2936 [Note] InnoDB: Dumping buffer pool(s) not yet started
2017-08-10 13:15:28 7496 [Note] Plugin 'partition' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'SEQUENCE' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_CMP' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'XTRADB_RSEG' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-08-10 13:15:28 7496 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2017-08-10 13:15:28 7496 [Warning] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
2017-08-10 13:15:28 7496 [Warning] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: unknown option '--loose-skip-plugin-innodb-changed-pages'
2017-08-10 13:15:28 7496 [Note] Server socket created on IP: '::'.
2017-08-10 13:15:28 7496 [Note] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: ready for connections.
Version: '10.1.26-MariaDB-debug'  socket: ''  port: 16000  Source distribution
2017-08-10 13:15:28 1712 [Note] InnoDB: Saving InnoDB page number: 0
2017-08-10 13:15:28 1712 [Note] InnoDB: Dirtying page:0 of space:0
2017-08-10 13:15:29 1992 [Note] I:/mysql/10.1/bld/sql//Debug/mysqld.exe (mysqld 10.1.26-MariaDB-debug) starting as process 2596 ...
2017-08-10 13:15:29 1992 [Note] InnoDB:  innodb-page-size has been changed from the default value 16384 to 32768.
2017-08-10 13:15:29 1992 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-08-10 13:15:29 1992 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-10 13:15:29 1992 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2017-08-10 13:15:29 1992 [Note] InnoDB: The InnoDB memory heap is disabled
2017-08-10 13:15:29 1992 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2017-08-10 13:15:29 1992 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2017-08-10 13:15:29 1992 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-08-10 13:15:29 1992 [Note] InnoDB: Using generic crc32 instructions
2017-08-10 13:15:29 1992 [Note] InnoDB: Initializing buffer pool, size = 24.0M
2017-08-10 13:15:29 1992 [Note] InnoDB: Completed initialization of buffer pool
2017-08-10 13:15:29 1992 [Note] InnoDB: Restoring page 0 of tablespace 0
2017-08-10 13:15:29 1992 [Note] InnoDB: Writing 32768 bytes into file: ibdata1
InnoDB: Error: Current page size 32768 !=  page size on page 16384
2017-08-10 13:15:29 1992 [Note] InnoDB: Highest supported file format is Barracuda.
2017-08-10 13:15:29 1992 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3280891
2017-08-10 13:15:29 1992 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
2017-08-10 13:15:30 1992 [Note] InnoDB: Starting final batch to recover 2 pages from redo log
2017-08-10 13:15:31 12048 [Note] InnoDB: Starting in background the rollback of recovered transactions
2017-08-10 13:15:31 1992 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 96512
2017-08-10 13:15:31 2f10  InnoDB: Rolling back trx with id 96004, 1 rows to undo
2017-08-10 13:15:31 1992 [Note] InnoDB: Waiting for purge to start
2017-08-10 13:15:31 12048 [Note] InnoDB: Rollback of trx with id 96004 completed
2017-08-10 13:15:31 12048 [Note] InnoDB: Rollback of non-prepared transactions completed
2017-08-10 13:15:31 1992 [Note] InnoDB: 5.6.36 started; log sequence number 3281424
2017-08-10 13:15:32 10284 [Note] InnoDB: Dumping buffer pool(s) not yet started
2017-08-10 13:15:32 1992 [Note] Plugin 'partition' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'SEQUENCE' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_CMP' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'XTRADB_RSEG' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-08-10 13:15:32 1992 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2017-08-10 13:15:32 1992 [Warning] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
2017-08-10 13:15:32 1992 [Warning] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: unknown option '--loose-skip-plugin-innodb-changed-pages'
2017-08-10 13:15:32 1992 [Note] Server socket created on IP: '::'.
2017-08-10 13:15:32 1992 [Note] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: ready for connections.
Version: '10.1.26-MariaDB-debug'  socket: ''  port: 16000  Source distribution
2017-08-10 13:15:32 11252 [Note] InnoDB: Saving InnoDB page number: 0
2017-08-10 13:15:32 11252 [Note] InnoDB: Dirtying page:0 of space:0
2017-08-10 13:15:33 604 [Note] I:/mysql/10.1/bld/sql//Debug/mysqld.exe (mysqld 10.1.26-MariaDB-debug) starting as process 5220 ...
2017-08-10 13:15:33 604 [Note] InnoDB:  innodb-page-size has been changed from the default value 16384 to 32768.
2017-08-10 13:15:33 604 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-08-10 13:15:33 604 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-10 13:15:33 604 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2017-08-10 13:15:33 604 [Note] InnoDB: The InnoDB memory heap is disabled
2017-08-10 13:15:33 604 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2017-08-10 13:15:33 604 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2017-08-10 13:15:33 604 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-08-10 13:15:33 604 [Note] InnoDB: Using generic crc32 instructions
2017-08-10 13:15:33 604 [Note] InnoDB: Initializing buffer pool, size = 24.0M
2017-08-10 13:15:33 604 [Note] InnoDB: Completed initialization of buffer pool
2017-08-10 13:15:33 604 [Note] InnoDB: Restoring page 0 of tablespace 0
2017-08-10 13:15:33 604 [Note] InnoDB: Writing 32768 bytes into file: ibdata1
InnoDB: Error: Current page size 32768 !=  page size on page 16384
2017-08-10 13:15:33 604 [Note] InnoDB: Highest supported file format is Barracuda.
2017-08-10 13:15:33 604 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3281977
2017-08-10 13:15:33 604 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
2017-08-10 13:15:34 604 [Note] InnoDB: Starting final batch to recover 1 pages from redo log
2017-08-10 13:15:35 12616 [Note] InnoDB: Starting in background the rollback of recovered transactions
2017-08-10 13:15:35 604 [Note] InnoDB: 128 rollback segment(s) are active.
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 97024
2017-08-10 13:15:35 3148  InnoDB: Rolling back trx with id 96516, 1 rows to undo
2017-08-10 13:15:35 604 [Note] InnoDB: Waiting for purge to start
2017-08-10 13:15:35 12616 [Note] InnoDB: Rollback of trx with id 96516 completed
2017-08-10 13:15:35 12616 [Note] InnoDB: Rollback of non-prepared transactions completed
2017-08-10 13:15:35 604 [Note] InnoDB: 5.6.36 started; log sequence number 3281983
2017-08-10 13:15:36 13248 [Note] InnoDB: Dumping buffer pool(s) not yet started
2017-08-10 13:15:36 604 [Note] Plugin 'partition' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'SEQUENCE' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_CMP' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'XTRADB_RSEG' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'FEEDBACK' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2017-08-10 13:15:36 604 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2017-08-10 13:15:36 604 [Warning] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
2017-08-10 13:15:36 604 [Warning] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: unknown option '--loose-skip-plugin-innodb-changed-pages'
2017-08-10 13:15:36 604 [Note] Server socket created on IP: '::'.
2017-08-10 13:15:36 604 [Note] I:/mysql/10.1/bld/sql//Debug/mysqld.exe: ready for connections.
Version: '10.1.26-MariaDB-debug'  socket: ''  port: 16000  Source distribution
2017-08-10 13:15:36 11984 [Note] InnoDB: Saving InnoDB page number: 1
2017-08-10 13:15:37 11984 [Note] InnoDB: Dirtying page:1 of space:0
2017-08-10 13:15:37 5912 [Note] I:/mysql/10.1/bld/sql//Debug/mysqld.exe (mysqld 10.1.26-MariaDB-debug) starting as process 5068 ...
2017-08-10 13:15:37 5912 [Note] InnoDB:  innodb-page-size has been changed from the default value 16384 to 32768.
2017-08-10 13:15:37 5912 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2017-08-10 13:15:37 5912 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2017-08-10 13:15:37 5912 [Note] InnoDB:  InnoDB: !!!!!!!! UNIV_SYNC_DEBUG switched on !!!!!!!!!
2017-08-10 13:15:37 5912 [Note] InnoDB: The InnoDB memory heap is disabled
2017-08-10 13:15:37 5912 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2017-08-10 13:15:37 5912 [Note] InnoDB: _mm_lfence() and _mm_sfence() are used for memory barrier
2017-08-10 13:15:37 5912 [Note] InnoDB: Compressed tables use zlib 1.2.3
2017-08-10 13:15:37 5912 [Note] InnoDB: Using generic crc32 instructions
2017-08-10 13:15:37 5912 [Note] InnoDB: Initializing buffer pool, size = 24.0M
2017-08-10 13:15:37 5912 [Note] InnoDB: Completed initialization of buffer pool
2017-08-10 13:15:37 5912 [Note] InnoDB: Highest supported file format is Barracuda.
2017-08-10 13:15:37 5912 [Note] InnoDB: Starting crash recovery from checkpoint LSN=3282025
2017-08-10 13:15:37 5912 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer...
2017-08-10 13:15:38 5912 [ERROR] InnoDB: Corruption: Block space_id 0 != page space_id 0 or Block offset 1 != page offset 0
170810 13:15:45 [ERROR] mysqld got exception 0x80000003 ;
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.1.26-MariaDB-debug
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=1001
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 387368 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
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...
ha_innodb.dll!issue_debug_notification()[report_runtime_error.cpp:125]
ha_innodb.dll!__acrt_report_runtime_error()[report_runtime_error.cpp:142]
ha_innodb.dll!abort()[abort.cpp:51]
ha_innodb.dll!buf_block_align_instance()[buf0buf.cc:2864]
ha_innodb.dll!buf_block_align()[buf0buf.cc:2894]
ha_innodb.dll!mtr_memo_contains_page()[mtr0mtr.cc:420]
ha_innodb.dll!ibuf_bitmap_page_get_bits_low()[ibuf0ibuf.cc:740]
ha_innodb.dll!ibuf_merge_or_delete_for_page()[ibuf0ibuf.cc:4638]
ha_innodb.dll!buf_page_io_complete()[buf0buf.cc:4941]
ha_innodb.dll!buf_read_page_low()[buf0rea.cc:228]
ha_innodb.dll!buf_read_page()[buf0rea.cc:449]
ha_innodb.dll!buf_page_get_gen()[buf0buf.cc:3186]
ha_innodb.dll!btr_cur_search_to_nth_level()[btr0cur.cc:612]
ha_innodb.dll!btr_pcur_open_low()[btr0pcur.ic:439]
ha_innodb.dll!btr_pcur_open_on_user_rec_func()[btr0pcur.cc:589]
ha_innodb.dll!dict_load_indexes()[dict0load.cc:1837]
ha_innodb.dll!dict_load_sys_table()[dict0load.cc:2765]
ha_innodb.dll!dict_boot()[dict0boot.cc:479]
ha_innodb.dll!innobase_start_or_create_for_mysql()[srv0start.cc:2548]
ha_innodb.dll!innobase_init()[ha_innodb.cc:3970]
mysqld.exe!ha_initialize_handlerton()[handler.cc:513]
mysqld.exe!plugin_initialize()[sql_plugin.cc:1406]
mysqld.exe!plugin_init()[sql_plugin.cc:1683]
mysqld.exe!init_server_components()[mysqld.cc:5148]
mysqld.exe!win_main()[mysqld.cc:5737]
mysqld.exe!mysql_service()[mysqld.cc:5981]
mysqld.exe!mysqld_main()[mysqld.cc:6175]
mysqld.exe!main()[main.cc:25]
mysqld.exe!invoke_main()[exe_common.inl:64]
mysqld.exe!__scrt_common_main_seh()[exe_common.inl:259]
mysqld.exe!__scrt_common_main()[exe_common.inl:302]
mysqld.exe!mainCRTStartup()[exe_main.cpp:17]
KERNEL32.DLL!BaseThreadInitThunk()
ntdll.dll!RtlGetAppContainerNamedObjectPath()
ntdll.dll!RtlGetAppContainerNamedObjectPath()
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.
Writing a core file
Minidump written to I:\mysql\10.1\bld\mysql-test\var\mysqld.1\data\mysqld.dmp
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
2       ++++++++++++
3       ////////////
4       ------------
5       ............
# Test End
# ---------------------------------------------------------------
# Test Begin: Test if recovery works if 2nd page of
# system tablespace is full of zeroes.
begin;
insert into t1 values (6, repeat('%', 400));
# Ensure that all dirty pages in the system are flushed.
set global innodb_buf_flush_list_now = 1;
# Make the second page dirty for system tablespace
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = 0;
# Ensure that the dirty page of system tablespace is also flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Make the 2nd page (page_no=1) of the system tablespace
# all zeroes.
 
 
 - saving 'I:/mysql/10.1/bld/mysql-test/var/log/innodb.doublewrite-32k,innodb_plugin/' to 'I:/mysql/10.1/bld/mysql-test/var/log/innodb.doublewrite-32k,innodb_plugin/'
 - found 'mysqld.dmp' (0/5)
 
Trying 'cdb' to get a backtrace
Cannot find cdb. Please Install Debugging tools for Windows
from http://www.microsoft.com/whdc/devtools/debugging/install64bit.mspx (native x64 version)
 
Only  1  of 10 completed.
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 800.812 of 2432 seconds executing testcases
 
Failure: Failed 1/19 tests, 94.74% were successful.
 
Failing test(s): innodb.doublewrite
 
The log files in var/log may give you some hint of what went wrong.
 
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
mysql-test-run: *** ERROR: there were failing test cases
 
I:\mysql\10.1\bld\mysql-test>

How to repeat. Use win32 and --repeat=100, in my machine it does repeat after ~20runs.

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

>Debug.listcallstack /showvalues /allthreads
Callstack for Thread 1 (Thread Id: 360 (0x168)):
 Index  Function
--------------------------------------------------------------------------------
 1      ha_innodb.dll!issue_debug_notification(const wchar_t * const message=0x0ff11c80)
 2      ha_innodb.dll!__acrt_report_runtime_error(const wchar_t * message=0x0ff11c80)
 3      ha_innodb.dll!abort()
 4      ha_innodb.dll!buf_block_align_instance(buf_pool_t * buf_pool=0x083c3ee8, const unsigned char * ptr=0x08cdc000)
 5      ha_innodb.dll!buf_block_align(const unsigned char * ptr=0x08cdc000)
 6      ha_innodb.dll!mtr_memo_contains_page(mtr_t * mtr=0x00ef9ac4, const unsigned char * ptr=0x08cdc000, unsigned long type=0x00000002)
*7      ha_innodb.dll!ibuf_bitmap_page_get_bits_low(const unsigned char * page=0x08cdc000, unsigned long page_no=0x0000000b, unsigned long zip_size=0x00000000, unsigned long latch_type=0x00000002, mtr_t * mtr=0x00ef9ac4, unsigned long bit=0x00000002)
 8      ha_innodb.dll!ibuf_merge_or_delete_for_page(buf_block_t * block=0x08c906e0, unsigned long space_id=0x00000000, unsigned long page_no=0x0000000b, unsigned long zip_size=0x00000000, unsigned long update_ibuf_bitmap=0x00000001)
 9      ha_innodb.dll!buf_page_io_complete(buf_page_t * bpage=0x08c906e0, bool evict=false)
 10     ha_innodb.dll!buf_read_page_low(dberr_t * err=0x00efa0b0, bool sync=true, unsigned long mode=0x00000084, unsigned long space=0x00000000, unsigned long zip_size=0x00000000, unsigned long unzip=0x00000000, __int64 tablespace_version=0x0000000000000001, unsigned long offset=0x0000000b)
 11     ha_innodb.dll!buf_read_page(unsigned long space_id=0x00000000, unsigned long zip_size=0x00000000, unsigned long offset=0x0000000b)
 12     ha_innodb.dll!buf_page_get_gen(unsigned long space=0x00000000, unsigned long zip_size=0x00000000, unsigned long offset=0x0000000b, unsigned long rw_latch=0x00000003, buf_block_t * guess=0x00000000, unsigned long mode=0x0000000a, const char * file=0x0f92c00c, unsigned long line=0x0000072e, mtr_t * mtr=0x00efa59c, dberr_t * err=0x00efa45c)
 13     ha_innodb.dll!btr_cur_search_to_nth_level(dict_index_t * index=0x08499118, unsigned long level=0x00000000, const dtuple_t * tuple=0x08499818, unsigned long mode=0x00000002, unsigned long latch_mode=0x00000001, btr_cur_t * cursor=0x00efaa2c, unsigned long has_search_latch=0x00000000, const char * file=0x0f92c00c, unsigned long line=0x0000072e, mtr_t * mtr=0x00efa59c)
 14     ha_innodb.dll!btr_pcur_open_low(dict_index_t * index=0x08499118, unsigned long level=0x00000000, const dtuple_t * tuple=0x08499818, unsigned long mode=0x00000002, unsigned long latch_mode=0x00000001, btr_pcur_t * cursor=0x00efaa2c, const char * file=0x0f92c00c, unsigned long line=0x0000072e, mtr_t * mtr=0x00efa59c)
 15     ha_innodb.dll!btr_pcur_open_on_user_rec_func(dict_index_t * index=0x08499118, const dtuple_t * tuple=0x08499818, unsigned long mode=0x00000002, unsigned long latch_mode=0x00000001, btr_pcur_t * cursor=0x00efaa2c, const char * file=0x0f92c00c, unsigned long line=0x0000072e, mtr_t * mtr=0x00efa59c)
 16     ha_innodb.dll!dict_load_indexes(dict_table_t * table=0x08483ea8, mem_block_info_t * heap=0x084997d8, dict_err_ignore_t ignore_err=DICT_ERR_IGNORE_NONE)
 17     ha_innodb.dll!dict_load_sys_table(dict_table_t * table=0x08483ea8)
 18     ha_innodb.dll!dict_boot()
 19     ha_innodb.dll!innobase_start_or_create_for_mysql()
 20     ha_innodb.dll!innobase_init(void * p=0x082fe768)
 21     mysqld.exe!ha_initialize_handlerton(st_plugin_int * plugin=0x000b8610)
 22     mysqld.exe!plugin_initialize(st_mem_root * tmp_root=0x00eff140, st_plugin_int * plugin=0x000b8610, int * argc=0x02da42b8, char * * argv=0x000ec1e0, bool options_only=false)
 23     mysqld.exe!plugin_init(int * argc=0x02da42b8, char * * argv=0x000ec1e0, int flags=0x00000002)
 24     mysqld.exe!init_server_components()
 25     mysqld.exe!win_main(int argc=0x00000093, char * * argv=0x000ec1e0)
 26     mysqld.exe!mysql_service(void * p=0x00000000)
 27     mysqld.exe!mysqld_main(int argc=0x00000016, char * * argv=0x000d8938)
 28     mysqld.exe!main(int argc=0x00000016, char * * argv=0x000d8938)
 29     [External Code]
 30     [Frames below may be incorrect and/or missing, no symbols loaded for kernel32.dll]
 
Callstack for Thread 2 (Thread Id: 11292 (0x2c1c)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      mysqld.exe!pthread_cond_timedwait(pthread_cond_t * cond=0x035ff2a0, _RTL_CRITICAL_SECTION * mutex=0x035ff284, const timespec * abstime=0x08b9f864)
 4      mysqld.exe!inline_mysql_cond_timedwait(st_mysql_cond * that=0x035ff2a0, st_mysql_mutex * mutex=0x035ff284, const timespec * abstime=0x08b9f864, const char * src_file=0x02bdd9e8, unsigned int src_line=0x00000124)
 5      mysqld.exe!timer_handler(void * arg=0x00000000)
 6      mysqld.exe!pfs_spawn_thread(void * arg=0x000c2f68)
 7      mysqld.exe!pthread_start(void * p=0x000d1970)
 8      mysqld.exe!invoke_thread_procedure(unsigned int(__stdcall*)(void *) procedure=0x01d096b0, void * const context=0x000d1970)
 9      mysqld.exe!thread_start<unsigned int (__stdcall*)(void *)>(void * const parameter=0x08257780)
 10     [External Code]
 
Callstack for Thread 3 (Thread Id: 6900 (0x1af4)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_aio_windows_handle(unsigned long segment=0x00000000, unsigned long pos=0x00000000, fil_node_t * * message1=0x096df7e4, void * * message2=0x096df7d8, unsigned long * type=0x096df7cc)
 4      ha_innodb.dll!fil_aio_wait(unsigned long segment=0x00000000)
 5      ha_innodb.dll!io_handler_thread(void * arg=0x0ff7a5d0)
 6      [External Code]
 
Callstack for Thread 4 (Thread Id: 6836 (0x1ab4)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_aio_windows_handle(unsigned long segment=0x00000000, unsigned long pos=0x00000000, fil_node_t * * message1=0x097df8b4, void * * message2=0x097df8a8, unsigned long * type=0x097df89c)
 4      ha_innodb.dll!fil_aio_wait(unsigned long segment=0x00000001)
 5      ha_innodb.dll!io_handler_thread(void * arg=0x0ff7a5d4)
 6      [External Code]
 
Callstack for Thread 5 (Thread Id: 2720 (0xaa0)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_aio_windows_handle(unsigned long segment=0x00000000, unsigned long pos=0x00000000, fil_node_t * * message1=0x098dfbec, void * * message2=0x098dfbe0, unsigned long * type=0x098dfbd4)
 4      ha_innodb.dll!fil_aio_wait(unsigned long segment=0x00000002)
 5      ha_innodb.dll!io_handler_thread(void * arg=0x0ff7a5d8)
 6      [External Code]
 
Callstack for Thread 6 (Thread Id: 8388 (0x20c4)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_aio_windows_handle(unsigned long segment=0x00000001, unsigned long pos=0x00000000, fil_node_t * * message1=0x099dfd40, void * * message2=0x099dfd34, unsigned long * type=0x099dfd28)
 4      ha_innodb.dll!fil_aio_wait(unsigned long segment=0x00000003)
 5      ha_innodb.dll!io_handler_thread(void * arg=0x0ff7a5dc)
 6      [External Code]
 
Callstack for Thread 7 (Thread Id: 12948 (0x3294)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_aio_windows_handle(unsigned long segment=0x00000000, unsigned long pos=0x00000000, fil_node_t * * message1=0x09adf908, void * * message2=0x09adf8fc, unsigned long * type=0x09adf8f0)
 4      ha_innodb.dll!fil_aio_wait(unsigned long segment=0x00000004)
 5      ha_innodb.dll!io_handler_thread(void * arg=0x0ff7a5e0)
 6      [External Code]
 
Callstack for Thread 8 (Thread Id: 13064 (0x3308)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_aio_windows_handle(unsigned long segment=0x00000001, unsigned long pos=0x00000000, fil_node_t * * message1=0x09bdfe94, void * * message2=0x09bdfe88, unsigned long * type=0x09bdfe7c)
 4      ha_innodb.dll!fil_aio_wait(unsigned long segment=0x00000005)
 5      ha_innodb.dll!io_handler_thread(void * arg=0x0ff7a5e4)
 6      [External Code]
 
Callstack for Thread 9 (Thread Id: 6544 (0x1990)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 3      ha_innodb.dll!os_cond_wait_timed(_RTL_CONDITION_VARIABLE * cond=0x0840b3d0, os_fast_mutex_t * fast_mutex=0x0840b3a4, unsigned long time_in_ms=0x00000064)
 4      ha_innodb.dll!os_event_wait_time_low(os_event * event=0x0840b3a0, unsigned long time_in_usec=0x000186a0, __int64 reset_sig_count=0x0000000000000001)
 5      ha_innodb.dll!recv_writer_thread(void * arg=0x00000000)
 6      [External Code]
 
Callstack for Thread 10 (Thread Id: 6160 (0x1810)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]
 
Callstack for Thread 11 (Thread Id: 12564 (0x3114)):
 Index  Function
--------------------------------------------------------------------------------
 1      [External Code]
 2      [Frames below may be incorrect and/or missing, no symbols loaded for ntdll.dll]

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

Locals from ibuf:

		latch_type	0x00000002	unsigned long
-		mtr	0x00ef9ac4 {state=0x00002fc7 memo={heap=0x00000000 <NULL> used=0x00000008 data=0x00ef9ad0 "\x2" ...} ...}	mtr_t *
		state	0x00002fc7	unsigned long
+		memo	{heap=0x00000000 <NULL> used=0x00000008 data=0x00ef9ad0 "\x2" ...}	dyn_block_t
+		log	{heap=0x00000000 <NULL> used=0x00000000 data=0x00ef9cf4 "ÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌÌ... ...}	dyn_block_t
		inside_ibuf	0x00000001	unsigned int
		modifications	0x00000000	unsigned int
		made_dirty	0x00000000	unsigned int
		n_log_recs	0x00000000	unsigned long
		n_freed_pages	0x00000000	unsigned long
		log_mode	0x00000015	unsigned long
		start_lsn	0xcccccccccccccccc	unsigned __int64
		end_lsn	0xcccccccccccccccc	unsigned __int64
		magic_n	0x0000d517	unsigned long
+		trx	0x00000000 <NULL>	trx_t *
-		page	0x08cdc000 ""	const unsigned char *
			0x00 '\0'	const unsigned char
		zip_size	0x00000000	unsigned long

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

This is different way to crash:

 	ha_innodb.dll!issue_debug_notification(const wchar_t * const message) Line 125	C++
 	ha_innodb.dll!__acrt_report_runtime_error(const wchar_t * message) Line 142	C++
 	ha_innodb.dll!abort() Line 51	C++
 	ha_innodb.dll!ib_logf(ib_log_level_t level, const char * format, ...) Line 20631	C++
>	ha_innodb.dll!buf_page_io_complete(buf_page_t * bpage, bool evict) Line 4913	C++
 	ha_innodb.dll!buf_read_page_low(dberr_t * err, bool sync, unsigned long mode, unsigned long space, unsigned long zip_size, unsigned long unzip, __int64 tablespace_version, unsigned long offset) Line 228	C++
 	ha_innodb.dll!buf_read_page(unsigned long space_id, unsigned long zip_size, unsigned long offset) Line 449	C++
 	ha_innodb.dll!buf_page_get_gen(unsigned long space, unsigned long zip_size, unsigned long offset, unsigned long rw_latch, buf_block_t * guess, unsigned long mode, const char * file, unsigned long line, mtr_t * mtr, dberr_t * err) Line 3186	C++
 	ha_innodb.dll!ibuf_bitmap_get_map_page_func(unsigned long space, unsigned long page_no, unsigned long zip_size, const char * file, unsigned long line, mtr_t * mtr) Line 870	C++
 	ha_innodb.dll!ibuf_merge_or_delete_for_page(buf_block_t * block, unsigned long space_id, unsigned long page_no, unsigned long zip_size, unsigned long update_ibuf_bitmap) Line 4633	C++
 	ha_innodb.dll!buf_page_io_complete(buf_page_t * bpage, bool evict) Line 4941	C++
 	ha_innodb.dll!buf_read_page_low(dberr_t * err, bool sync, unsigned long mode, unsigned long space, unsigned long zip_size, unsigned long unzip, __int64 tablespace_version, unsigned long offset) Line 228	C++
 	ha_innodb.dll!buf_read_page(unsigned long space_id, unsigned long zip_size, unsigned long offset) Line 449	C++
 	ha_innodb.dll!buf_page_get_gen(unsigned long space, unsigned long zip_size, unsigned long offset, unsigned long rw_latch, buf_block_t * guess, unsigned long mode, const char * file, unsigned long line, mtr_t * mtr, dberr_t * err) Line 3186	C++
 	ha_innodb.dll!btr_cur_search_to_nth_level(dict_index_t * index, unsigned long level, const dtuple_t * tuple, unsigned long mode, unsigned long latch_mode, btr_cur_t * cursor, unsigned long has_search_latch, const char * file, unsigned long line, mtr_t * mtr) Line 612	C++
 	ha_innodb.dll!btr_pcur_open_low(dict_index_t * index, unsigned long level, const dtuple_t * tuple, unsigned long mode, unsigned long latch_mode, btr_pcur_t * cursor, const char * file, unsigned long line, mtr_t * mtr) Line 439	C++
 	ha_innodb.dll!btr_pcur_open_on_user_rec_func(dict_index_t * index, const dtuple_t * tuple, unsigned long mode, unsigned long latch_mode, btr_pcur_t * cursor, const char * file, unsigned long line, mtr_t * mtr) Line 589	C++
 	ha_innodb.dll!dict_load_indexes(dict_table_t * table, mem_block_info_t * heap, dict_err_ignore_t ignore_err) Line 1837	C++
 	ha_innodb.dll!dict_load_sys_table(dict_table_t * table) Line 2765	C++
 	ha_innodb.dll!dict_boot() Line 479	C++
 	ha_innodb.dll!innobase_start_or_create_for_mysql() Line 2548	C++
 	ha_innodb.dll!innobase_init(void * p) Line 3970	C++
 	mysqld.exe!ha_initialize_handlerton(st_plugin_int * plugin) Line 513	C++
 	mysqld.exe!plugin_initialize(st_mem_root * tmp_root, st_plugin_int * plugin, int * argc, char * * argv, bool options_only) Line 1406	C++
 	mysqld.exe!plugin_init(int * argc, char * * argv, int flags) Line 1683	C++
 	mysqld.exe!init_server_components() Line 5148	C++
 	mysqld.exe!win_main(int argc, char * * argv) Line 5737	C++
 	mysqld.exe!mysql_service(void * p) Line 5981	C++
 	mysqld.exe!mysqld_main(int argc, char * * argv) Line 6175	C++
 	mysqld.exe!main(int argc, char * * argv) Line 25	C++
 	[External Code]	
 	[Frames below may be incorrect and/or missing, no symbols loaded for kernel32.dll]	

Locals

-		bpage	0x08d40898 {space=0x00000000 offset=0x00000001 buf_fix_count=0x00000000 ...}	buf_page_t *
		space	0x00000000	unsigned int
		offset	0x00000001	unsigned int
		buf_fix_count	0x00000000	unsigned int
		io_fix	0x00000001	unsigned int
		state	0x00000005	unsigned int
		flush_type	0x00000000	unsigned int
		buf_pool_index	0x00000000	unsigned int
+		zip	{data=0x00000000 <NULL> m_start=0x00000000 m_external=false ...}	page_zip_des_t
		write_size	0x00000000	unsigned long
		encrypted	false	bool
		real_size	0x00000000	unsigned long
+		slot	0x00000000 <NULL>	buf_tmp_buffer_t *
+		hash	0x00000000 <NULL>	buf_page_t *
		in_page_hash	0x00000001	unsigned long
		in_zip_hash	0x00000000	unsigned long
+		list	{prev=0x00000000 <NULL> next=0x08d40a50 {space=0x00000000 offset=0x00000000 buf_fix_count=0x00000000 ...} }	ut_list_node<buf_page_t>
		in_flush_list	0x00000000	unsigned long
		in_free_list	0x00000000	unsigned long
		newest_modification	0x0000000000000000	unsigned __int64
		oldest_modification	0x0000000000000000	unsigned __int64
+		LRU	{prev=0x00000000 <NULL> next=0x08d406e0 {space=0x00000000 offset=0x0000000b buf_fix_count=0x00000000 ...} }	ut_list_node<buf_page_t>
		in_LRU_list	0x00000001	unsigned long
		old	0x00000000	unsigned int
		freed_page_clock	0x00000000	unsigned int
		access_time	0x00000000	unsigned int
		file_page_was_freed	0x00000000	unsigned long
+		buf_pool	0x084a3fa0 {mutex={event=0x08433da8 {handle=0xcdcdcdcd os_mutex={mutex={DebugInfo=0xffffffff {Type=??? ...} ...} ...} ...} ...} ...}	buf_pool_t *
		err	DB_PAGE_CORRUPTED (0x00000044)	dberr_t
		evict	false	bool
+		frame	0x08dc0000 ""	unsigned char *
		io_type	BUF_IO_READ (0x00000001)	buf_io_fix
		key_version	0x00000000	unsigned int
		read_page_no	0x00000000	unsigned long
		read_space_id	0x00000000	unsigned long
-		space	0x085fb880 {name=0x083ae020 ".\\ibdata1" id=0x00000000 tablespace_version=0x0000000000000001 ...}	fil_space_t *
+		name	0x083ae020 ".\\ibdata1"	char *
		id	0x00000000	unsigned long
		tablespace_version	0x0000000000000001	__int64
		stop_ios	0x00000000	unsigned long
		stop_new_ops	false	bool
		purpose	0x000001f5	unsigned long
+		chain	{count=0x00000001 start=0x085fbbe0 {space=0x085fb880 {name=0x083ae020 ".\\ibdata1" id=0x00000000 tablespace_version=...} ...} ...}	ut_list_base<fil_node_t>
		size	0x00000980	unsigned long
		recv_size	0x00000000	unsigned long
		flags	0x00000180	unsigned long
		n_reserved_extents	0x00000000	unsigned long
		n_pending_flushes	0x00000000	unsigned long
		n_pending_ops	0x00000003	unsigned long
		n_pending_ios	0x00000002	unsigned long
		hash	0x00000000	void *
		name_hash	0x00000000	void *
+		latch	{lock_word=0x00100000 waiters=0x00000000 recursive=0x00000000 ...}	rw_lock_t
+		unflushed_spaces	{prev=0x00000000 <NULL> next=0x00000000 <NULL> }	ut_list_node<fil_space_t>
		is_in_unflushed_spaces	true	bool
		printed_compression_failure	false	bool
+		crypt_data	0x085fb728 {min_key_version=0x00000000 page0_offset=0x000050bc encryption=FIL_ENCRYPTION_DEFAULT (0x00000000) ...}	fil_space_crypt_t *
		file_block_size	0x00000200	unsigned long
+		space_list	{prev=0x00000000 <NULL> next=0x085fbca8 {name=0x083ae420 ".\\ib_logfile0" id=0xfffffff0 tablespace_version=...} }	ut_list_node<fil_space_t>
+		rotation_list	{prev=0x00000000 <NULL> next=0x00000000 <NULL> }	ut_list_node<fil_space_t>
		is_in_rotation_list	false	bool
		magic_n	0x00015d80	unsigned long
		uncompressed	0x00000001	const unsigned long

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

Locals from case 1.

-		block	0x091a0898 {page={space=0x00000000 offset=0x00000001 buf_fix_count=0x00000001 ...} frame=0x09220000 "" ...}	buf_block_t *
-		page	{space=0x00000000 offset=0x00000001 buf_fix_count=0x00000001 ...}	buf_page_t
		space	0x00000000	unsigned int
		offset	0x00000001	unsigned int
		buf_fix_count	0x00000001	unsigned int
		io_fix	0x00000000	unsigned int
		state	0x00000005	unsigned int
		flush_type	0x00000000	unsigned int
		buf_pool_index	0x00000000	unsigned int
+		zip	{data=0x00000000 <NULL> m_start=0x00000000 m_external=false ...}	page_zip_des_t
		write_size	0x00000000	unsigned long
		encrypted	false	bool
		real_size	0x00000000	unsigned long
+		slot	0x00000000 <NULL>	buf_tmp_buffer_t *
+		hash	0x00000000 <NULL>	buf_page_t *
		in_page_hash	0x00000001	unsigned long
		in_zip_hash	0x00000000	unsigned long
+		list	{prev=0x00000000 <NULL> next=0x00000000 <NULL> }	ut_list_node<buf_page_t>
		in_flush_list	0x00000001	unsigned long
		in_free_list	0x00000000	unsigned long
		newest_modification	0x00000000003167fb	unsigned __int64
		oldest_modification	0x00000000003167f5	unsigned __int64
+		LRU	{prev=0x00000000 <NULL> next=0x091a06e0 {space=0x00000000 offset=0x0000000b buf_fix_count=0x00000000 ...} }	ut_list_node<buf_page_t>
		in_LRU_list	0x00000001	unsigned long
		old	0x00000000	unsigned int
		freed_page_clock	0x00000000	unsigned int
		access_time	0xcc208128	unsigned int
		file_page_was_freed	0x00000000	unsigned long
+		frame	0x09220000 ""	unsigned char *
+		unzip_LRU	{prev=0x00000000 <NULL> next=0x00000000 <NULL> }	ut_list_node<buf_block_t>
		in_unzip_LRU_list	0x00000000	unsigned long
+		mutex	{event=0x088c4848 {handle=0xcdcdcdcd os_mutex={mutex={DebugInfo=0xffffffff {Type=??? CreatorBackTraceIndex=...} ...} ...} ...} ...}	ib_mutex_t
+		lock	{lock_word=0x00000000 waiters=0x00000000 recursive=0x00000001 ...}	rw_lock_t
		lock_hash_val	0x00000915	unsigned int
		check_index_page_at_flush	0x00000000	unsigned long
		modify_clock	0x0000000000000000	unsigned __int64
		n_hash_helps	0x00000000	unsigned long
		n_fields	0x00000001	unsigned long
		n_bytes	0x00000000	unsigned long
		left_side	0x00000001	unsigned long
		n_pointers	0x00000000	unsigned long
		curr_n_fields	0x00000000	unsigned int
		curr_n_bytes	0x00000000	unsigned int
		curr_left_side	0x00000000	unsigned int
+		index	0x00000000 <NULL>	dict_index_t *
+		debug_latch	{lock_word=0x000fffff waiters=0x00000000 recursive=0x00000000 ...}	rw_lock_t
+		buf_pool	0x088c3fa0 {mutex={event=0x08854208 {handle=0xcdcdcdcd os_mutex={mutex={DebugInfo=0xffffffff {Type=??? ...} ...} ...} ...} ...} ...}	buf_pool_t *
+		chunk	0x087ce420 {mem_size=0x01858000 size=0x00000300 mem=0x091a0000 ...}	buf_chunk_t *
		i	0x00000000	unsigned long
		offs	0x00000005	unsigned long
		offset	0x00000000	unsigned long
+		ptr	0x09220000 ""	const unsigned char *
		space	0x00000000	unsigned long

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

ptr content:

0x09220000  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 31 67 f8 00 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  .....................1gø........................
0x09220030  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  ................................................

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

Error case 3:

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
innodb.doublewrite '32k,innodb_plugin'   [ pass ]  45666
innodb.doublewrite '32k,innodb_plugin'   [ fail ]
        Test ended at 2017-08-10 15:55:21
 
CURRENT_TEST: innodb.doublewrite
mysqltest: At line 325: query 'select f1, f2 from t1' failed: 1286: Unknown storage engine 'InnoDB'
 
The result from queries just before the failure was:
< snip >
# Test End
# ---------------------------------------------------------------
# Test Begin: Test if recovery works if first page of
# system tablespace is corrupted.
begin;
insert into t1 values (6, repeat('%', 400));
# Ensure that all dirty pages in the system are flushed.
set global innodb_buf_flush_list_now = 1;
# Make the first page dirty for system tablespace
set global innodb_saved_page_number_debug = 0;
set global innodb_fil_make_page_dirty_debug = 0;
# Ensure that the dirty page of system tablespace is also flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Corrupt the first page (page_no=0) of the system tablespace.
check table t1;
Table   Op      Msg_type        Msg_text
test.t1 check   Error   Unknown storage engine 'InnoDB'
test.t1 check   error   Corrupt
select f1, f2 from t1;
 
More results from queries before failure can be found in I:\mysql\10.1\bld\mysql-test\var\log\doublewrite.log
 
 - saving 'I:/mysql/10.1/bld/mysql-test/var/log/innodb.doublewrite-32k,innodb_plugin/' to 'I:/mysql/10.1/bld/mysql-test/var/log/innodb.doublewrite-32k,innodb_plugin/'
 
Only  1  of 10 completed.
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 45.666 of 102 seconds executing testcases
 
Failure: Failed 1/2 tests, 50.00% were successful.
 
Failing test(s): innodb.doublewrite
 
The log files in var/log may give you some hint of what went wrong.
 
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
mysql-test-run: *** ERROR: there were failing test cases

Comment by Marko Mäkelä [ 2017-08-10 ]

Thanks! The buf_block_t matches the ptr; we have block->frame == ptr, and block->state = BUF_BLOCK_FILE_PAGE.
The only mystery is why the second page of the system tablespace (page 0:1) is not a valid change buffer bitmap page.

A possible explanation is that the test was run with innodb_page_size=32k or innodb_page_size=64k, and we got this kicking in:

--source include/kill_mysqld.inc
 
--echo # Make the first page (page_no=0) of the system tablespace
--echo # all zeroes.
perl;
use IO::Handle;
my $fname= "$ENV{'MYSQLD_DATADIR'}ibdata1";
open(FILE, "+<", $fname) or die;
FILE->autoflush(1);
binmode FILE;
print FILE chr(0) x ($ENV{'INNODB_PAGE_SIZE'});
close FILE;
EOF
 
--source include/start_mysqld.inc

Which page size was used when the test failed? Which portion of the test was executing right before the failure? (Look in the subdirectories of mysql-test/var for the test client output.)
My current hypothesis is that somehow, when seeing that the first half of page 0 is filled with zeroes, InnoDB determined the page size to be 16k, and perhaps also loaded a part of the larger page 0 frame to the buffer pool as page 1.

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

All my failures with innodb.doublewrite,32k,innodb_plugin

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

Case 1 and 3 seen also with 16k page size. Case 3 with 8k page size, there is some race condition.

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

Observation it is not always the same place in test:

begin;
insert into t1 values (6, repeat('%', 400));
# Ensure that all dirty pages in the system are flushed.
set global innodb_buf_flush_list_now = 1;
# Make the second page dirty for system tablespace
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = 0;
# Ensure that the dirty page of system tablespace is also flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Make the 2nd page (page_no=1) of the system tablespace
# all zeroes.
 
 
 - saving 'I:/mysql/10.1/bld/mysql-test/var/log/innodb.doublewrite-8k,innodb_plugin/' to 'I:/mysql/10.1/bld/mysql-test/var/log/innodb.doublewrite-8k,innodb_plugin/'
 - found 'mysqld.dmp' (0/5)
 
Trying 'cdb' to get a backtrace
Cannot find cdb. Please Install Debugging tools for Windows
from http://www.microsoft.com/whdc/devtools/debugging/install64bit.mspx (native x64 version)
 
Only  1  of 2 completed.
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 83.045 of 1110 seconds executing testcases
 
Failure: Failed 1/3 tests, 66.67% were successful.
 
Failing test(s): innodb.doublewrite
 
The log files in var/log may give you some hint of what went wrong.
 
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
 
mysql-test-run: *** ERROR: there were failing test cases
 
I:\mysql\10.1\bld\mysql-test>mysql-test-run.pl doublewrite,4k --repeat=100
Logging: I:/mysql/10.1/mysql-test/mysql-test-run.pl  doublewrite,4k --repeat=100
VS config: Debug
vardir: I:/mysql/10.1/bld/mysql-test/var
Checking leftover processes...
Removing old var directory...
Creating var directory 'I:/mysql/10.1/bld/mysql-test/var'...
Checking supported features...
MariaDB Version 10.1.26-MariaDB-debug
 - SSL connections supported
 - binaries are debug compiled
Sphinx 'indexer' binary not found, sphinx suite will be skipped
Collecting tests...
Installing system database...
 
==============================================================================
 
TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------
 
worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
innodb.doublewrite '4k,innodb_plugin'    [ fail ]
        Test ended at 2017-08-10 18:36:08
 
CURRENT_TEST: innodb.doublewrite
mysqltest: At line 325: query 'select f1, f2 from t1' failed: 1286: Unknown storage engine 'InnoDB'
 
The result from queries just before the failure was:
< snip >
# Test End
# ---------------------------------------------------------------
# Test Begin: Test if recovery works if first page of
# system tablespace is corrupted.
begin;
insert into t1 values (6, repeat('%', 400));
# Ensure that all dirty pages in the system are flushed.
set global innodb_buf_flush_list_now = 1;
# Make the first page dirty for system tablespace
set global innodb_saved_page_number_debug = 0;
set global innodb_fil_make_page_dirty_debug = 0;
# Ensure that the dirty page of system tablespace is also flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Corrupt the first page (page_no=0) of the system tablespace.
check table t1;
Table   Op      Msg_type        Msg_text
test.t1 check   Error   Unknown storage engine 'InnoDB'
test.t1 check   error   Corrupt
select f1, f2 from t1;

Comment by Jan Lindström (Inactive) [ 2017-08-10 ]

I can repeat on Linux (do not use --vardir=/dev/shm) but unfortunately can't get good stack:

innodb.doublewrite '16k,innodb_plugin'   w2 [ fail ]  Found warnings/errors in server log file!
        Test ended at 2017-08-10 21:28:46
line
170810 21:28:43 [ERROR] mysqld got signal 11 ;
Attempting backtrace. You can use the following information to find out
^ Found warnings in /home/jan/mysql/10.1/mysql-test/var/2/log/mysqld.1.err
ok
 
 - saving '/home/jan/mysql/10.1/mysql-test/var/2/log/innodb.doublewrite-16k,innodb_plugin/' to '/home/jan/mysql/10.1/mysql-test/var/log/innodb.doublewrite-16k,innodb_plugin/'
 - found 'core' (0/5)
 
Trying 'dbx' to get a backtrace
 
Trying 'gdb' to get a backtrace from coredump /home/jan/mysql/10.1/mysql-test/var/log/innodb.doublewrite-16k,innodb_plugin/mysqld.1/data/core
Core generated by '/home/jan/mysql/10.1/sql/mysqld'
Output from gdb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
[New LWP 31637]
[New LWP 31613]
[New LWP 31635]
[New LWP 31634]
[New LWP 31636]
[New LWP 31638]
[New LWP 31674]
[New LWP 31639]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/home/jan/mysql/10.1/sql/mysqld --defaults-group-suffix=.1 --defaults-file=/hom'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007fab33bb4c7b in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
[Current thread is 1 (Thread 0x7fab27bfc700 (LWP 31637))]
#0  0x00007fab33bb4c7b in ?? () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#1  0x00007fab33bb6618 in _Unwind_Backtrace () from /lib/x86_64-linux-gnu/libgcc_s.so.1
#2  0x00007fab338fcc6f in __GI___backtrace (array=<optimized out>, size=<optimized out>) at ../sysdeps/x86_64/backtrace.c:110
#3  0x000055aa0767c746 in my_print_stacktrace (stack_bottom=0x0, thread_stack=295936) at /home/jan/mysql/10.1/mysys/stacktrace.c:267
#4  0x000055aa07018b6f in handle_fatal_signal (sig=11) at /home/jan/mysql/10.1/sql/signal_handler.cc:166
#5  <signal handler called>
#6  0x00007fab2c38307e in ?? ()
#7  0x00007fab2c4f3138 in ?? ()
#8  0x0000000000000100 in ?? ()
#9  0x0000000000000001 in ?? ()
#10 0x00007fab2dfff060 in ?? ()
#11 0x0000000100000007 in ?? ()
#12 0x00007fab3240e730 in ?? ()
#13 0x00007fab2e3f1000 in ?? ()
#14 0x00007fab366bf000 in ?? ()
#15 0x0000000000000100 in ?? ()
#16 0x0000000000000200 in ?? ()
#17 0x00007fab27bfbc50 in ?? ()
#18 0x00007fab2c386451 in ?? ()
#19 0x0000000000000000 in ?? ()

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

jplindst, your comment about SIGSEGV on Linux seems to be a known problem: server crash on shutdown after aborted InnoDB startup. At the end of the test, we have such a scenario that hit SIGSEGV for both me and elenst when running 10.1 with

./mtr --valgrind innodb.doublewrite,16k,innodb_plugin

--echo #
--echo # MDEV-12600 crash during install_db with innodb_page_size=32K
--echo # and ibdata1=3M
--echo #
let bugdir= $MYSQLTEST_VARDIR/tmp/doublewrite;
--mkdir $bugdir
 
let $check_no_innodb=SELECT * FROM INFORMATION_SCHEMA.ENGINES
WHERE engine = 'innodb'
AND support IN ('YES', 'DEFAULT', 'ENABLED');
 
--let $ibp=--innodb-log-group-home-dir=$bugdir --innodb-data-home-dir=$bugdir
--let $ibd=$ibp --innodb-undo-tablespaces=0 --innodb-log-files-in-group=2
--let $ibp=$ibp --innodb-data-file-path=ibdata1:1M;ibdata2:1M:autoextend
 
--let $restart_parameters= $ibp
--source include/restart_mysqld.inc
eval $check_no_innodb;
--let SEARCH_PATTERN= \[ERROR\] InnoDB: Cannot create doublewrite buffer
--source include/search_pattern_in_file.inc
--let $restart_parameters=
--source include/restart_mysqld.inc

In MariaDB 10.2, I have made numerous fixes to allow the server to shut down cleanly after aborted InnoDB startup. One of the first fixes was January 31, 2017. Such large refactoring is not possible in a GA release.

It seems that we never got this kind of a failure on buildbot.

The problems that were observed on Windows are more alarming, because they seem to hint that the contents of the buffer pool is corrupted, or alternatively that the block->lock is not correctly protecting the block->frame contents during I/O.

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

For the record, with Valgrind, the crash at shutdown after aborted InnoDB startup looks like this:

2017-08-11 14:43:44 67431040 [Warning] InnoDB: New log files created, LSN=45890
2017-08-11 14:43:44 67431040 [ERROR] InnoDB: Cannot create doublewrite buffer: the first file in innodb_data_file_path must be at least 3M.
2017-08-11 14:43:44 67431040 [ERROR] InnoDB: Database creation was aborted at /mariadb/10.1/storage/innobase/srv/srv0start.cc [2821] with error Generic error. You may need to delete the ibdata1 file before trying to start up again.
2017-08-11 14:43:44 67431040 [ERROR] Plugin 'InnoDB' init function returned error.
2017-08-11 14:43:44 67431040 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2017-08-11 14:43:44 67431040 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2017-08-11 14:43:44 67431040 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
2017-08-11 14:43:44 67431040 [Warning] /mariadb/10.1/bld/sql/mysqld: unknown option '--loose-pam-debug'
2017-08-11 14:43:44 67431040 [Warning] /mariadb/10.1/bld/sql/mysqld: unknown option '--loose-skip-plugin-innodb-changed-pages'
2017-08-11 14:43:44 67431040 [Note] Server socket created on IP: '127.0.0.1'.
2017-08-11 14:43:45 67431040 [Note] /mariadb/10.1/bld/sql/mysqld: ready for connections.
Version: '10.1.26-MariaDB-debug'  socket: '/mariadb/10.1/bld/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  Source distribution
2017-08-11 14:43:46 68348672 [Note] /mariadb/10.1/bld/sql/mysqld: Normal shutdown
 
2017-08-11 14:43:46 68348672 [Note] Event Scheduler: Purging the queue. 0 events
==12404== Thread 5:
==12404== Jump to the invalid address stated on the next line
==12404==    at 0xBC494A7: ???
==12404==    by 0xBC49855: ???
==12404==    by 0xBB5A80A: ???
==12404==    by 0xBD2E339: ???
==12404==    by 0x4E3F493: start_thread (pthread_create.c:333)
==12404==    by 0x66AAABE: clone (clone.S:97)
==12404==  Address 0xbc494a7 is not stack'd, malloc'd or (recently) free'd
==12404== 
170811 14:43:46 [ERROR] mysqld got signal 11 ;

Comment by Jan Lindström (Inactive) [ 2017-08-14 ]

Shorter version where page corruption was repeatable Win32Debug

Comment by Marko Mäkelä [ 2017-08-14 ]

I looked at some of the attached dumps. To my surprise, I did not find any sign of a doublewrite buffer copy of page 0:1 (which is mentioned in some of the buffer pool crashes) in the attachments.
In case2_8k.zip, the doublewrite buffer page numbers are 128‥255, corresponding to the file offset 0x100000‥0x1fffff. In the ibdata1 file, all bytes from 0x100000 to 0x2ffffff are zero. So, the doublewrite buffer was apparently not enabled at all (why? was this the original, unmodified test?). In this test, the failure occurs because the intentionally corrupted page 0:1 cannot be restored (unsurprisingly).

Comment by Alice Sherepa [ 2017-08-18 ]

innodb.doublewrite '4k,innodb_plugin' failed on windows http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/4896/steps/test/logs/stdio

innodb.doublewrite '4k,innodb_plugin'    w2 [ fail ]
        Test ended at 2017-08-17 14:19:48
 
CURRENT_TEST: innodb.doublewrite
mysqltest: At line 247: query 'select f1, f2 from t1' failed: 1932: Table 'test.t1' doesn't exist in engine
 
The result from queries just before the failure was:
< snip >
# tablespace is corrupted.
select space from information_schema.innodb_sys_tables
where name = 'test/t1' into @space_id;
# Ensure that dirty pages of table t1 is flushed.
flush tables t1 for export;
unlock tables;
begin;
insert into t1 values (6, repeat('%', 400));
# Make the 2nd page dirty for table t1
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = @space_id;
# Ensure that the dirty pages of table t1 are flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Corrupt the 2nd page (page_no=1) of the user tablespace.
check table t1;
Table	Op	Msg_type	Msg_text
test.t1	check	Error	Table 'test.t1' doesn't exist in engine
test.t1	check	status	Operation failed
select f1, f2 from t1;

2017-08-17 14:19:24 2452 [ERROR] InnoDB: innodb-page-size mismatch in tablespace .\test\t1.ibd (table test/t1)
InnoDB: Error: Current page size 4096 !=  page size on page 16384
2017-08-17 14:19:31 376 [ERROR] InnoDB: innodb-page-size mismatch in tablespace .\test\t1.ibd (table test/t1)
InnoDB: Error: Current page size 4096 !=  page size on page 16384
2017-08-17 14:19:45 2024 [ERROR] InnoDB: Database page corruption on disk or a failed file read of tablespace test/t1 page  [page id: space=4, page number=1]. You may have to recover from a backup.
2017-08-17 14:19:47 5996 [ERROR] InnoDB: Table "test"."t1" is corrupted. Please drop the table and recreate.len 4096; hex 
2017-08-17 14:19:47 5996 [Warning] InnoDB: Cannot open table test/t1 from the internal data dictionary of InnoDB though the .frm file for the table exists. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html for how you can resolve the problem.
2017-08-17 14:19:47 5996 [ERROR] InnoDB: Table "test"."t1" is corrupted. Please drop the table and recreate.

Comment by Marko Mäkelä [ 2017-08-18 ]

alice, please file separate issues for different problems and try to analyze the logs more carefully.
This MDEV-12905 originally reported a crash during SQL statement execution:

CURRENT_TEST: innodb.doublewrite
mysqltest: At line 220: query 'set global innodb_fil_make_page_dirty_debug = @space_id' failed: 2013: Lost connection to MySQL server during query

It appears that the log files for this run are no longer available. I would have wanted to check what is in the corresponding mysqld.1.err file.
The original issue may have been repeated by jplindst who reported later in this issue that the buffer pool contains a corrupted copy of page 0:1, detected in this stack trace:

 	ha_innodb.dll!abort() Line 51	C++
>	ha_innodb.dll!buf_block_align_instance(buf_pool_t * buf_pool, const unsigned char * ptr) Line 2864	C++
 	ha_innodb.dll!buf_block_align(const unsigned char * ptr) Line 2894	C++
 	ha_innodb.dll!mtr_memo_contains_page(mtr_t * mtr, const unsigned char * ptr, unsigned long type) Line 420	C++
 	ha_innodb.dll!ibuf_bitmap_page_get_bits_low(const unsigned char * page, unsigned long page_no, unsigned long zip_size, unsigned long latch_type, mtr_t * mtr, unsigned long bit) Line 740	C++
 	ha_innodb.dll!ibuf_merge_or_delete_for_page(buf_block_t * block, unsigned long space_id, unsigned long page_no, unsigned long zip_size, unsigned long update_ibuf_bitmap) Line 4638	C++

This MDEV-12905 ticket was also convoluted with reports of a known problem that the server may crash on shutdown after failed InnoDB startup. I fixed the issue in 10.2, but I think that it would require too big changes to 10.1 or earlier.

Let me now extract the relevant data from the logs:

innodb.doublewrite '4k,innodb_plugin'    w2 [ fail ]
        Test ended at 2017-08-17 14:19:48
 
CURRENT_TEST: innodb.doublewrite
mysqltest: At line 247: query 'select f1, f2 from t1' failed: 1932: Table 'test.t1' doesn't exist in engine

We have to look for this timestamp 2017-08-17 14:19:48 (give or take a few seconds) in the mysqld.1.err file that corresponds to worker 2. The timestamps 14:19:24 and 14:19:31 are definitely from other runs and not relevant, because they were generated by deliberate fault injection. You also did not dig up the reason why the server did not start up.
The cause for these repeated page dumps could be MDEV-11799.
The server error log suggests that the startup took too long because of the repeated page dumps (InnoDB was still starting up, spitting page dumps), and the server was killed at 14:19:48.
The server restarted only 4 seconds earlier, after forced kill in no_checkpoint-end.inc:

2017-08-17 14:19:42 4012 [Note] InnoDB: Dirtying page:1 of space:4
2017-08-17 14:19:44 4500 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.1.27-MariaDB-debug) starting as process 2396 ...

The above log snippet corresponds to these lines in doublewrite.test:

--echo # Make the 2nd page dirty for table t1
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = @space_id;
 
--echo # Ensure that the dirty pages of table t1 are flushed.
set global innodb_buf_flush_list_now = 1;
 
--source include/no_checkpoint_end.inc
 
--echo # Corrupt the 2nd page (page_no=1) of the user tablespace.
perl;
use IO::Handle;
my $fname= "$ENV{'MYSQLD_DATADIR'}test/t1.ibd";
open(FILE, "+<", $fname) or die;
FILE->autoflush(1);
binmode FILE;
seek(FILE, $ENV{'INNODB_PAGE_SIZE'}, SEEK_SET);
print FILE chr(0) x ($ENV{'INNODB_PAGE_SIZE'}/2);
close FILE;
EOF
 
--source include/start_mysqld.inc

To add insult to injury, the CURRENT_TEST line immediately before the next startup is preceded by a page dump (a long sequence of zeroes). The next startup is this one, probably for the retry attempt:

2017-08-17 14:20:02 2500 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.1.27-Maria2017-08-17 14:20:02 2500 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.1.27-MariaDB-debug) starting as process 4912 ...
2017-08-17 14:20:02 2500 [Note] InnoDB:  innodb-page-size has been changed from the default value 16384 to 4096.

So, we have two questions to ask:

  1. Why did the SELECT time out so quickly (in only 4 seconds) and decide that the server did not start up?
  2. What was the contents of the doublewrite buffer? Can this be an occurrence of MDEV-11799 (Buildbot does not preserve the ibdata1 file, so we will never know.)
Comment by Jan Lindström (Inactive) [ 2017-08-18 ]

Latest crash on Windows on var.zip test log:

# ---------------------------------------------------------------
# Test Begin: Test if recovery works if 2nd page of
# system tablespace is full of zeroes.
begin;
insert into t1 values (6, repeat('%', 400));
# Ensure that all dirty pages in the system are flushed.
set global innodb_buf_flush_list_now = 1;
# Make the second page dirty for system tablespace
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = 0;
# Ensure that the dirty page of system tablespace is also flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Make the 2nd page (page_no=1) of the system tablespace
# all zeroes.
# Start 7
# 

Comment by Marko Mäkelä [ 2017-08-18 ]

I can confirm that the log/mysqld.1.err in var.zip corresponds to the restart after this fault injection:

--echo # Make the second page dirty for system tablespace
set global innodb_saved_page_number_debug = 1;
set global innodb_fil_make_page_dirty_debug = 0;
 
--echo # Ensure that the dirty page of system tablespace is also flushed.
set global innodb_buf_flush_list_now = 1;
 
--source include/kill_mysqld.inc
 
--echo # Make the 2nd page (page_no=1) of the system tablespace
--echo # all zeroes.

I can also confirm that the ibdata1_start7 page 1 (bytes 0x1000 to 0x1fff) are all zero.
Then, I proceeded to start up the server with this file:

./mtr --mem --manual-gdb innodb.doublewrite,innodb_plugin
cd /path/to/restored
unzip var.zip
ln -s backup/ib_logfile0_start7 ib_logfile0
ln -s backup/ib_logfile1_start7 ib_logfile1
ln -s backup/ibdata1_start7 ibdata1
cd -
# [interrupt]
# [copy and adapt the arguments from the generated file]
gdb ../sql/mysqld
run --defaults-group-suffix=.1 --defaults-file=/mariadb/10.1/build/mysql-test/var/my.cnf --debug=d,ib_log --log-output=file --gdb --ignore-builtin-innodb --plugin-load-add=ha_innodb.so --innodb-page-size=4K --gdb --innodb-log-group-home-dir=/path/to/restored --innodb-data-home-dir=/path/to/restored

Yes, this will point datadir to the instance created by mtr bootstrap. And yes, the t1.ibd is missing. What matters for InnoDB should be the system tablespace and the redo log files.

As expected, no redo log was applied (the redo log was clean). After startup and clean shutdown, the system tablespace page 1 was not recovered from the doublewrite buffer (the file still contained zeroes in that page).
The doublewrite buffer is located at pages 256 to 511:

00005f40: 0032 1fff bd5f 0000 0100 0000 0200 1fff  .2..._..........

The doublewrite buffer does not contain a copy of that page. It only contains these 3 pages:

unzip -p var.zip backup/ibdata1_start7|od -Ax -t x1 -j 0x100000 -N 0x100000|grep -B 2 '020\>'
100000 07 99 92 8b 00 00 03 2c 00 00 00 00 00 00 00 00
100010 00 00 00 00 00 0b 2b 34 00 02 00 00 00 00 00 00
100020 00 00 00 00 00 00 00 01 01 10 01 1c ff ff ff ff
--
101000 af 00 06 27 00 00 00 03 ff ff ff ff ff ff ff ff
101010 00 00 00 00 00 0b 2d 03 45 bf 00 00 00 00 00 00
101020 00 00 00 00 00 04 00 02 02 f9 80 09 01 33 00 24
--
102000 8e 53 5a c2 00 00 03 2c 00 00 00 00 00 00 00 00
102010 00 00 00 00 00 0b 2b 04 00 02 00 00 00 00 00 00
102020 00 00 00 00 00 00 00 01 01 10 01 10 ff ff ff ff

These are pages 0:0x32c, 4:3 (the clustered index root page of t1_start7.ibd), and 0:0x32c again.
There is no copy of page 0:1, even though the test wanted to write that.
Side note: page 0:0x32c is an undo log page, apparently for updating a record that contains the string gtid_slave_pos:

unzip -p var.zip backup/ibdata1_start7|od -Ax -t x1 -j 0x32c000 -N 0x1000
32c000 07 99 92 8b 00 00 03 2c 00 00 00 00 00 00 00 00
32c010 00 00 00 00 00 0b 2b 34 00 02 00 00 00 00 00 00
32c020 00 00 00 00 00 00 00 01 01 10 01 1c ff ff ff ff
32c030 00 00 ff ff ff ff 00 00 00 01 00 56 00 00 00 00
32c040 00 00 03 28 09 32 00 00 00 01 00 00 03 2c 00 2c
32c050 00 00 03 2c 00 2c 00 00 00 00 00 00 13 04 00 00
32c060 00 00 00 00 00 00 00 01 01 10 00 00 00 00 00 00
32c070 00 00 00 11 00 00 00 00 00 00 00 00 00 00 00 00
32c080 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
*
32c110 01 1c 0b 00 12 04 80 00 00 06 01 10 67 74 69 64
32c120 5f 73 6c 61 76 65 5f 70 6f 73 01 10 01 41 0b 01

So, the assertion failure is catching a genuine bug: the page 0:1 that our test intentionally corrupted was loaded in corrupted form to the buffer pool.
Actually, it is revealing 2 bugs:

  1. innodb_fil_make_page_dirty_debug somehow skipped the write to the doublewrite buffer
  2. we loaded an all-zero page into the buffer pool; maybe in MDEV-13542 we should return an error to the buf_page_get_gen() caller for trying to read all-zero pages
Comment by Marko Mäkelä [ 2017-08-18 ]

jplindst, I am reassigning this to you, because you can repeat this in your environment.

For me, the doublewrite buffer does contain a copy of the page 0:1 at that point of the test:

diff --git a/mysql-test/suite/innodb/t/doublewrite.test b/mysql-test/suite/innodb/t/doublewrite.test
index aba3d6ecff5..8fb7a339f6a 100644
--- a/mysql-test/suite/innodb/t/doublewrite.test
+++ b/mysql-test/suite/innodb/t/doublewrite.test
@@ -380,6 +380,7 @@ set global innodb_fil_make_page_dirty_debug = 0;
 --echo # Ensure that the dirty page of system tablespace is also flushed.
 set global innodb_buf_flush_list_now = 1;
 
+--copy_file $MYSQLD_DATADIR/ibdata1 $MYSQLD_DATADIR/ibdata1_start7
 --source include/kill_mysqld.inc
 
 --echo # Make the 2nd page (page_no=1) of the system tablespace

./mtr --mem innodb.doublewrite,4k,innodb_plugin
od -Ax -t x1 var/mysqld.1/data/ibdata1_start7 -j 0x100000 -N 0x100000|grep -B 2 '020\>'
100000 f2 e6 bb 7a 00 00 00 01 00 00 00 00 00 00 00 00
100010 00 00 00 00 00 0b 2f 38 00 05 00 00 00 00 00 00
100020 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
--
101000 ae f6 82 52 00 00 00 03 ff ff ff ff ff ff ff ff
101010 00 00 00 00 00 0b 2f 32 45 bf 00 00 00 00 00 00
101020 00 00 00 00 00 04 00 02 02 f9 80 09 01 33 00 24
--
102000 48 76 9e cd 00 00 03 2c 00 00 00 00 00 00 00 00
102010 00 00 00 00 00 0b 2d 33 00 02 00 00 00 00 00 00
102020 00 00 00 00 00 00 00 01 01 10 01 10 ff ff ff ff

See, pages 0:1, 4:3, and 0:0x32c are there. And yes, 0:0x32c is an undo log page that looks equivalent to the ibdata1_start7 in var.zip.

Comment by Marko Mäkelä [ 2017-08-18 ]

Note: the stack trace with the assertion failure is the path how we currently detect the corrupted (all-zero) first change buffer bitmap page of the system tablespace (page 0:1). The change buffer bitmap would be consulted for determining if there are any unmerged changes to pages in the range 2‥innodb_page_size-1. Any read of the pages in the range 0‥innodb_page_size-1 will require page 0:1 to be loaded and consulted. Because the InnoDB internal data dictionary tables are stored in this page range, this corruption of the change buffer bitmap page should be noticed on every server InnoDB startup, when the 4 hard-coded InnoDB dictionary tables are being loaded in dict_boot().
(I cannot currently explain why it did not fail for me when I tried to start up InnoDB on the ibdata1_start7 file.)

Comment by Marko Mäkelä [ 2017-09-25 ]

One more failure on 32-bit Windows:

innodb.doublewrite '64k,innodb_plugin'   w4 [ fail ]
        Test ended at 2017-09-25 09:06:38
 
CURRENT_TEST: innodb.doublewrite
 
 
Server [mysqld.1 - pid: 1212, winpid: 1212, exit: 768] failed during test run
# Ensure that dirty pages of table t1 are flushed.
set global innodb_buf_flush_list_now = 1;
# Kill the server
# Corrupt the first page (page_no=0) of the user tablespace.
 
 
 
 - saving 'D:/win32-debug/build/mysql-test/var/4/log/innodb.doublewrite-64k,innodb_plugin/' to 'D:/win32-debug/build/mysql-test/var/log/innodb.doublewrite-64k,innodb_plugin/'
 
Retrying test innodb.doublewrite, attempt(2/3)...
 
***Warnings generated in error logs during shutdown after running tests: innodb.doublewrite
 
2017-09-25  9:06:31 5108 [ERROR] InnoDB: innodb-page-size mismatch in tablespace .\test\t1.ibd (table test/t1)
InnoDB: Error: Current page size 65536 !=  page size on page 16384
2017-09-25  9:06:37 6752 [ERROR] InnoDB: innodb-page-size mismatch in tablespace .\test\t1.ibd (table test/t1)
2017-09-25  9:06:37 6752 [Warning] InnoDB: Doublewrite does not have page_no=0 of space: 4

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

I believe that I have repeated the same problem once on 10.2, using

cmake -DCMAKE_BUILD_TYPE=RelWithDebInfo -DWITH_ASAN=1

with the following symptoms:

CURRENT_TEST: innodb.log_file_name
mysqltest: At line 135: query 'SELECT * FROM t3' failed: 2013: Lost connection to MySQL server during query

This SELECT should be the very first SQL access to table t3 after the server was originally killed. Before the kill, there were only INSERT and COMMIT, so there should be nothing to roll back or (in 10.2, before MDEV-12288 which is in 10.3) to purge:

--source include/no_checkpoint_start.inc
CREATE TABLE t3(a INT PRIMARY KEY) ENGINE=InnoDB;
 
BEGIN;
INSERT INTO t3 VALUES (33101),(347);
INSERT INTO t1 VALUES (42),(9),(101);
RENAME TABLE t1 TO t2;
UPDATE t2 SET a=347 where a=42;
COMMIT;
 
--let CLEANUP_IF_CHECKPOINT=DROP TABLE t2,t3;
--source include/no_checkpoint_end.inc

The last statement would kill the server. After this, the test does move t3.ibd around, and it is expecting the InnoDB startup to fail due to various consistencies that should prevent a redo log apply (WL#7142) and cause InnoDB to refuse startup.
The crashing SELECT is after the very first expected-to-be-successful recovery attempt:

# Restore t2.ibd
--remove_file $MYSQLD_DATADIR/test/t2.ibd
--move_file $MYSQLD_DATADIR/test/t.ibd $MYSQLD_DATADIR/test/t2.ibd
 
--source include/start_mysqld.inc
 
SELECT * FROM t2;
SELECT * FROM t3;

The crash occurs, because the file t3.ibd is uninitialized, except for the first page that contains some valid information:

od -Ax -t x1 bld/mysql-test/var/log/innodb.log_file_name-innodb/mysqld.1/data/test/t3.ibd 
000000 d7 ca d3 0a 00 00 00 00 00 00 00 00 00 00 00 00
000010 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
000020 00 00 00 00 00 b3 00 00 00 b3 00 00 00 00 00 00
000030 00 00 00 00 00 00 00 00 00 21 00 00 00 00 00 00
000040 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
*
003ff0 00 00 00 00 00 00 00 00 d7 ca d3 0a 00 00 00 00
004000 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
*
018000

The doublewrite buffer is located at pages 64 to 128 (I would expect 64 to 192):

od -t x1 -Ax -N 16 -j 0x17f40 bld/mysql-test/var/log/innodb.log_file_name-innodb/mysqld.1/data/ibdata1 
017f40 0a b2 1f ff bd 5f 00 00 00 40 00 00 00 80 1f ff
017f50

Looking at pages 64 to 192, I see no buffered changes for this tablespace (space_id=0xb3):

od -t x1 -Ax -N 0x200000 -j 0x100000 bld/mysql-test/var/log/innodb.log_file_name-innodb/mysqld.1/data/ibdata1 |grep -B 2 '[048c]020\>.*b3'
114000 f1 f2 81 12 00 00 00 0c ff ff ff ff ff ff ff ff
114010 00 00 00 00 05 b5 54 25 45 bf 00 00 00 00 00 00
114020 00 00 00 00 00 00 00 06 1b dc 00 b3 1b 3f 18 60

The false match is for the page 0:12. So, nothing was buffered for t3.ibd.
Here is the SYS_TABLES record for the table. (There were also a couple delete-marked entries; I suppose the name test.t3 was used in some preceding tests.)

000213d0: b200 0000 5000 0000 ae34 b030 2c24 201c  ....P....4.0,$ .
000213e0: 140d 0700 01e8 1500 7474 6573 742f 7433  ........ttest/t3
000213f0: 0000 0000 1b83 d400 0001 8501 1000 0000  ................
00021400: 0000 0000 f380 0000 0100 0000 2100 0000  ............!...
00021410: 0000 0000 0000 0000 5000 0000 b300 0000  ........P.......

This decodes to (NAME,DB_TRX_ID,DB_ROLL_PTR,ID,N_COLS,TYPE,MIX_ID,MIX_LEN,CLUSTER_NAME,SPACE)
as follows: NAME='test/t3',ID=0xf3, N_COLS=1|(ROW_FORMAT!=REDUNDANT), TYPE=0x21, MIX_ID=0, MIX_LEN=0x50,CLUSTER_NAME=NULL,SPACE=0xb3.
For reference, the first byte of the record header is at 0x213d9, and it says that the last column is 4 bytes, ending at offset 0x34 from the record start. This indeed is the field SPACE=0xb3, which matches page 0 of t3.ibd.

I believe that I have proven that the same problem is repeatable on 10.2, with different symptoms. For some reason, before the test killed the server, there was nothing written to the doublewrite buffer for that tablespace 0xb3 (t3.ibd). This looks very very wrong.

For some reason, the problem is more easily repeatable on the 10.1 innodb_plugin on Windows, using the test innodb.doublewrite. Based on the above, I do not think that the problem is limited to that platform.

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

For the record, here is the relevant part of the error log for the above innodb.log_file_name failure:

CURRENT_TEST: innodb.log_file_name
2017-10-11 12:01:15 139847651086784 [Note] /mariadb/10.2/bld/sql/mysqld (mysqld 10.2.10-MariaDB-log) starting as process 30950 ...
2017-10-11 12:01:34 140067481366976 [Note] /mariadb/10.2/bld/sql/mysqld (mysqld 10.2.10-MariaDB-log) starting as process 32089 ...
Version: '10.2.10-MariaDB-log'  socket: '/mariadb/10.2/bld/mysql-test/var/tmp/1/mysqld.1.sock'  port: 16060  Source distribution
2017-10-11 12:01:35 140067061847808 [ERROR] InnoDB: Flag mismatch in page [page id: space=179, page number=3] index `PRIMARY` of table `test`.`t3`
2017-10-11 12:01:35 0x7f63e7775700  InnoDB: Assertion failure in file /mariadb/10.2/storage/innobase/btr/btr0btr.cc line 185
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
171011 12:01:35 [ERROR] mysqld got signal 6 ;

The first startup message is the first (failed) recovery attempt after the test killed the server. There are several failed startup attempts initiated by the test. The last messages are from the last recovery attempt, which should have succeeded.

For the record, on the second recovery attempt we did get this message for the file t3.ibd, and apparently did not refuse startup as expected:

2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: The error means the system cannot find the path specified.
2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: Cannot open datafile for read-only: './test/t3.ibd' OS error: 71
2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: Operating system error number 2 in a file operation.
2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: The error means the system cannot find the path specified.
2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: If you are installing InnoDB, remember that you must create directories yourself, InnoDB does not create them.
2017-10-11 12:01:21 140400653447616 [ERROR] InnoDB: Could not find a valid tablespace file for `test/t3`. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.
2017-10-11 12:01:21 140400653447616 [Warning] InnoDB: Ignoring tablespace for `test`.`t3` because it could not be opened.
2017-10-11 12:01:21 140400653447616 [Note] InnoDB: 128 out of 128 rollback segments are active.
2017-10-11 12:01:21 140400653447616 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2017-10-11 12:01:21 140400653447616 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-10-11 12:01:21 140400653447616 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2017-10-11 12:01:21 140400653447616 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-10-11 12:01:21 140400653447616 [Note] InnoDB: 5.7.19 started; log sequence number 95773105

This corresponds to the following test snippet:

--echo # Fault 2: Wrong space_id in a dirty file, and a missing file.
--move_file $MYSQLD_DATADIR/test/t3.ibd $MYSQLD_DATADIR/test/t1.ibd
 
--source include/start_mysqld.inc
eval $check_no_innodb;
 
let SEARCH_PATTERN= InnoDB: Ignoring data file '.*t1.ibd' with space ID.*;
--source include/search_pattern_in_file.inc
 
let SEARCH_PATTERN= InnoDB: Tablespace \d+ was not found at.*t3.ibd.*;
--source include/search_pattern_in_file.inc
 
--source include/shutdown_mysqld.inc

In the log_file_name.log we indeed got the unexpected result that InnoDB did start up:

# Fault 2: Wrong space_id in a dirty file, and a missing file.
SELECT * FROM INFORMATION_SCHEMA.ENGINES
WHERE engine = 'innodb'
AND support IN ('YES', 'DEFAULT', 'ENABLED');
ENGINE	SUPPORT	COMMENT	TRANSACTIONS	XA	SAVEPOINTS
InnoDB	YES	Supports transactions, row-level locking, foreign keys and encryption for tables	YES	YES	YES
FOUND 1 /InnoDB: Ignoring data file '.*t1.ibd' with space ID.*/ in mysqld.1.err
FOUND 1 /InnoDB: Tablespace \d+ was not found at.*t3.ibd.*/ in mysqld.1.err

It is theoretically possible that the doublewrite entries for t3.ibd were cleared at this recovery attempt, which should have failed. We really should have refused to start up the server, because --innodb-force-recovery was not specified and we were unable to find a data file for which there were changes since the latest redo log checkpoint.

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

To track the Fault 2 mentioned above, I filed the following issue:
MDEV-14049 InnoDB fails to refuse startup when a file is not found in crash recovery

One last dump before I abandon the dataset. Here are the page headers for all doublewrite buffer entries that are not referring to the system tablespace (I separately verified that the maximum space ID was less than 0xff):

od -t x1 -Ax -N 0x200000 -j 0x100000 bld/mysql-test/var/log/innodb.log_file_name-innodb/mysqld.1/data/ibdata1 |grep -B 2 '[048c]020\> .. .. 00 00 00 0\?[^0]'
138000 15 ff db 5e 00 00 00 01 00 00 00 00 00 00 00 00
138010 00 00 00 00 05 b5 43 26 00 05 00 00 00 00 00 00
138020 00 00 00 00 00 b2 00 00 00 00 00 00 00 00 00 00
--
13c000 de 52 fa 4d 00 00 00 00 00 00 00 00 00 00 00 00
13c010 00 00 00 00 05 b5 50 27 00 08 00 00 00 00 00 00
13c020 00 00 00 00 00 b2 00 00 00 b2 00 00 00 00 00 00
--
144000 72 81 c7 fe 00 00 00 02 00 00 00 00 00 00 00 00
144010 00 00 00 00 05 b5 50 27 00 03 00 00 00 00 00 00
144020 00 00 00 00 00 b2 ff ff ff ff 00 00 ff ff ff ff
--
148000 07 3f 5a 7f 00 00 00 03 ff ff ff ff ff ff ff ff
148010 00 00 00 00 05 b5 61 e8 45 bf 00 00 00 00 00 00
148020 00 00 00 00 00 b2 00 02 00 d0 80 06 00 7d 00 16
--
170000 5f 47 ec 8e 00 00 00 3f 00 00 00 3e 00 00 00 80
170010 00 00 00 00 05 92 b9 a1 45 bf 00 00 00 00 00 00
170020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
178000 67 af 59 cc 00 00 00 59 00 00 00 58 00 00 00 5a
178010 00 00 00 00 05 91 d2 28 45 bf 00 00 00 00 00 00
178020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
17c000 d7 b7 48 fd 00 00 00 5a 00 00 00 59 00 00 00 5b
17c010 00 00 00 00 05 92 79 25 45 bf 00 00 00 00 00 00
17c020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
180000 67 31 15 c6 00 00 00 80 00 00 00 3f 00 00 00 81
180010 00 00 00 00 05 94 25 7d 45 bf 00 00 00 00 00 00
180020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
188000 44 91 d0 5b 00 00 00 5b 00 00 00 5a 00 00 00 5c
188010 00 00 00 00 05 93 20 82 45 bf 00 00 00 00 00 00
188020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
190000 68 f2 38 57 00 00 00 5c 00 00 00 5b 00 00 00 5d
190010 00 00 00 00 05 93 c7 7f 45 bf 00 00 00 00 00 00
190020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
194000 0e 8c ca c6 00 00 00 81 00 00 00 80 00 00 00 82
194010 00 00 00 00 05 95 91 bb 45 bf 00 00 00 00 00 00
194020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
198000 98 1e 93 94 00 00 00 5d 00 00 00 5c 00 00 00 5e
198010 00 00 00 00 05 94 6e d0 45 bf 00 00 00 00 00 00
198020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1a0000 0d 8e 02 82 00 00 00 5e 00 00 00 5d 00 00 00 5f
1a0010 00 00 00 00 05 95 15 d9 45 bf 00 00 00 00 00 00
1a0020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1a4000 a7 fa cb e3 00 00 00 82 00 00 00 81 00 00 00 83
1a4010 00 00 00 00 05 96 fd 97 45 bf 00 00 00 00 00 00
1a4020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
1a8000 2d 64 47 e4 00 00 00 5f 00 00 00 5e 00 00 00 60
1a8010 00 00 00 00 05 95 bd 8c 45 bf 00 00 00 00 00 00
1a8020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1b0000 4c 4b dd 6f 00 00 00 60 00 00 00 5f 00 00 00 61
1b0010 00 00 00 00 05 96 64 37 45 bf 00 00 00 00 00 00
1b0020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1b8000 f4 8e 1f 88 00 00 00 83 00 00 00 82 00 00 00 84
1b8010 00 00 00 00 05 98 6a e8 45 bf 00 00 00 00 00 00
1b8020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
1bc000 f6 b8 dd 29 00 00 00 61 00 00 00 60 00 00 00 62
1bc010 00 00 00 00 05 97 0b e6 45 bf 00 00 00 00 00 00
1bc020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1c0000 0a a2 2e ea 00 00 00 62 00 00 00 61 00 00 00 63
1c0010 00 00 00 00 05 97 b2 f3 45 bf 00 00 00 00 00 00
1c0020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1c8000 55 86 f7 a6 00 00 00 84 00 00 00 83 00 00 00 c0
1c8010 00 00 00 00 05 99 d7 26 45 bf 00 00 00 00 00 00
1c8020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
1cc000 92 53 2c 87 00 00 00 63 00 00 00 62 00 00 00 64
1cc010 00 00 00 00 05 98 59 9c 45 bf 00 00 00 00 00 00
1cc020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1d4000 1f 1a 6a 30 00 00 00 64 00 00 00 63 00 00 00 65
1d4010 00 00 00 00 05 99 02 54 45 bf 00 00 00 00 00 00
1d4020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1d8000 ff 1f 2e 11 00 00 00 65 00 00 00 64 00 00 00 66
1d8010 00 00 00 00 05 99 a8 f6 45 bf 00 00 00 00 00 00
1d8020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1dc000 4b e6 50 4c 00 00 00 c0 00 00 00 84 00 00 00 c1
1dc010 00 00 00 00 05 9b 42 fa 45 bf 00 00 00 00 00 00
1dc020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
1e4000 db 6e 99 79 00 00 00 66 00 00 00 65 00 00 00 67
1e4010 00 00 00 00 05 9a 50 9a 45 bf 00 00 00 00 00 00
1e4020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1e8000 2f 94 9e 9f 00 00 00 67 00 00 00 66 00 00 00 68
1e8010 00 00 00 00 05 9a f7 a3 45 bf 00 00 00 00 00 00
1e8020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1f0000 18 17 01 e6 00 00 00 c1 00 00 00 c0 00 00 00 c2
1f0010 00 00 00 00 05 9c ae ce 45 bf 00 00 00 00 00 00
1f0020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
1f4000 c7 53 33 93 00 00 00 68 00 00 00 67 00 00 00 69
1f4010 00 00 00 00 05 9b 9e ec 45 bf 00 00 00 00 00 00
1f4020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
1fc000 8a f2 be 75 00 00 00 69 00 00 00 68 00 00 00 6a
1fc010 00 00 00 00 05 9c 45 e9 45 bf 00 00 00 00 00 00
1fc020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
200000 f8 26 de 50 00 00 00 c2 00 00 00 c1 00 00 00 c3
200010 00 00 00 00 05 9e 1b 04 45 bf 00 00 00 00 00 00
200020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
204000 87 a8 df 66 00 00 00 6a 00 00 00 69 00 00 00 6b
204010 00 00 00 00 05 9c ed a0 45 bf 00 00 00 00 00 00
204020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
20c000 e9 03 be ee 00 00 00 6b 00 00 00 6a 00 00 00 6c
20c010 00 00 00 00 05 9d 94 4b 45 bf 00 00 00 00 00 00
20c020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
210000 10 5c da 2f 00 00 00 c3 00 00 00 c2 00 00 00 c4
210010 00 00 00 00 05 9f 86 d8 45 bf 00 00 00 00 00 00
210020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
218000 25 b1 90 e4 00 00 00 6c 00 00 00 6b 00 00 00 6d
218010 00 00 00 00 05 9e 3b e6 45 bf 00 00 00 00 00 00
218020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
21c000 83 6c 47 94 00 00 00 6d 00 00 00 6c 00 00 00 6e
21c010 00 00 00 00 05 9e e2 9d 45 bf 00 00 00 00 00 00
21c020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
224000 0e 82 e8 6e 00 00 00 c4 00 00 00 c3 00 00 00 c5
224010 00 00 00 00 05 a0 f3 16 45 bf 00 00 00 00 00 00
224020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
228000 9b a8 ab d8 00 00 00 6e 00 00 00 6d 00 00 00 6f
228010 00 00 00 00 05 9f 8a 48 45 bf 00 00 00 00 00 00
228020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
22c000 d1 c7 74 02 00 00 00 6f 00 00 00 6e 00 00 00 70
22c010 00 00 00 00 05 a0 31 45 45 bf 00 00 00 00 00 00
22c020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
234000 dd 74 c0 2a 00 00 00 c5 00 00 00 c4 00 00 00 c6
234010 00 00 00 00 05 a2 5f 4c 45 bf 00 00 00 00 00 00
234020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
238000 40 79 e6 8d 00 00 00 70 00 00 00 6f 00 00 00 71
238010 00 00 00 00 05 a0 d7 f3 45 bf 00 00 00 00 00 00
238020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
240000 d6 5e 80 cb 00 00 00 71 00 00 00 70 00 00 00 72
240010 00 00 00 00 05 a1 7f 97 45 bf 00 00 00 00 00 00
240020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
244000 44 6d 95 85 00 00 00 72 00 00 00 71 00 00 00 73
244010 00 00 00 00 05 a2 26 a4 45 bf 00 00 00 00 00 00
244020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
248000 af d8 c9 08 00 00 00 c6 00 00 00 c5 00 00 00 c7
248010 00 00 00 00 05 a3 cb 20 45 bf 00 00 00 00 00 00
248020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
250000 8c 67 c7 07 00 00 00 73 00 00 00 72 00 00 00 74
250010 00 00 00 00 05 a2 cd e9 45 bf 00 00 00 00 00 00
250020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
258000 b2 1e c2 e0 00 00 00 74 00 00 00 73 00 00 00 75
258010 00 00 00 00 05 a3 74 f6 45 bf 00 00 00 00 00 00
258020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
25c000 9a f5 a7 2d 00 00 00 c7 00 00 00 c6 00 00 00 c8
25c010 00 00 00 00 05 a5 36 f4 45 bf 00 00 00 00 00 00
25c020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
260000 7b 09 85 2c 00 00 00 75 00 00 00 74 00 00 00 76
260010 00 00 00 00 05 a4 1c 3f 45 bf 00 00 00 00 00 00
260020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
268000 79 9b ce 15 00 00 00 76 00 00 00 75 00 00 00 77
268010 00 00 00 00 05 a4 c3 48 45 bf 00 00 00 00 00 00
268020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
26c000 21 1a e5 5e 00 00 00 c8 00 00 00 c7 00 00 00 c9
26c010 00 00 00 00 05 a6 a3 2a 45 bf 00 00 00 00 00 00
26c020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
270000 40 03 52 a2 00 00 00 77 00 00 00 76 00 00 00 78
270010 00 00 00 00 05 a5 6a f3 45 bf 00 00 00 00 00 00
270020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
278000 ae 50 ee ea 00 00 00 78 00 00 00 77 00 00 00 79
278010 00 00 00 00 05 a6 11 8e 45 bf 00 00 00 00 00 00
278020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
27c000 57 d9 cd 5c 00 00 00 c9 00 00 00 c8 00 00 00 ca
27c010 00 00 00 00 05 a8 0f 68 45 bf 00 00 00 00 00 00
27c020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
284000 71 96 f8 aa 00 00 00 79 00 00 00 78 00 00 00 7a
284010 00 00 00 00 05 a6 b9 45 45 bf 00 00 00 00 00 00
284020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
288000 eb 99 ec f6 00 00 00 7a 00 00 00 79 00 00 00 7b
288010 00 00 00 00 05 a7 60 52 45 bf 00 00 00 00 00 00
288020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
290000 2a f9 2c e5 00 00 00 ca 00 00 00 c9 00 00 00 cb
290010 00 00 00 00 05 a9 7c 29 45 bf 00 00 00 00 00 00
290020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
294000 cb 30 78 3e 00 00 00 7b 00 00 00 7a 00 00 00 7c
294010 00 00 00 00 05 a8 07 02 45 bf 00 00 00 00 00 00
294020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
29c000 e4 71 3f 08 00 00 00 7c 00 00 00 7b 00 00 00 7d
29c010 00 00 00 00 05 a8 ae a4 45 bf 00 00 00 00 00 00
29c020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2a0000 96 c5 60 ef 00 00 00 7d 00 00 00 7c 00 00 00 7e
2a0010 00 00 00 00 05 a9 55 c1 45 bf 00 00 00 00 00 00
2a0020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2a4000 e8 e3 cc 67 00 00 00 cb 00 00 00 ca 00 00 00 cc
2a4010 00 00 00 00 05 aa ec 7e 45 bf 00 00 00 00 00 00
2a4020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
2ac000 f7 70 59 32 00 00 00 7e 00 00 00 7d 00 00 00 7f
2ac010 00 00 00 00 05 a9 fe 74 45 bf 00 00 00 00 00 00
2ac020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2b0000 22 08 75 ce 00 00 00 7f 00 00 00 7e 00 00 01 00
2b0010 00 00 00 00 05 aa a7 f3 45 bf 00 00 00 00 00 00
2b0020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2b8000 df a2 40 d9 00 00 00 cc 00 00 00 cb 00 00 00 cd
2b8010 00 00 00 00 05 ac 5d 98 45 bf 00 00 00 00 00 00
2b8020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
2bc000 91 8f 0a 77 00 00 01 00 00 00 00 7f 00 00 01 01
2bc010 00 00 00 00 05 ab 51 aa 45 bf 00 00 00 00 00 00
2bc020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2c4000 b6 52 02 bb 00 00 01 01 00 00 01 00 00 00 01 02
2c4010 00 00 00 00 05 ab fb 25 45 bf 00 00 00 00 00 00
2c4020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2c8000 3c df 71 03 00 00 00 cd 00 00 00 cc 00 00 00 ce
2c8010 00 00 00 00 05 ad cf 24 45 bf 00 00 00 00 00 00
2c8020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
2cc000 e3 c7 10 3d 00 00 01 02 00 00 01 01 00 00 01 03
2cc010 00 00 00 00 05 ac a5 4a 45 bf 00 00 00 00 00 00
2cc020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2d4000 39 dd 55 ea 00 00 01 03 00 00 01 02 00 00 01 04
2d4010 00 00 00 00 05 ad 4e 63 45 bf 00 00 00 00 00 00
2d4020 00 00 00 00 00 b0 00 96 3a c5 82 57 00 00 00 00
--
2d8000 e9 29 66 62 00 00 00 ce 00 00 00 cd 00 00 00 cf
2d8010 00 00 00 00 05 af 40 4e 45 bf 00 00 00 00 00 00
2d8020 00 00 00 00 00 b0 01 46 3d 68 85 16 00 00 00 00
--
2e0000 e9 ac 0d 0e 00 00 00 07 ff ff ff ff ff ff ff ff
2e0010 00 00 00 00 05 4c d8 c5 45 bf 00 00 00 00 00 00
2e0020 00 00 00 00 00 a2 00 02 00 ab 80 06 00 00 00 00
--
2e4000 c1 0e 67 a6 00 00 00 04 ff ff ff ff ff ff ff ff
2e4010 00 00 00 00 05 4c b7 98 45 bf 00 00 00 00 00 00
2e4020 00 00 00 00 00 a2 00 02 00 97 80 05 00 00 00 00
--
2e8000 12 66 dd 54 00 00 00 11 ff ff ff ff ff ff ff ff
2e8010 00 00 00 00 05 4b 9c 63 45 bf 00 00 00 00 00 00
2e8020 00 00 00 00 00 9e 00 02 00 f3 80 03 00 00 00 00
--
2ec000 1d 3e e7 19 00 00 00 0a ff ff ff ff ff ff ff ff
2ec010 00 00 00 00 05 4b 9c 63 45 bf 00 00 00 00 00 00
2ec020 00 00 00 00 00 9e 00 02 00 e9 80 03 00 00 00 00
--
2f0000 3c fd 30 24 00 00 00 0b ff ff ff ff ff ff ff ff
2f0010 00 00 00 00 05 4b 9c 63 45 bf 00 00 00 00 00 00
2f0020 00 00 00 00 00 9e 00 02 00 e9 80 03 00 00 00 00

There are some entries referring to tablespace 0xb2 (t2.ibd) and many to some earlier tablespaces (such as 0x9e, 0xa2, 0xb0) which were probably created and dropped by earlier tests.
This leads me to believe that in the unexpectedly-not-refused startup attempt "Fault 2", the doublewrite buffer was not emptied, and we indeed did not have doublewrite entries for t3.ibd before the kill. So, the doublewrite buffer bug should affect MariaDB 10.2 as well.

Comment by Jan Lindström (Inactive) [ 2018-01-15 ]

Test report from 10.1 and Windows 32-bit: The difference between successful test run and failed one is that in innodb_plugin when page 1 from tablespace 0 is dirtied it uses buffered doublewrite write for that dirtied page. When test fails that buffered write does not happen i.e. server is killed before the buffered doublewrite page is written.

Comment by Marko Mäkelä [ 2018-02-15 ]

MDEV-15325 shows how to repeat this deterministically on GNU/Linux.

Comment by Marko Mäkelä [ 2021-04-27 ]

I wonder if we still encounter this. With an rr replay trace of the killed server and the failed recovery this should be trivial to analyze.

Starting with 10.5 the code is very different, mostly due to MDEV-23855, which streamlined the page flushing and made the doublewrite buffer use asynchronous writes.

In 10.1 (which finally reached its end of life in 2020), the test innodb.doublewrite would also fail due to other reasons (memory corruption after InnoDB failed to start up). The memory leaks and corruption on failed InnoDB startup were only fixed in the 10.2 series.

Comment by Marko Mäkelä [ 2021-04-27 ]

The last occurrences of innodb.doublewrite test failures that I observed for other than 10.1 branches were:

branch revision platform timestamp
10.2 aed2050e40cb332d54e8d40eb7242309 win32-debug 2018-01-01 15:27:00
10.3 956b296248acbe35aa87f056ccf99dbb kvm-fulltest2 2018-06-19 12:01:31

All 10.4 failures (there were very few of them in total) that I checked were actually due to MDEV-20159. Also the most recent failures for 10.2 and 10.3 appear to be for something else.

It seems that MDEV-15325 must have fixed this in March 2018. Also MDEV-12699 and related improvements reduced the need for the doublewrite buffer, but that was fixed in April 2019, much later.

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