[MDEV-32822] Crash signal 11 with Rocksb Created: 2023-11-16  Updated: 2023-11-19

Status: Open
Project: MariaDB Server
Component/s: Server
Fix Version/s: None

Type: Task Priority: Major
Reporter: Aurélien LEQUOY Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-27438 Spider: crash in spider_sys_open_tabl... Open

 Description   

It's was long time it's happend to me last time : (version of MariaDB : 10.11.6, on ubuntu 22.04)

2023-11-16 12:19:11 0 [Note] Starting MariaDB 10.11.6-MariaDB-1:10.11.6+maria~ubu2204-log source revision fecd78b83785d5ae96f2c6ff340375be803cd299 as process 37569
2023-11-16 12:19:11 0 [Note] mariadbd: Aria engine: starting recovery
recovered pages: 0% 10% 20% 32% 46% 60% 71% 86% 96% 100% (0.0 seconds); tables to flush: 1 0
 (0.0 seconds); 
2023-11-16 12:19:11 0 [Note] mariadbd: Aria engine: recovery done
2023-11-16 12:19:11 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-11-16 12:19:11 0 [Note] InnoDB: Number of transaction pools: 1
2023-11-16 12:19:11 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-11-16 12:19:11 0 [Note] InnoDB: Using liburing
2023-11-16 12:19:11 0 [Note] InnoDB: Initializing buffer pool, total size = 47.000GiB, chunk size = 0.734GiB
2023-11-16 12:19:11 0 [Note] InnoDB: Completed initialization of buffer pool
2023-11-16 12:19:11 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2023-11-16 12:19:11 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4695286604
2023-11-16 12:19:12 0 [Note] InnoDB: End of log at LSN=4868790831
2023-11-16 12:19:12 0 [Note] InnoDB: To recover: 464 pages
2023-11-16 12:19:13 0 [Note] InnoDB: Last binlog file '/srv/mysql/binlog/mariadb-bin.000620', position 93990914
2023-11-16 12:19:13 0 [Note] InnoDB: 128 rollback segments are active.
2023-11-16 12:19:13 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2023-11-16 12:19:13 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2023-11-16 12:19:13 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2023-11-16 12:19:13 0 [Note] InnoDB: log sequence number 4868790831; transaction id 2877698
2023-11-16 12:19:13 0 [Note] InnoDB: Loading buffer pool(s) from /srv/mysql/data/ib_buffer_pool
2023-11-16 12:19:13 0 [Note] Plugin 'FEEDBACK' is disabled.
231116 12:19:13 server_audit: MariaDB Audit Plugin version 1.4.14 STARTED.
231116 12:19:13 server_audit: logging started to the file /srv/mysql/log/audit.log.
2023-11-16 12:19:13 0 [Note] InnoDB: Buffer pool(s) load completed at 231116 12:19:13
2023-11-16 12:19:13 0 [Note] RocksDB: 2 column families found
2023-11-16 12:19:13 0 [Note] RocksDB: Column Families at start:
2023-11-16 12:19:13 0 [Note]   cf=default
2023-11-16 12:19:13 0 [Note]     write_buffer_size=67108864
2023-11-16 12:19:13 0 [Note]     target_file_size_base=67108864
2023-11-16 12:19:13 0 [Note]   cf=__system__
2023-11-16 12:19:13 0 [Note]     write_buffer_size=67108864
2023-11-16 12:19:13 0 [Note]     target_file_size_base=67108864
2023-11-16 12:19:16 0 [Note] RocksDB: Table_store: loaded DDL data for 270 tables
2023-11-16 12:19:16 0 [Note] RocksDB: global statistics using get_sched_indexer_t indexer
2023-11-16 12:19:16 0 [Note] MyRocks storage engine plugin has been successfully initialized.
2023-11-16 12:19:16 0 [Note] Recovering after a crash using /srv/mysql/binlog/mariadb-bin
2023-11-16 12:19:16 0 [Note] Starting table crash recovery...
2023-11-16 12:19:16 0 [Note] Found 1 prepared transaction(s) in ROCKSDB
2023-11-16 12:19:16 0 [Note] Crash table recovery finished.
2023-11-16 12:19:16 0 [ERROR] Error in Log_event::read_log_event(): 'Event invalid', data_len: 0, event_type: 0
231116 12:19:16 [ERROR] mysqld got signal 11 ;
Sorry, we probably made a mistake, and this is a bug.
 
Your assistance in bug reporting will enable us to fix this for the next release.
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.11.6-MariaDB-1:10.11.6+maria~ubu2204-log source revision: fecd78b83785d5ae96f2c6ff340375be803cd299
key_buffer_size=134217728
read_buffer_size=2097152
max_used_connections=0
max_threads=1002
thread_count=20
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 6314082 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 0x49000
/usr/sbin/mariadbd(my_print_stacktrace+0x32)[0x56188120a8b2]
/usr/sbin/mariadbd(handle_fatal_signal+0x478)[0x561880cd6e68]
libc_sigaction.c:0(__restore_rt)[0x7fb66e042520]
/usr/lib/mysql/plugin/ha_spider.so(_Z21spider_sys_open_tableP3THDP10TABLE_LISTPP15start_new_trans+0x1b)[0x7faa4593420b]
/usr/lib/mysql/plugin/ha_spider.so(_Z21spider_open_sys_tableP3THDPKcibPP15start_new_transbPi+0xf6)[0x7faa45934496]
/usr/lib/mysql/plugin/ha_spider.so(_Z34spider_internal_xa_rollback_by_xidP3THDP21st_spider_transactionP5xid_t+0x15b)[0x7faa4594238b]
/usr/lib/mysql/plugin/ha_spider.so(_Z25spider_xa_rollback_by_xidP10handlertonP5xid_t+0x3f)[0x7faa4594534f]
/usr/sbin/mariadbd(+0xa8b09d)[0x561880cd909d]
/usr/sbin/mariadbd(_Z24plugin_foreach_with_maskP3THDPFcS0_P13st_plugin_intPvEijS3_+0x1a9)[0x561880a8dc99]
/usr/sbin/mariadbd(+0xa89dcf)[0x561880cd7dcf]
/usr/sbin/mariadbd(my_hash_iterate+0x50)[0x5618811eb3c0]
/usr/sbin/mariadbd(_Z19ha_recover_completeP7st_hashPSt4pairIjyE+0x30)[0x561880cdcc30]
/usr/sbin/mariadbd(_ZN16Recovery_context8completeEP13MYSQL_BIN_LOGR7st_hash+0x6f)[0x561880df8b8f]
/usr/sbin/mariadbd(_ZN13MYSQL_BIN_LOG7recoverEP11st_log_infoPKcP11st_io_cacheP28Format_description_log_eventb+0x780)[0x561880df9a90]
/usr/sbin/mariadbd(_ZN13MYSQL_BIN_LOG18do_binlog_recoveryEPKcb+0x303)[0x561880df9ee3]
/usr/sbin/mariadbd(_ZN13MYSQL_BIN_LOG4openEPKc+0x3f)[0x561880e0043f]
/usr/sbin/mariadbd(+0x7147a9)[0x5618809627a9]
/usr/sbin/mariadbd(_Z11mysqld_mainiPPc+0x424)[0x561880967384]
nptl/libc_start_call_main.h:58(__libc_start_call_main)[0x7fb66e029d90]
csu/libc-start.c:128(call_init)[0x7fb66e029e40]
/usr/sbin/mariadbd(_start+0x25)[0x56188095be65]
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mariadbd/ contains
information that should help you find out what is causing the crash.
Writing a core file...
Working directory at /srv/mysql/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                    unlimited            bytes     
Max resident set          unlimited            unlimited            bytes     
Max processes             255361               255361               processes 
Max open files            32768                32768                files     
Max locked memory         524288               524288               bytes     
Max address space         unlimited            unlimited            bytes     
Max file locks            unlimited            unlimited            locks     
Max pending signals       255361               255361               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%p -s%s -c%c -d%d -P%P -u%u -g%g -- %E
 
Kernel version: Linux version 6.2.0-36-generic (buildd@lcy02-amd64-050) (x86_64-linux-gnu-gcc-11 (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, GNU ld (GNU Binutils for Ubuntu) 2.38) #37~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Mon Oct  9 15:34:04 UTC 2
 
2023-11-16 12:20:45 0 [Note] Starting MariaDB 10.11.6-MariaDB-1:10.11.6+maria~ubu2204-log source revision fecd78b83785d5ae96f2c6ff340375be803cd299 as process 37740
2023-11-16 12:20:45 0 [Note] mysqld: Aria engine: starting recovery
recovered pages: 0% 10% 20% 32% 46% 60% 71% 86% 96% 100% (0.0 seconds); tables to flush: 1 0
 (0.0 seconds); 
2023-11-16 12:20:45 0 [Note] mysqld: Aria engine: recovery done
2023-11-16 12:20:45 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-11-16 12:20:45 0 [Note] InnoDB: Number of transaction pools: 1
2023-11-16 12:20:45 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-11-16 12:20:45 0 [Note] InnoDB: Using liburing
2023-11-16 12:20:45 0 [Note] InnoDB: Initializing buffer pool, total size = 47.000GiB, chunk size = 0.734GiB
2023-11-16 12:20:45 0 [Note] InnoDB: Completed initialization of buffer pool
2023-11-16 12:20:45 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2023-11-16 12:20:45 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=4695286604
2023-11-16 12:20:47 0 [Note] InnoDB: End of log at LSN=4868791288
2023-11-16 12:20:47 0 [Note] InnoDB: To recover: 464 pages
2023-11-16 12:20:47 0 [Note] InnoDB: Last binlog file '/srv/mysql/binlog/mariadb-bin.000620', position 93990914
2023-11-16 12:20:47 0 [Note] InnoDB: 128 rollback segments are active.
2023-11-16 12:20:47 0 [Note] InnoDB: Removed temporary tablespace data file: "./ibtmp1"
2023-11-16 12:20:47 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2023-11-16 12:20:47 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2023-11-16 12:20:47 0 [Note] InnoDB: log sequence number 4868791288; transaction id 2877698
2023-11-16 12:20:47 0 [Note] Plugin 'FEEDBACK' is disabled.
231116 12:20:47 server_audit: MariaDB Audit Plugin version 1.4.14 STARTED.
231116 12:20:47 server_audit: logging started to the file /srv/mysql/log/audit.log.
2023-11-16 12:20:47 0 [Note] InnoDB: Loading buffer pool(s) from /srv/mysql/data/ib_buffer_pool
2023-11-16 12:20:47 0 [Note] InnoDB: Buffer pool(s) load completed at 231116 12:20:47
2023-11-16 12:20:47 0 [Note] RocksDB: 2 column families found
2023-11-16 12:20:47 0 [Note] RocksDB: Column Families at start:
2023-11-16 12:20:47 0 [Note]   cf=default
2023-11-16 12:20:47 0 [Note]     write_buffer_size=67108864
2023-11-16 12:20:47 0 [Note]     target_file_size_base=67108864
2023-11-16 12:20:47 0 [Note]   cf=__system__
2023-11-16 12:20:47 0 [Note]     write_buffer_size=67108864
2023-11-16 12:20:47 0 [Note]     target_file_size_base=67108864
2023-11-16 12:20:50 0 [Note] RocksDB: Table_store: loaded DDL data for 270 tables
2023-11-16 12:20:50 0 [Note] RocksDB: global statistics using get_sched_indexer_t indexer
2023-11-16 12:20:50 0 [Note] MyRocks storage engine plugin has been successfully initialized.
2023-11-16 12:20:50 0 [Note] Heuristic crash recovery mode
2023-11-16 12:20:50 0 [Note] Found 1 prepared transaction(s) in ROCKSDB
2023-11-16 12:20:50 0 [Note] Please restart without --tc-heuristic-recover
2023-11-16 12:20:50 0 [Note] Recovering after a crash using /srv/mysql/binlog/mariadb-bin
2023-11-16 12:20:50 0 [ERROR] Error in Log_event::read_log_event(): 'Event invalid', data_len: 0, event_type: 0
2023-11-16 12:20:50 0 [ERROR] Can't init tc log
2023-11-16 12:20:50 0 [ERROR] Aborting
231116 12:20:50 server_audit: STOPPED
2023-11-16 12:21:00 0 [Note] Starting MariaDB 10.11.6-MariaDB-1:10.11.6+maria~ubu2204-log source revision fecd78b83785d5ae96f2c6ff340375be803cd299 as process 38171
2023-11-16 12:21:00 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2023-11-16 12:21:00 0 [Note] InnoDB: Number of transaction pools: 1
2023-11-16 12:21:00 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2023-11-16 12:21:00 0 [Note] InnoDB: Using liburing
2023-11-16 12:21:00 0 [Note] InnoDB: Initializing buffer pool, total size = 47.000GiB, chunk size = 0.734GiB
2023-11-16 12:21:00 0 [Note] InnoDB: Completed initialization of buffer pool
2023-11-16 12:21:00 0 [Note] InnoDB: Buffered log writes (block size=512 bytes)
2023-11-16 12:21:00 0 [Note] InnoDB: End of log at LSN=4868792460
2023-11-16 12:21:00 0 [Note] InnoDB: 128 rollback segments are active.
2023-11-16 12:21:00 0 [Note] InnoDB: Setting file './ibtmp1' size to 12.000MiB. Physically writing the file full; Please wait ...
2023-11-16 12:21:00 0 [Note] InnoDB: File './ibtmp1' size is now 12.000MiB.
2023-11-16 12:21:00 0 [Note] InnoDB: log sequence number 4868792460; transaction id 2877698
2023-11-16 12:21:00 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-11-16 12:21:00 0 [Note] InnoDB: Loading buffer pool(s) from /srv/mysql/data/ib_buffer_pool
231116 12:21:00 server_audit: MariaDB Audit Plugin version 1.4.14 STARTED.
231116 12:21:00 server_audit: logging started to the file /srv/mysql/log/audit.log.
2023-11-16 12:21:00 0 [Note] InnoDB: Buffer pool(s) load completed at 231116 12:21:00
2023-11-16 12:21:01 0 [Note] RocksDB: 2 column families found
2023-11-16 12:21:01 0 [Note] RocksDB: Column Families at start:
2023-11-16 12:21:01 0 [Note]   cf=default
2023-11-16 12:21:01 0 [Note]     write_buffer_size=67108864
2023-11-16 12:21:01 0 [Note]     target_file_size_base=67108864
2023-11-16 12:21:01 0 [Note]   cf=__system__
2023-11-16 12:21:01 0 [Note]     write_buffer_size=67108864
2023-11-16 12:21:01 0 [Note]     target_file_size_base=67108864
2023-11-16 12:21:01 0 [Note] RocksDB: Table_store: loaded DDL data for 270 tables
2023-11-16 12:21:01 0 [Note] RocksDB: global statistics using get_sched_indexer_t indexer
2023-11-16 12:21:01 0 [Note] MyRocks storage engine plugin has been successfully initialized.
2023-11-16 12:21:01 0 [Note] Server socket created on IP: '0.0.0.0'.
2023-11-16 12:21:01 22 [Note] Event Scheduler: scheduler thread started with id 22
2023-11-16 12:21:01 0 [Note] /usr/sbin/mariadbd: ready for connections.
Version: '10.11.6-MariaDB-1:10.11.6+maria~ubu2204-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution

I guess it's happened when my laptop was out of battery

to solve it :

mysqld --tc-heuristic-recover=rollback

and start again mysql :

service mysql start



 Comments   
Comment by Roel Van de Paar [ 2023-11-19 ]

Demangled stack

/usr/sbin/mariadbd(my_print_stacktrace+0x32)[0x56188120a8b2]
/usr/sbin/mariadbd(handle_fatal_signal+0x478)[0x561880cd6e68]
libc_sigaction.c:0(__restore_rt)[0x7fb66e042520]
/usr/lib/mysql/plugin/ha_spider.so(spider_sys_open_table(THD*, TABLE_LIST*, start_new_trans**)+0x1b)[0x7faa4593420b]
/usr/lib/mysql/plugin/ha_spider.so(spider_open_sys_table(THD*, char const*, int, bool, start_new_trans**, bool, int*)+0xf6)[0x7faa45934496]
/usr/lib/mysql/plugin/ha_spider.so(spider_internal_xa_rollback_by_xid(THD*, st_spider_transaction*, xid_t*)+0x15b)[0x7faa4594238b]
/usr/lib/mysql/plugin/ha_spider.so(spider_xa_rollback_by_xid(handlerton*, xid_t*)+0x3f)[0x7faa4594534f]
/usr/sbin/mariadbd(+0xa8b09d)[0x561880cd909d]
/usr/sbin/mariadbd(plugin_foreach_with_mask(THD*, char (*)(THD*, st_plugin_int*, void*), int, unsigned int, void*)+0x1a9)[0x561880a8dc99]
/usr/sbin/mariadbd(+0xa89dcf)[0x561880cd7dcf]
/usr/sbin/mariadbd(my_hash_iterate+0x50)[0x5618811eb3c0]
/usr/sbin/mariadbd(ha_recover_complete(st_hash*, std::pair<unsigned int, unsigned long long>*)+0x30)[0x561880cdcc30]
/usr/sbin/mariadbd(Recovery_context::complete(MYSQL_BIN_LOG*, st_hash&)+0x6f)[0x561880df8b8f]
/usr/sbin/mariadbd(MYSQL_BIN_LOG::recover(st_log_info*, char const*, st_io_cache*, Format_description_log_event*, bool)+0x780)[0x561880df9a90]
/usr/sbin/mariadbd(MYSQL_BIN_LOG::do_binlog_recovery(char const*, bool)+0x303)[0x561880df9ee3]
/usr/sbin/mariadbd(MYSQL_BIN_LOG::open(char const*)+0x3f)[0x561880e0043f]
/usr/sbin/mariadbd(+0x7147a9)[0x5618809627a9]
/usr/sbin/mariadbd(mysqld_main(int, char**)+0x424)[0x561880967384]
nptl/libc_start_call_main.h:58(__libc_start_call_main)[0x7fb66e029d90]
csu/libc-start.c:128(call_init)[0x7fb66e029e40]
/usr/sbin/mariadbd(_start+0x25)[0x56188095be65]

Generated at Thu Feb 08 10:34:17 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.