[MDEV-25518] mariadb crash with mysqld got signal 11 Created: 2021-04-26  Updated: 2022-01-03  Resolved: 2022-01-03

Status: Closed
Project: MariaDB Server
Component/s: wsrep
Affects Version/s: 10.5.9, 10.5
Fix Version/s: 10.2.41, 10.3.32, 10.4.22, 10.5.13, 10.6.5

Type: Bug Priority: Critical
Reporter: Jaroslav Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Attachments: Text File gdb_output.txt     Text File system.log    
Issue Links:
Relates
relates to MDEV-23328 Server hang due to Galera lock confli... Closed

 Description   

We've seems to hit over and over mariadb crashing with following on our multi-master setup. We've tried to decrease memory limits on the nodes but seems issue still occurs.

210425 18:56:31 [ERROR] mysqld got signal 11 ;
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.9-MariaDB-1:10.5.9+maria~focal
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=25
max_threads=252
thread_count=35
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 685804 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
mysqld(my_print_stacktrace+0x32)[0x561fa0b33af2]
Printing to addr2line failed
mysqld(handle_fatal_signal+0x485)[0x561fa05896f5]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x153c0)[0x7f141501f3c0]
mysqld(+0xc70ebf)[0x561fa088eebf]
mysqld(handle_manager+0x15e)[0x561fa036be9e]
mysqld(+0xbc1c66)[0x561fa07dfc66]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x9609)[0x7f1415013609]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x43)[0x7f1414c02293]
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...
Working directory at /var/lib/mysql
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        unlimited            unlimited            bytes
Max resident set          unlimited            unlimited            bytes
Max processes             unlimited            unlimited            processes
Max open files            1048576              1048576              files
Max locked memory         16777216             16777216             bytes
Max address space         unlimited            unlimited            bytes
Max file locks            unlimited            unlimited            locks
Max pending signals       59986                59986                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: core.%e.%p.%t

Our specific config options:

  galera.cnf: |
    [galera]
    user = mysql
    bind-address = 0.0.0.0
    default_storage_engine = InnoDB
    binlog_format = ROW
    innodb_autoinc_lock_mode = 2
    innodb_flush_log_at_trx_commit = 0
    query_cache_size = 0
    query_cache_type = 0
    binlog_cache_size = 61440
 
    # MariaDB Galera settings
    wsrep_on=ON
    wsrep_provider=/usr/lib/galera/libgalera_smm.so
    wsrep_sst_method=rsync
    wsrep_slave_threads=8
    wsrep_sync_wait=7
 
    # Cluster settings (automatically updated)
    wsrep_cluster_address=gcomm://
    wsrep_cluster_name=mysql
    wsrep_node_address=127.0.0.1
  mariadb.cnf: "[client]\ndefault-character-set = utf8\n[mysqld]\ncore-file\nunix_socket
    = OFF\nperformance_schema = ON\ncharacter-set-server = utf8\ncollation-server
    = utf8_general_ci\nignore-db-dirs = lost+found \nmax_connections = 250\ninteractive_timeout
    = 450 \nwait_timeout = 450\n# InnoDB tuning\ninnodb_buffer_pool_size = 7000MB\ninnodb_log_file_size
    = 1600MB\n"

Performance details from mysqtuner

-------- Performance Metrics -----------------------------------------------------------------------
[--] Up for: 11h 32m 3s (482K q [11.626 qps], 60K conn, TX: 800M, RX: 105M)
[--] Reads / Writes: 80% / 20%
[--] Binary logging is disabled
[--] Physical Memory     : 14.7G
[--] Max MySQL memory    : 11.8G
[--] Other process memory: 0B
[--] Total buffers: 7.2G global + 18.9M per thread (250 max threads)
[--] P_S Max memory usage: 72B
[--] Galera GCache Max memory usage: 128M
[OK] Maximum reached memory usage: 7.7G (52.38% of installed RAM)
[OK] Maximum possible memory usage: 11.8G (80.17% of installed RAM)
[OK] Overall possible memory usage with other process is compatible with memory available
[OK] Slow queries: 0% (0/482K)
[OK] Highest usage of available connections: 11% (29/250)
[OK] Aborted connections: 0.00%  (0/60012)
[!!] name resolution is active : a reverse name resolution is made for each new connection and can reduce performance
[OK] Query cache is disabled by default due to mutex contention on multiprocessor machines.
[OK] Sorts requiring temporary tables: 0% (0 temp sorts / 1K sorts)
[!!] Joins performed without indexes: 1008
[OK] Temporary tables created on disk: 1% (804 on disk / 57K total)
[OK] Thread cache hit rate: 99% (38 created / 60K connections)
[OK] Table cache hit rate: 98% (530 open / 537 opened)
[OK] table_definition_cache(400) is upper than number of tables(383)
[OK] Open file limit used: 0% (60/32K)
[OK] Table locks acquired immediately: 100% (791 immediate / 791 locks)

Can you please check if this is a bug or some configuration issue? The crash file is one-time download in https://file.io/UfHRT94iSLvI



 Comments   
Comment by Marko Mäkelä [ 2021-04-26 ]

jaroslav, can you please try to provide a full stack trace of the crash that would include all threads that were executing during the time of the crash?

The stack trace includes a handle_manager thread that is consuming events that were produced by mysql_manager_submit() calls. Because Galera is involved, I suspect that this has something to do with MDEV-23328.

Comment by Jaroslav [ 2021-04-26 ]

Marko it seems that our current design won't allow us to install debug version of mariadb. We use stripped version (docker)

/usr/sbin/mariadbd: ELF 64-bit LSB shared object, x86-64, version 1 (GNU/Linux), dynamically linked, interpreter /lib64/ld-linux-x86-64.so.2, BuildID[sha1]=ef5223e4cd797dbd8fcf62bff76e99eb94ceaf9e, for GNU/Linux 3.2.0, stripped

I can't find and easy way how to do this for this kind of architecture. Is there some additional way how to get you more details from crash?

Comment by Jaroslav [ 2021-04-26 ]

We tried to add some more debug to the core file we added as description and this is the most we could get (see attachment gdb_output). Will this be sufficient Marko/Sergei?

Comment by Sergei Golubchik [ 2021-04-28 ]

yes, thanks. let me see what we can get from that.

Comment by Sergei Golubchik [ 2021-05-02 ]

The important part apparently is

#0  0x0000561fa088eebf in bg_wsrep_kill_trx (void_arg=<optimized out>) at ./storage/innobase/handler/ha_innodb.cc:18690
#1  0x0000561fa036be9e in handle_manager (arg=arg@entry=0x0) at ./sql/sql_manager.cc:113
#2  0x0000561fa07dfc66 in pfs_spawn_thread (arg=0x561fa9fd65a8) at ./storage/perfschema/pfs.cc:2201

and the line in question is

18676
        if ((bf_thd= find_thread_by_id(arg->bf_thd_id)))
18677
                wsrep_thd_LOCK(bf_thd);
18678
        if ((thd= find_thread_by_id(arg->thd_id)))
18679
                wsrep_thd_LOCK(thd);
18680
 
18681
        if (!thd || !bf_thd || !(victim_trx= thd_to_trx(thd)))
18682
                goto ret0;
18683
 
18684
        lock_mutex_enter();
18685
        trx_mutex_enter(victim_trx);
18686
        if (victim_trx->id != arg->trx_id)
18687
        {
18688
                /* apparently victim trx was meanwhile rolled back.
18689
                tell bf thd not to wait, in case it already started to */
18690
                trx_t *trx= thd_to_trx(bf_thd);
18691
                if (lock_t *lock= trx->lock.wait_lock) {

If the highlighted line 18690 has indeed caused the crash, it means that thd pointer was invalid. It couldn't have been NULL, this was checked on the line 18681. And it was still valid on the line 18677. Generally find_thread_by_id() returns a thd with its thd->LOCK_thd_kill locked, so thd couldn't have been deleted after find_thread_by_id(), if that protection is broken we would've likely had lots of bug reports and tests would've likely detected it too.

Another option is that the crash was actually caused by the line 18691, meaning thd is fine, but trx is invalid.

Comment by Jaroslav [ 2021-05-03 ]

Thanks Sergei. Is there something we can do in this case to confirm this theory? The signal 11 seems to be ongoing for us so if you would like to see "fresh" coredump we can maybe provide those. However they were created on stripped version.

Comment by Sergei Golubchik [ 2021-12-25 ]

This code no longer exists in MariaDB it was completely rewritten in the last release. Do you still experience crashes?

Comment by Jaroslav [ 2022-01-03 ]

I think this one is good to be closed. Haven't seen this one to occur recently

Generated at Thu Feb 08 09:38:18 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.