[#MDEV-20481] innodb.blob-crash crashes during recovery

Comment by Marko Mäkelä [ 2019-09-03 ]

I think that this report basically duplicates ~~MDEV-13830~~.

Comment by Elena Stepanova [ 2019-11-03 ]

Another variation of 10.3 (also upon recovery, so I assume it's related):
http://buildbot.askmonty.org/buildbot/builders/kvm-asan/builds/2156

10.3 5b2fa078e8aee75a180461963bd54ce8
nnodb.blob-crash '16k,debug,innodb' w3 [ fail ]
Test ended at 2019-10-02 13:19:36

CURRENT_TEST: innodb.blob-crash


Server [mysqld.1 - pid: 27427, winpid: 27427, exit: 256] failed during test run
Server log from this test:
...
2019-10-02 13:19:35 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
mysqld: /home/buildbot/buildbot/build/mariadb-10.3.19/storage/innobase/fil/fil0fil.cc:4653: static ulint Check::validate(const fil_space_t*): Assertion `space->id != 0xFFFFFFFEU \|\| space == fil_system.temp_space' failed.
191002 13:19:35 [ERROR] mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.

To report this bug, see https://mariadb.com/kb/en/reporting-bugs

We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.

Server version: 10.3.19-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=153
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63283 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...
stack_bottom = 0x0 thread_stack 0x5fc00
/usr/lib/x86_64-linux-gnu/libasan.so.2(+0x4a077)[0x7f8bb9c3b077]
/home/buildbot/buildbot/build/mariadb-10.3.19/sql/mysqld(my_print_stacktrace+0xce)[0x21bdfd4]
/home/buildbot/buildbot/build/mariadb-10.3.19/sql/mysqld(handle_fatal_signal+0x8ae)[0x100960c]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f8bb84b5390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f8bb786f428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f8bb787102a]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dbd7)[0x7f8bb7867bd7]
/lib/x86_64-linux-gnu/libc.so.6(+0x2dc82)[0x7f8bb7867c82]
/home/buildbot/buildbot/build/mariadb-10.3.19/sql/mysqld[0x1e6d7c5]
include/mem0mem.ic:457(mem_heap_get_size(mem_block_info_t*))[0x1e6876f]
row/row0import.cc:1868(PageConverter::update_index_page(buf_block_t*))[0x1e4cb55]
include/ut0lst.h:202(void ut_list_append<ut_list_base<row_fts_token_t, ut_list_node<row_fts_token_t> row_fts_token_t::>, GenericGetNode<row_fts_token_t> >(ut_list_base<row_fts_token_t, ut_list_node<row_fts_token_t> row_fts_token_t::>&, ut_list_base<row_fts_token_t, ut_list_node<row_fts_token_t> row_fts_token_t::>::elem_type, GenericGetNode<row_fts_token_t>))[0x1e6722b]
row/row0import.cc:1612(PageConverter::adjust_cluster_index_blob_columns(unsigned char, unsigned long const))[0x1d95cd3]
mtr/mtr0mtr.cc:577(mtr_t::commit_checkpoint(unsigned long, bool))[0x1d9710d]
mtr/mtr0mtr.cc:695(mtr_t::x_lock_space(unsigned long, char const*, unsigned int))[0x1d3d060]
lock/lock0lock.cc:6731(DeadlockChecker::search())[0x1ce4df7]
include/sync0rw.ic:425(rw_lock_x_unlock_func(unsigned long, rw_lock_t*))[0x1ce58dd]
include/sync0rw.ic:685(pfs_rw_lock_sx_lock_func(rw_lock_t, unsigned long, char const, unsigned int))[0x1cd6ce5]
handler/i_s.cc:6683(innodb_sys_indexes_init(void*))[0x1f695aa]
include/mach0data.ic:312(mach_read_next_compressed(unsigned char const**))[0x1f6aa26]
include/data0data.ic:335(dtuple_create_from_mem(void*, unsigned long, unsigned long, unsigned long))[0x1f706b0]
include/mach0data.ic:132(mach_write_to_3(unsigned char*, unsigned long))[0x1b6f18d]
maria/ma_check.c:6707(_ma_safe_scan_block_record)[0x1b6f625]
maria/ma_check.c:6765(_ma_safe_scan_block_record)[0x1a17a2d]
maria/ma_loghandler.c:7262(translog_read_record_header_scan)[0x1a17eb8]
maria/ma_loghandler.c:7302(translog_read_next_record_header)[0x1a1826f]
maria/ma_loghandler.c:7327(translog_read_next_record_header)[0x1c2b788]
handler/ha_innodb.cc:17978(innodb_buffer_pool_evict_uncompressed())[0x1c2ca40]
handler/ha_innodb.cc:18399(buffer_pool_dump_now(THD, st_mysql_sys_var, void, void const))[0x1c2d172]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f8bb84ab6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f8bb794082d]
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...
Working directory at /dev/shm/var/3/mysqld.1/data
Resource Limits:
Limit Soft Limit Hard Limit Units
Max cpu time unlimited unlimited seconds
Max file size unlimited unlimited bytes
Max data size unlimited unlimited bytes
Max stack size 8388608 unlimited bytes
Max core file size 0 0 bytes
Max resident set unlimited unlimited bytes
Max processes 23715 23715 processes
Max open files 1024 1024 files
Max locked memory 65536 65536 bytes
Max address space unlimited unlimited bytes
Max file locks unlimited unlimited locks
Max pending signals 23715 23715 signals
Max msgqueue size 819200 819200 bytes
Max nice priority 0 0
Max realtime priority 0 0
Max realtime timeout unlimited unlimited us
Core pattern: \|/usr/share/apport/apport %p %s %c %P

----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
INSERT INTO t1 (a, b) VALUES (1, repeat('^', 40000));
INSERT INTO t1 (a, b) VALUES (2, '2');
INSERT INTO t1 (a, b) VALUES (3, '3');
INSERT INTO t1 (a, b) VALUES (4, '4');
INSERT INTO t1 (a, b) VALUES (5, '5');
begin;
INSERT INTO t1 (a, b) VALUES (6, REPEAT('a', 410241024));
SELECT a, right(b, 50) FROM t1;
a right(b, 50)
1 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
2 2
3 3
4 4
5 5
#
# Uncompressed Table - UPDATE Operation - Crash Test
# Update of non-blob column so that blob is needed.
#
begin;
UPDATE t1 set b = REPEAT('a', 410241024) where a = 5 ;

Comment by Elena Stepanova [ 2019-12-04 ]

And another one, now on 10.2. Please feel free to split it into a separate bug report if it's unrelated

http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/16684

bb-10.2-release f7d35ffc
innodb.blob-crash '16k,debug,innodb' w2 [ fail ]
Test ended at 2019-12-03 20:36:55

CURRENT_TEST: innodb.blob-crash


Server [mysqld.1 - pid: 1192, winpid: 1192, exit: 768] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2019-12-03 20:36:48 8700 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.2.30-MariaDB-debug-log) starting as process 1236 ...
2019-12-03 20:36:48 8700 [Note] Plugin 'partition' is disabled.
2019-12-03 20:36:48 8700 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2019-12-03 20:36:48 8700 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2019-12-03 20:36:48 8700 [Note] InnoDB: Uses event mutexes
2019-12-03 20:36:48 8700 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-12-03 20:36:48 8700 [Note] InnoDB: Number of pools: 1
2019-12-03 20:36:48 8700 [Note] InnoDB: Using SSE2 crc32 instructions
2019-12-03 20:36:48 8700 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2019-12-03 20:36:48 8700 [Note] InnoDB: Completed initialization of buffer pool
2019-12-03 20:36:48 8700 [Note] InnoDB: Highest supported file format is Barracuda.
2019-12-03 20:36:48 8700 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-12-03 20:36:48 8700 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-12-03 20:36:48 8700 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-12-03 20:36:48 8700 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2019-12-03 20:36:48 8700 [Note] InnoDB: Waiting for purge to start
2019-12-03 20:36:48 8700 [Note] InnoDB: 5.7.28 started; log sequence number 1628870
2019-12-03 20:36:48 8460 [Note] InnoDB: Loading buffer pool(s) from D:\winx64-debug\build\mysql-test\var\2\mysqld.1\data\ib_buffer_pool
2019-12-03 20:36:48 8460 [Note] InnoDB: Buffer pool(s) load completed at 191203 20:36:48
2019-12-03 20:36:48 8700 [Note] Plugin 'SEQUENCE' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_CMP' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'FEEDBACK' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'user_variables' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2019-12-03 20:36:48 8700 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2019-12-03 20:36:48 8700 [Warning] D:/winx64-debug/build/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
2019-12-03 20:36:48 8700 [Note] Server socket created on IP: '::'.
2019-12-03 20:36:49 8700 [Note] Reading of all Master_info entries succeeded
2019-12-03 20:36:49 8700 [Note] Added new Master_info '' to hash table
2019-12-03 20:36:49 8700 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe: ready for connections.
Version: '10.2.30-MariaDB-debug-log' socket: '' port: 16020 Source distribution
2019-12-03 20:36:50 7108 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.2.30-MariaDB-debug-log) starting as process 2748 ...
2019-12-03 20:36:50 7108 [Note] Plugin 'partition' is disabled.
2019-12-03 20:36:50 7108 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2019-12-03 20:36:50 7108 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2019-12-03 20:36:50 7108 [Note] InnoDB: Uses event mutexes
2019-12-03 20:36:50 7108 [Note] InnoDB: Compressed tables use zlib 1.2.11
2019-12-03 20:36:50 7108 [Note] InnoDB: Number of pools: 1
2019-12-03 20:36:50 7108 [Note] InnoDB: Using SSE2 crc32 instructions
2019-12-03 20:36:50 7108 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2019-12-03 20:36:50 7108 [Note] InnoDB: Completed initialization of buffer pool
2019-12-03 20:36:50 7108 [Note] InnoDB: Highest supported file format is Barracuda.
2019-12-03 20:36:50 7108 [Note] InnoDB: Starting crash recovery from checkpoint LSN=1628870
2019-12-03 20:36:50 7108 [Note] InnoDB: Starting a batch to recover 151 pages from redo log.
2019-12-03 20:36:50 7108 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
2019-12-03 20:36:50 7108 [Note] InnoDB: Trx id counter is 1792
2019-12-03 20:36:50 7108 [Note] InnoDB: Starting final batch to recover 129 pages from redo log.
2019-12-03 20:36:51 7108 [Note] InnoDB: 128 out of 128 rollback segments are active.
2019-12-03 20:36:51 6444 [Note] InnoDB: Starting in background the rollback of recovered transactions
2019-12-03 20:36:51 7108 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2019-12-03 20:36:51 7108 [Note] InnoDB: Creating shared tablespace for temporary tables
2019-12-03 20:36:51 7108 [Note] InnoDB: Setting file '.\ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2019-12-03 20:36:51 7108 [Note] InnoDB: File '.\ibtmp1' size is now 12 MB.
2019-12-03 20:36:51 7108 [Note] InnoDB: Waiting for purge to start
2019-12-03 20:36:51 7108 [Note] InnoDB: 5.7.28 started; log sequence number 5941314
2019-12-03 20:36:51 7340 [Note] InnoDB: Loading buffer pool(s) from D:\winx64-debug\build\mysql-test\var\2\mysqld.1\data\ib_buffer_pool
2019-12-03 20:36:51 7108 [Note] Plugin 'SEQUENCE' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_CMP' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'FEEDBACK' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'user_variables' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2019-12-03 20:36:51 6444 [Note] InnoDB: Rolled back recovered transaction 1294
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2019-12-03 20:36:51 6444 [Note] InnoDB: Rollback of non-prepared transactions completed
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2019-12-03 20:36:51 7108 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2019-12-03 20:36:51 7108 [Warning] D:/winx64-debug/build/sql//Debug/mysqld.exe: unknown option '--loose-pam-debug'
2019-12-03 20:36:51 7108 [Note] Server socket created on IP: '::'.
2019-12-03 20:36:51 7108 [Note] Reading of all Master_info entries succeeded
2019-12-03 20:36:51 7108 [Note] Added new Master_info '' to hash table

2019-12-03 20:36:51 7108 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe: ready for connections.

Version: '10.2.30-MariaDB-debug-log'  socket: ''  port: 16020  Source distribution

2019-12-03 20:36:51 7340 [Note] InnoDB: Buffer pool(s) load completed at 191203 20:36:51

2019-12-03 20:36:52 4224 [Note] D:/winx64-debug/build/sql//Debug/mysqld.exe (mysqld 10.2.30-MariaDB-debug-log) starting as process 1124 ...

2019-12-03 20:36:52 4224 [Note] Plugin 'partition' is disabled.

2019-12-03 20:36:52 4224 [Note] InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!

2019-12-03 20:36:52 4224 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions

2019-12-03 20:36:52 4224 [Note] InnoDB: Uses event mutexes

2019-12-03 20:36:52 4224 [Note] InnoDB: Compressed tables use zlib 1.2.11

2019-12-03 20:36:52 4224 [Note] InnoDB: Number of pools: 1

2019-12-03 20:36:52 4224 [Note] InnoDB: Using SSE2 crc32 instructions

2019-12-03 20:36:52 4224 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M

2019-12-03 20:36:52 4224 [Note] InnoDB: Completed initialization of buffer pool

2019-12-03 20:36:52 4224 [Note] InnoDB: Highest supported file format is Barracuda.

2019-12-03 20:36:52 4224 [Note] InnoDB: Starting crash recovery from checkpoint LSN=9200874

2019-12-03 20:36:52 4224 [Note] InnoDB: Starting a batch to recover 137 pages from redo log.

2019-12-03 20:36:53 4224 [Note] InnoDB: Starting a batch to recover 135 pages from redo log.

2019-12-03 20:36:53 4224 [ERROR] [FATAL] InnoDB: Page [page id: space=4, page number=3] still fixed or dirty

191203 20:36:53 [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.2.30-MariaDB-debug-log

key_buffer_size=1048576

read_buffer_size=131072

max_used_connections=0

max_threads=65537

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4233 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...

mysqld.exe!my_sigabrt_handler()[my_thr_init.c:487]

mysqld.exe!raise()[signal.cpp:547]

mysqld.exe!abort()[abort.cpp:71]

mysqld.exe!ib::fatal::~fatal()[ut0ut.cc:645]

mysqld.exe!buf_all_freed_instance()[buf0buf.cc:6256]

mysqld.exe!buf_pool_invalidate_instance()[buf0buf.cc:6310]

mysqld.exe!buf_pool_invalidate()[buf0buf.cc:6342]

mysqld.exe!recv_apply_hashed_log_recs()[log0recv.cc:2536]

mysqld.exe!recv_group_scan_log_recs()[log0recv.cc:3442]

mysqld.exe!recv_recovery_from_checkpoint_start()[log0recv.cc:3886]

mysqld.exe!innobase_start_or_create_for_mysql()[srv0start.cc:2210]

mysqld.exe!innobase_init()[ha_innodb.cc:4370]

mysqld.exe!ha_initialize_handlerton()[handler.cc:555]

mysqld.exe!plugin_initialize()[sql_plugin.cc:1417]

mysqld.exe!plugin_init()[sql_plugin.cc:1698]

mysqld.exe!init_server_components()[mysqld.cc:5333]

mysqld.exe!win_main()[mysqld.cc:5929]

mysqld.exe!mysql_service()[mysqld.cc:6189]

mysqld.exe!mysqld_main()[mysqld.cc:6382]

mysqld.exe!main()[main.cc:26]

mysqld.exe!__scrt_common_main_seh()[exe_common.inl:288]

KERNEL32.DLL!BaseThreadInitThunk()

ntdll.dll!RtlUserThreadStart()

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 at D:\winx64-debug\build\mysql-test\var\2\mysqld.1\data\

----------SERVER LOG END-------------

mysqltest failed but provided no output

The result from queries just before the failure was:

< snip >

INSERT INTO t1 (a, b) VALUES (1, repeat('^', 40000));

INSERT INTO t1 (a, b) VALUES (2, '2');

INSERT INTO t1 (a, b) VALUES (3, '3');

INSERT INTO t1 (a, b) VALUES (4, '4');

INSERT INTO t1 (a, b) VALUES (5, '5');

begin;

INSERT INTO t1 (a, b) VALUES (6, REPEAT('a', 4*1024*1024));

SELECT a, right(b, 50) FROM t1;

a	right(b, 50)

1	^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

2	2

3	3

4	4

5	5

# Uncompressed Table - UPDATE Operation - Crash Test

# Update of non-blob column so that blob is needed.

begin;

UPDATE t1 set b = REPEAT('a', 4*1024*1024) where a = 5 ;

Comment by Aleksey Midenkov [ 2020-05-29 ]

http://buildbot.askmonty.org/buildbot/builders/win32-debug/builds/17180/steps/test/logs/stdio

Comment by Daniel Black [ 2020-07-31 ]

http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/20272/steps/test/logs/stdio
(has 1 non-innodb related commit on top of f99de8915e8f9109384d1f197ca69c747487cb48)

10.5-f99de8915e8f9109384d1f197ca69c747487cb48
innodb.blob-crash '8k,debug,innodb' w1 [ fail ]
Test ended at 2020-07-31 01:15:24

CURRENT_TEST: innodb.blob-crash

2020-07-31 1:15:22 0 [Note] InnoDB: Starting a batch to recover 169 pages from redo log.
2020-07-31 1:15:23 0 [Note] InnoDB: Starting a batch to recover 167 pages from redo log.
2020-07-31 1:15:23 0 [ERROR] [FATAL] InnoDB: Page [page id: space=5, page number=3] still fixed or dirty
200731 1:15:23 [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.5.5-MariaDB-debug-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=0
max_threads=65537
thread_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4577 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...
server.dll!my_sigabrt_handler()[my_thr_init.c:465]
ucrtbase.dll!raise()
ucrtbase.dll!abort()
server.dll!ib::fatal::~fatal()[ut0ut.cc:580]
server.dll!buf_pool_t::assert_all_freed()[buf0buf.cc:4362]
server.dll!buf_pool_invalidate()[buf0buf.cc:4402]
server.dll!recv_sys_t::apply()[log0recv.cc:2758]
server.dll!recv_group_scan_log_recs()[log0recv.cc:3116]
server.dll!recv_recovery_from_checkpoint_start()[log0recv.cc:3564]
server.dll!srv_start()[srv0start.cc:1530]
server.dll!innodb_init()[ha_innodb.cc:3999]
server.dll!ha_initialize_handlerton()[handler.cc:645]
server.dll!plugin_initialize()[sql_plugin.cc:1459]
server.dll!plugin_init()[sql_plugin.cc:1751]
server.dll!init_server_components()[mysqld.cc:4911]
server.dll!win_main()[mysqld.cc:5494]
server.dll!mysql_service()[mysqld.cc:5742]
server.dll!mysqld_main()[mysqld.cc:5960]
mariadbd.exe!main()[main.cc:26]
mariadbd.exe!__scrt_common_main_seh()[exe_common.inl:288]
KERNEL32.DLL!BaseThreadInitThunk()
ntdll.dll!RtlUserThreadStart()

Comment by Marko Mäkelä [ 2020-07-31 ]

This report seems to bundle together many separate issues around InnoDB crash recovery.

~~MDEV-13830~~ was about a bogus debug assertion recv_sys->mlog_checkpoint_lsn <= recv_sys->recovered_lsn. It has been fixed in 10.2, but the fix has not been merged even to 10.3 yet.
~~MDEV-19298~~ Assertion space->id != 0xFFFFFFFEU || space == fil_system.temp_space failed and its sibling ~~MDEV-20159~~ have been fixed in 10.3,10.4,10.5.
We seem to have an open bug [FATAL] InnoDB: Page … still fixed or dirty affecting at least 10.5. There are some 10.5-only changes such as ~~MDEV-15528~~ which might make this more probable on 10.5. ~~MDEV-21843~~ has been filed for something similar.

Comment by Marko Mäkelä [ 2020-07-31 ]

Reopening because of the "still fixed or dirty" issue, which is similar to ~~MDEV-21843~~.

Comment by Alice Sherepa [ 2020-10-14 ]

http://buildbot.askmonty.org/buildbot/builders/winx64-debug/builds/21312/steps/test/logs/stdio

innodb.blob-crash '4k,debug,innodb'      w3 [ fail ]

        Test ended at 2020-10-09 10:15:45

201009 10:15:43 [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.5.7-MariaDB-debug-log

key_buffer_size=1048576

read_buffer_size=131072

max_used_connections=0

max_threads=65537

thread_count=0

It is possible that mysqld could use up to

key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4635 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...

server.dll!my_sigabrt_handler()[my_thr_init.c:465]

ucrtbase.dll!raise()

ucrtbase.dll!abort()

server.dll!ib::fatal::~fatal()[ut0ut.cc:580]

server.dll!buf_pool_t::assert_all_freed()[buf0buf.cc:4398]

server.dll!buf_pool_invalidate()[buf0buf.cc:4438]

server.dll!recv_sys_t::apply()[log0recv.cc:2782]

server.dll!recv_group_scan_log_recs()[log0recv.cc:3140]

server.dll!recv_recovery_from_checkpoint_start()[log0recv.cc:3590]

server.dll!srv_start()[srv0start.cc:1531]

server.dll!innodb_init()[ha_innodb.cc:3899]

server.dll!ha_initialize_handlerton()[handler.cc:645]

server.dll!plugin_initialize()[sql_plugin.cc:1459]

server.dll!plugin_init()[sql_plugin.cc:1751]

server.dll!init_server_components()[mysqld.cc:4913]

server.dll!win_main()[mysqld.cc:5496]

server.dll!mysql_service()[mysqld.cc:5744]

server.dll!mysqld_main()[mysqld.cc:5962]

mariadbd.exe!main()[main.cc:26]

mariadbd.exe!__scrt_common_main_seh()[exe_common.inl:288]

KERNEL32.DLL!BaseThreadInitThunk()

ntdll.dll!RtlUserThreadStart()

The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mysqld/ contains

information that should help you find out what is causing the crash.

Writing a core file at D:\winx64-debug\build\mysql-test\var\3\mysqld.1\data\

Comment by Marko Mäkelä [ 2023-01-17 ]

The last failure of innodb.blob-crash for 10.5 with "still fixed or dirty" occured in 2020. That seems to be exactly the failure that alice posted above:

10.5 a891fe6aa5ede1bf1f4551cfa75cf856
innodb.blob-crash '4k,debug,innodb' w3 [ fail ]
…
2020-10-09 10:15:42 0 [Note] InnoDB: Starting a batch to recover 338 pages from redo log.
2020-10-09 10:15:42 0 [Note] InnoDB: Starting a batch to recover 317 pages from redo log.
2020-10-09 10:15:43 0 [Note] InnoDB: Starting a batch to recover 317 pages from redo log.
2020-10-09 10:15:43 0 [ERROR] [FATAL] InnoDB: Page [page id: space=5, page number=2] still fixed or dirty

~~MDEV-23399~~ and ~~MDEV-23855~~ were pushed to the 10.5 branch soon after this. They could have fixed this trouble for this particular test.

I remember seeing some possibly related failure in 10.5, even recently. I think it was this one:

void

rw_lock_free_func(

/*==============*/

	rw_lock_t*	lock)	/*!< in/out: rw-lock */

	ut_ad(rw_lock_validate(lock));

	ut_a(lock->lock_word == X_LOCK_DECR);

In ~~MDEV-24142~~ (10.6), that code was replaced with debug assertions in srw_lock::destroy() and sux_lock::free(), but I do not remember seeing those assertions failing.

Comment by Marko Mäkelä [ 2023-01-17 ]

The related failure that I am referring to is MDEV-26733, seemingly specific to 10.5 and the test innodb.undo_truncate.

Comment by Marko Mäkelä [ 2023-01-17 ]

Because I had some trouble with the Buildbot cross-reference, elenst provided to me a list of some failures for the failing still fixed or dirty check on shutdown. I accidentally asked her to search anything after 2019-10-09, instead of 2020-10-09, which was the last failure returned also by her search.

Failures are rather rare: none in 2020-01, 2020-02, 2020-11, 2020-12, and otherwise it was failing about once per month in some main branch. Here are some of other latest failures:

10.3 fbef428645e01113521824c2eb0a42fe
CURRENT_TEST: innodb_gis.types
…
2020-04-03 8:18:10 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=31648455
2020-04-03 8:18:11 0 [Note] InnoDB: Starting a batch to recover 307 pages from redo log.
2020-04-03 8:18:11 0 [Note] InnoDB: Starting a batch to recover 293 pages from redo log.
2020-04-03 8:18:11 0 [ERROR] [FATAL] InnoDB: Page [page id: space=0, page number=511] still fixed or dirty

10.5 9ae015878f11be3e3033fd1b35357ea5
CURRENT_TEST: innodb.blob-crash
…
2020-03-10 15:37:09 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=47877
2020-03-10 15:37:09 0 [Note] InnoDB: Starting a batch to recover 110 pages from redo log.
2020-03-10 15:37:09 0 [Note] InnoDB: Starting a batch to recover 89 pages from redo log.
2020-03-10 15:37:09 0 [ERROR] [FATAL] InnoDB: Page [page id: space=5, page number=2] still fixed or dirty

10.5 90b7ac28a917fde7bceed573956aa4c6
CURRENT_TEST: innodb.blob-crash
…
2020-03-17 16:43:28 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=7956119
2020-03-17 16:43:28 0 [Note] InnoDB: Starting a batch to recover 168 pages from redo log.
2020-03-17 16:43:28 0 [Note] InnoDB: Starting a batch to recover 170 pages from redo log.
2020-03-17 16:43:28 0 [Note] InnoDB: Starting a batch to recover 170 pages from redo log.
2020-03-17 16:43:29 0 [ERROR] [FATAL] InnoDB: Page [page id: space=5, page number=0] still fixed or dirty

~~MDEV-24449~~ was fixed in 10.2 on December 28, and in 10.5 on December 21. The test innodb.blob-crash does define a secondary index on the table (t3), so the change buffer might be used for it. Likewise, the test innodb_gis.types, which often runs out of memory on recovery (~~MDEV-22512~~), defines a secondary index on the table t_wl6455. I think that it is plausible that this bug was fixed by ~~MDEV-24449~~.

Comment by Marko Mäkelä [ 2023-01-17 ]

I believe that this was fixed by ~~MDEV-24449~~ for 10.3 and 10.4, and by ~~MDEV-24448~~ for 10.5 and 10.6.

[MDEV-20481] innodb.blob-crash crashes during recovery Created: 2019-09-03 Updated: 2023-01-17 Resolved: 2023-01-17
Status:	Closed
Project:	MariaDB Server
Component/s:	Storage Engine - InnoDB, Tests
Affects Version/s:	10.2, 10.3, 10.4, 10.5
Fix Version/s:	10.3.28, 10.4.18, 10.5.9, 10.6.0

[MDEV-20481] innodb.blob-crash crashes during recovery Created: 2019-09-03 Updated: 2023-01-17 Resolved: 2023-01-17