[MDEV-15608] Crash during transaction rollback when using optimistic parallel replication, few threads, non-durable configuration. Created: 2018-03-20  Updated: 2023-03-20  Resolved: 2021-04-13

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.12
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Juan Assignee: Marko Mäkelä
Resolution: Cannot Reproduce Votes: 3
Labels: assertion, innodb, optimistic, parallelreplication
Environment:

CentOS 7.4.1708

Issue Links:
Relates
relates to MDEV-14711 Assertion `mode == 16 || mode == 12 |... Closed
relates to MDEV-22388 Corrupted undo log record leads to se... Closed
relates to MDEV-24449 Corruption of system tablespace or la... Closed
relates to MDEV-30671 innodb_undo_log_truncate=ON fails to ... Closed

 Description   

A user is seeing this crash frequently when testing Optimistic parallel replication. Note that the crash happens reliably, possibly on rollback, with fewer replication threads (4) and a non-durable configuration (sync_binlog = 0 and trx_commit = 2) w binlog & slave-updates enabled.

Could be a duplicate of MDEV-13800 ?

		...after a LOT of 2018-02-06  6:54:56 140100964673280 [ERROR] mysqld: Can't find record in 'db_waypoint'
 
		2018-02-06 06:54:58 0x7f6bc4436700  InnoDB: Assertion failure in file /home/buildbot/buildbot/padding_for_CPACK_RPM_BUILD_SOURCE_DIRS_PREFIX/mariadb-10.2.12/storage/innobase/row/row0umod.cc line 145
 
		InnoDB: Failing assertion: !dummy_big_rec
 
		InnoDB: We intentionally generate a memory trap.
 
		InnoDB: Submit a detailed bug report to https://jira.mariadb.org/
 
		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.
 
		180206  6:54:58 [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.2.12-MariaDB-log
 
		key_buffer_size=805306368
 
		read_buffer_size=131072
 
		max_used_connections=8
 
		max_threads=3002
 
		thread_count=48
 
		It is possible that mysqld could use up to
 
		key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4308788 K  bytes of memory
 
		Hope that's ok; if not, decrease some variables in the equation.
 
 
 
		Thread pointer: 0x7f6a2c0009a8
 
		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 = 0x7f6bc4435cf0 thread_stack 0x49000
 
		(my_addr_resolve failure: fork)
 
		/usr/sbin/mysqld(my_print_stacktrace+0x2e) [0x55f8ef879c4e]
 
		/usr/sbin/mysqld(handle_fatal_signal+0x355) [0x55f8ef304825]
 
		/lib64/libpthread.so.0(+0xf5e0) [0x7f89c74655e0]
 
		/lib64/libc.so.6(gsignal+0x37) [0x7f89c59721f7]
 
		/lib64/libc.so.6(abort+0x148) [0x7f89c59738e8]
 
		/usr/sbin/mysqld(+0x42479e) [0x55f8ef0bd79e]
 
		/usr/sbin/mysqld(+0xac5298) [0x55f8ef75e298]
 
		/usr/sbin/mysqld(+0xac5e25) [0x55f8ef75ee25]
 
		/usr/sbin/mysqld(+0x93cb5c) [0x55f8ef5d5b5c]
 
		/usr/sbin/mysqld(+0x8e0a68) [0x55f8ef579a68]
 
		/usr/sbin/mysqld(+0x9825f2) [0x55f8ef61b5f2]
 
		/usr/sbin/mysqld(+0x98300c) [0x55f8ef61c00c]
 
		/usr/sbin/mysqld(+0x9834b9) [0x55f8ef61c4b9]
 
		/usr/sbin/mysqld(+0x84e609) [0x55f8ef4e7609]
 
		/usr/sbin/mysqld(ha_rollback_trans(THD*, bool)+0xe3) [0x55f8ef3074c3]
 
		/usr/sbin/mysqld(trans_rollback(THD*)+0x49) [0x55f8ef250c19]
 
		/usr/sbin/mysqld(rpl_group_info::cleanup_context(THD*, bool)+0x60) [0x55f8ef239590]
 
		/usr/sbin/mysqld(+0x5ece5e) [0x55f8ef285e5e]
 
		/usr/sbin/mysqld(handle_rpl_parallel_thread+0x581) [0x55f8ef287651]
 
		/usr/sbin/mysqld(+0x81d3ad) [0x55f8ef4b63ad]
 
		/lib64/libpthread.so.0(+0x7e25) [0x7f89c745de25]
 
		/lib64/libc.so.6(clone+0x6d) [0x7f89c5a3534d]
 
 
 
		Trying to get some variables.
 
		Some pointers may be invalid and cause the dump to abort.
 
		Query (0x0): is an invalid pointer
 
		Connection ID (thread ID): 311
 
		Status: NOT_KILLED
 
 
 
		Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
 
 
 
		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.
 
 
 
		We think the query pointer is invalid, but we will try to print it anyway.
 
		Query:
 
 
 
		2018-02-06  6:55:15 140452082636928 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html

note also the rollbacks:

We think the query pointer is invalid, but we will try to print it anyway.
 
Query:
 
 
 
2018-02-08  9:47:19 140367169685632 [Warning] InnoDB: Using innodb_file_format is deprecated and the parameter may be removed in future releases. See http://dev.mysql.com/doc/refman/5.7/en/innodb-file-format.html
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Uses event mutexes
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Compressed tables use zlib 1.2.7
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Using Linux native AIO
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Number of pools: 1
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Using SSE2 crc32 instructions
 
2018-02-08  9:47:19 140367169685632 [Note] InnoDB: Initializing buffer pool, total size = 112.625G, instances = 53, chunk size = 128M
 
2018-02-08  9:47:25 140367169685632 [Note] InnoDB: Completed initialization of buffer pool
 
2018-02-08  9:47:26 140235365107456 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2018-02-08  9:47:26 140367169685632 [Note] InnoDB: Highest supported file format is Barracuda.
 
2018-02-08  9:47:27 140367169685632 [Note] InnoDB: Starting crash recovery from checkpoint LSN=23122751843637
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198798 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198798 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198800 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198800 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198802 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198802 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198805 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198805 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198809 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198810 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198810 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198811 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Transaction 6438198812 was in the XA prepared state.
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: 9 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Trx id counter is 6438199296
 
2018-02-08  9:47:29 140367169685632 [Note] InnoDB: Starting final batch to recover 8617 pages from redo log.
 
2018-02-08  9:47:34 140367169685632 [Note] InnoDB: Last binlog file '../log/binlog.000925', position 12841999
 
2018-02-08  9:47:34 140367169685632 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2018-02-08  9:47:34 140235337811712 [Note] InnoDB: Starting in background the rollback of recovered transactions



 Comments   
Comment by Marko Mäkelä [ 2018-03-21 ]

MDEV-13800 is about undo log record corruption (trying to allocate a negative number of bytes for copying an undo log record).
This issue is some problem during the rollback of an update or delete operation, involving BLOBs. This would look more related to MDEV-14711, which is reporting an attempt to read a BLOB from a freed page.

Comment by Elena Stepanova [ 2018-03-23 ]

See also comment in the linked issue MDEV-14711 – according to marko, it might have more to do with this one.

Comment by Marko Mäkelä [ 2018-07-26 ]

If the workload involved InnoDB temporary tables, this could be a duplicate of MDEV-15826, which was fixed in 10.2.15 and 10.3.7. Does the problem repeat with a newer server?

Comment by Jean-François Gagné [ 2018-07-26 ]

Hi Marko, sorry, I cannot test if the problem repeats with a newer version, as I do not have access (anymore) to the system where I initially saw this problem.
There is a coredump attached to the internal ticket on this, maybe looking there would allow you to exactly know what this was.
Best, JFG

Comment by Chris Calender (Inactive) [ 2020-05-05 ]

We've just seen the the same crash and stack trace in a 10.2.27 instance.

Comment by Chris Calender (Inactive) [ 2020-05-05 ] 

Server version: 10.2.27-MariaDB-log
 
key_buffer_size=134217728
 
read_buffer_size=131072
 
max_used_connections=1426
 
max_threads=4002
 
thread_count=1451
 
It is possible that mysqld could use up to
 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4826741 K bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7ed2cc0009a8
 
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 = 0x7f2fe819de00 thread_stack 0x49000
 
/path/mariadb/10.2.27/bin/mysqld(my_print_stacktrace+0x2b)[0x559e958dac1b]
 
/path/mariadb/10.2.27/bin/mysqld(handle_fatal_signal+0x4b5)[0x559e9535fde5]
 
/lib64/libpthread.so.0(+0xf5f0)[0x7f30569fa5f0]
 
/lib64/libc.so.6(+0x15b901)[0x7f305592a901]
 
/path/mariadb/10.2.27/bin/mysqld(+0x9a0e69)[0x559e9563ae69]
 
/path/mariadb/10.2.27/bin/mysqld(+0x9a4b4f)[0x559e9563eb4f]
 
/path/mariadb/10.2.27/bin/mysqld(+0x970c77)[0x559e9560ac77]
 
/path/mariadb/10.2.27/bin/mysqld(+0xaee4af)[0x559e957884af]
 
/path/mariadb/10.2.27/bin/mysqld(+0xaf0203)[0x559e9578a203]
 
/path/mariadb/10.2.27/bin/mysqld(+0x964bed)[0x559e955febed]
 
/path/mariadb/10.2.27/bin/mysqld(+0x906377)[0x559e955a0377]
 
/path/mariadb/10.2.27/bin/mysqld(+0x9aabdd)[0x559e95644bdd]
 
/path/mariadb/10.2.27/bin/mysqld(+0x9ab59b)[0x559e9564559b]
 
/path/mariadb/10.2.27/bin/mysqld(+0x866379)[0x559e95500379]
 
/path/mariadb/10.2.27/bin/mysqld(_Z17ha_rollback_transP3THDb+0xe2)[0x559e95362e02]
 
/path/mariadb/10.2.27/bin/mysqld(_Z14trans_rollbackP3THD+0x5a)[0x559e952ae6ba]
 
/path/mariadb/10.2.27/bin/mysqld(_ZN14rpl_group_info15cleanup_contextEP3THDb+0x60)[0x559e95297ef0]
 
/path/mariadb/10.2.27/bin/mysqld(+0x649a21)[0x559e952e3a21]
 
/path/mariadb/10.2.27/bin/mysqld(handle_rpl_parallel_thread+0xd70)[0x559e952e5b80]
 
/path/mariadb/10.2.27/bin/mysqld(+0x84a15d)[0x559e954e415d]
 
/lib64/libpthread.so.0(+0x7e65)[0x7f30569f2e65]
 
/lib64/libc.so.6(clone+0x6d)[0x7f30558cd88d]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.

Comment by Marko Mäkelä [ 2020-05-06 ]

I resolved the numeric addresses in the MariaDB 10.2.27 stack trace that ccalender posted:

mariadb-10.2.27

 
0x9a0e69 is in trx_undo_get_undo_rec_low(roll_ptr_t, mem_heap_t*) (/home/buildbot/buildbot/build/storage/innobase/include/trx0rec.ic:99).
 
0x9a4b4f is in trx_undo_prev_version_build(unsigned char const*, mtr_t*, unsigned char const*, dict_index_t*, unsigned long*, mem_block_info_t*, unsigned char**, mem_block_info_t*, dtuple_t**, unsigned long) (/home/buildbot/buildbot/build/storage/innobase/trx/trx0rec.cc:2258).
 
0x970c77 is in row_vers_old_has_index_entry(bool, unsigned char const*, mtr_t*, dict_index_t*, dtuple_t const*, unsigned long, unsigned long, purge_vcol_info_t*) (/home/buildbot/buildbot/build/storage/innobase/include/mem0mem.ic:426).
 
0xaee4af is in row_undo_mod_del_mark_or_remove_sec_low(undo_node_t*, que_thr_t*, dict_index_t*, dtuple_t*, ulint) (/home/buildbot/buildbot/build/storage/innobase/row/row0umod.cc:507).
 
0xaf0203 is in row_undo_mod(undo_node_t*, que_thr_t*) (/home/buildbot/buildbot/build/storage/innobase/row/row0umod.cc:582).
 
0x964bed is in row_undo_step(que_thr_t*) (/home/buildbot/buildbot/build/storage/innobase/row/row0undo.cc:303).
 
0x906377 is in que_run_threads(que_thr_t*) (/home/buildbot/buildbot/build/storage/innobase/que/que0que.cc:1060).
 
0x9aabdd is in trx_rollback_to_savepoint_low(trx_t*, trx_savept_t*) (/home/buildbot/buildbot/build/storage/innobase/trx/trx0roll.cc:111).
 
0x9ab59b is in trx_rollback_for_mysql(trx_t*) (/home/buildbot/buildbot/build/storage/innobase/trx/trx0roll.cc:171).
 
166	in /home/buildbot/buildbot/build/storage/innobase/trx/trx0roll.cc
 
0x866379 is in innobase_rollback(handlerton*, THD*, bool) (/home/buildbot/buildbot/build/storage/innobase/handler/ha_innodb.cc:2886).

I do not have the matching libc.so.6 code that this resolved part of the stack trace is invoking. The return address in the stack is for the following function call:

   0x00000000009a0e64 <+404>:	callq  0x8d3d10 <mem_heap_dup(mem_block_info_t*, void const*, unsigned long)>
 
   0x00000000009a0e69 <+409>:	mov    %rax,%r13

It corresponds to the following source code:

/***********************************************************************//**
 
Copies the undo record to the heap.
 
@return own: copy of undo log record */
 
UNIV_INLINE
 
trx_undo_rec_t*
 
trx_undo_rec_copy(
 
/*==============*/
 
	const trx_undo_rec_t*	undo_rec,	/*!< in: undo log record */
 
	mem_heap_t*		heap)		/*!< in: heap where copied */
 
{
 
	ulint		len;
 
 
 
	len = mach_read_from_2(undo_rec)
 
		- ut_align_offset(undo_rec, UNIV_PAGE_SIZE);
 
	ut_ad(len < UNIV_PAGE_SIZE);
 
	trx_undo_rec_t* rec = static_cast<trx_undo_rec_t*>(
 
		mem_heap_dup(heap, undo_rec, len));
 
	mach_write_to_2(rec, len);
 
	return rec;
 
}

I would guess that len is negative (or close to 16 EiB), that is, we have a corrupted undo log page, or maybe even more likely, a corrupted or stale DB_ROLL_PTR that is not pointing to the start of a valid undo log record. This stack trace does not look like the originally reported bug, but rather something that is likely related to MDEV-14711.

Normally, the undo log records are written ahead of the clustered index leaf page changes, and on rollback or purge, the DB_ROLL_PTR references in the clustered index leaf page would be invalidated before the undo record becomes invalid. All these operations are written ahead to the redo log. If InnoDB ever reported of some LSN mismatch (such as, FIL_PAGE_LSN being in the future), that could explain why the clustered index B-tree leaf page and the undo log page got out of sync. This would be a sign of something being seriously wrong with the database, and it would be a sign of a bug in InnoDB redo logging, crash recovery, or Mariabackup. (If innodb_force_recovery=6 is ever used or the ib_logfile* are discarded or renamed before starting the server, or if data files are being copied while the server is running, then it could be a user error.)

Comment by Marko Mäkelä [ 2020-12-28 ]

MDEV-22388 suggests how we could fix the code to avoid a crash when encountering this type of corruption. The cause of this corruption might be fixed by MDEV-24449.

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

Both reported failures in this ticket could have been the result of corruption that was caused by the bug that was present in all InnoDB implementations until MDEV-24449 was recently fixed.

That bug can corrupt anything in the InnoDB system tablespace (including undo logs) as well as corrupt secondary indexes.

Comment by Ian Gilfillan [ 2023-03-14 ]

Note the possibly-related discussion at https://mariadb.zulipchat.com/#narrow/stream/118759-general/topic/InnoDB.20Rollback.20Bug

Comment by Marko Mäkelä [ 2023-03-15 ]

When it comes to the corruption that causes the crash in trx_undo_rec_copy(), in MDEV-30671 we found proof for it in the case when innodb_undo_log_truncate=ON is being used. I believe that such corruption may be possible also in the case that trx_purge_truncate_rseg_history() is calling trx_purge_free_segment() and the page is being reused for something else before the record is being accessed.

The rollback of some operations involves a purge of older history, nowadays in the function row_undo_mod_must_purge(). It can access undo log records for not yet purged committed transactions. Also in the posted mariadb-10.2.27 stack trace, we see a similar check, via the call row_vers_old_has_index_entry(). Such undo log records could become garbage due to the bug that was fixed in MDEV-30671.

Comment by Marko Mäkelä [ 2023-03-20 ]

For the discussion that greenman linked to, I filed MDEV-30882, which is a bug related to DELETE operations in ROW_FORMAT=COMPRESSED tables.

Comment by Jean-François Gagné [ 2023-03-20 ]

Nice, thanks Marko.

I think we got to the root cause of this. Optimistic Parallel replication needs to do some rollback when something run optimistically ends-up conflicting with something that should have run before, so with the possibility of a rollback causing a crash, things make sense. I will continue to follow in MDEV-30882.

This MDEV (MDEV-15608) can probably be resolved as "duplicate of MDEV-30882".

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