Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-15608

Crash during transaction rollback when using optimistic parallel replication, few threads, non-durable configuration.

    XMLWordPrintable

    Details

      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
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                marko Marko Mäkelä
                Reporter:
                juan.vera Juan
              • Votes:
                2 Vote for this issue
                Watchers:
                7 Start watching this issue

                Dates

                • Created:
                  Updated: