[MDEV-23943] innodb double free on shutdown after insufficent innodb buffer pool allocation Created: 2020-10-12  Updated: 2023-09-19  Resolved: 2023-09-19

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.3.17, 10.1.47, 10.2.34
Fix Version/s: 10.4.31

Type: Bug Priority: Major
Reporter: Leon Heess Assignee: Daniel Black
Resolution: Fixed Votes: 0
Labels: Papercut, crash, not-10.5
Environment:

CentOS 8


Issue Links:
Relates
relates to MDEV-17921 Galera SST successfully finishing wit... Closed

 Description   

About every three days this happens:

2020-09-30 15:05:16 0 [Note] InnoDB: Using Linux native AIO
2020-09-30 15:05:16 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-09-30 15:05:16 0 [Note] InnoDB: Uses event mutexes
2020-09-30 15:05:16 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-09-30 15:05:16 0 [Note] InnoDB: Number of pools: 1
2020-09-30 15:05:16 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-09-30 15:05:17 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-09-30 15:05:17 0 [ERROR] InnoDB: mmap(137297920 bytes) failed; errno 12
2020-09-30 15:05:17 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2020-09-30 15:05:17 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2020-09-30 15:05:17 0 [Note] InnoDB: Starting shutdown...
double free or corruption (out)
200930 15:05:17 [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.17-MariaDB
key_buffer_size=134217728
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 = 467422 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

The service crashes and cannot be restarted until I add

[mysqld]
innodb_force_recovery = 1

to my.cnf AND restart the entire server. What is happening?



 Comments   
Comment by Daniel Black [ 2020-10-12 ]

InnoDB: mmap(137297920 bytes) failed; errno 12

perror 12
OS error code 12: Cannot allocate memory

You ran out of memory, on 128M allocation. Running in tight memory constraints is difficult. Recommend ensuring more memory is available.

To be fair the shutdown shouldn't have crashed.

Comment by Daniel Black [ 2020-10-12 ]

reproduced on latest 10.3:

10.3.26

~/repos/build-mariadb-server-10.3-nosan 
$ ulimit -v $((1280 * 1024 ))
 
~/repos/build-mariadb-server-10.3-nosan 
$  mariadblocal --memlock --innodb-buffer-pool-size=2G
Installing MariaDB/MySQL system tables in '/tmp/build-mariadb-server-10.3-nosan-datadir' ...
2020-10-13  8:45:59 0 [Note] /home/dan/repos/build-mariadb-server-10.3-nosan/sql/mysqld (mysqld 10.3.26-MariaDB) starting as process 2609606 ...
2020-10-13  8:45:59 0 [Note] InnoDB: Using Linux native AIO
2020-10-13  8:45:59 0 [Note] InnoDB: The first innodb_system data file 'ibdata1' did not exist. A new tablespace will be created!
2020-10-13  8:45:59 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-10-13  8:45:59 0 [Note] InnoDB: Uses event mutexes
2020-10-13  8:45:59 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-10-13  8:45:59 0 [Note] InnoDB: Number of pools: 1
2020-10-13  8:45:59 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-10-13  8:45:59 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2020-10-13  8:45:59 0 [Note] InnoDB: Completed initialization of buffer pool
2020-10-13  8:45:59 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2020-10-13  8:45:59 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
2020-10-13  8:45:59 0 [Note] InnoDB: File './ibdata1' size is now 12 MB.
2020-10-13  8:45:59 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
2020-10-13  8:45:59 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
2020-10-13  8:45:59 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2020-10-13  8:45:59 0 [Note] InnoDB: New log files created, LSN=44897
2020-10-13  8:45:59 0 [Note] InnoDB: Doublewrite buffer not found: creating new
2020-10-13  8:45:59 0 [Note] InnoDB: Doublewrite buffer created
2020-10-13  8:45:59 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-10-13  8:45:59 0 [Note] InnoDB: Creating foreign key constraint system tables.
2020-10-13  8:45:59 0 [Note] InnoDB: Creating tablespace and datafile system tables.
2020-10-13  8:45:59 0 [Note] InnoDB: Creating sys_virtual system tables.
2020-10-13  8:45:59 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-10-13  8:45:59 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-10-13  8:45:59 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-10-13  8:45:59 0 [Note] InnoDB: Waiting for purge to start
2020-10-13  8:45:59 0 [Note] InnoDB: 10.3.26 started; log sequence number 0; transaction id 7
OK
2020-10-13  8:46:01 0 [Note] sql/mysqld (mysqld 10.3.26-MariaDB) starting as process 2609637 ...
2020-10-13  8:46:01 0 [Note] InnoDB: Using Linux native AIO
2020-10-13  8:46:01 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-10-13  8:46:01 0 [Note] InnoDB: Uses event mutexes
2020-10-13  8:46:01 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-10-13  8:46:01 0 [Note] InnoDB: Number of pools: 1
2020-10-13  8:46:01 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-10-13  8:46:01 0 [Note] InnoDB: Initializing buffer pool, total size = 2G, instances = 8, chunk size = 128M
2020-10-13  8:46:01 0 [ERROR] InnoDB: mmap(137035776 bytes) failed; errno 12
2020-10-13  8:46:01 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2020-10-13  8:46:01 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2020-10-13  8:46:01 0 [Note] InnoDB: Starting shutdown...
double free or corruption (out)
201013  8:46:01 [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.26-MariaDB
key_buffer_size=134217728
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 = 467424 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

10.5.6 unaffected

~/repos/build-mariadb-server-10.5-noasan 
$ ulimit -v
1310720
 
~/repos/build-mariadb-server-10.5-noasan 
$  mariadblocal --memlock --innodb-buffer-pool-size=2G
mysql.user table already exists!
Run mysql_upgrade, not mysql_install_db
2020-10-13  8:42:48 0 [Note] sql/mysqld (mysqld 10.5.7-MariaDB) starting as process 2608340 ...
2020-10-13  8:42:48 0 [Note] InnoDB: Using Linux native AIO
2020-10-13  8:42:48 0 [Note] InnoDB: Uses event mutexes
2020-10-13  8:42:48 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-10-13  8:42:48 0 [Note] InnoDB: Number of pools: 1
2020-10-13  8:42:48 0 [Note] InnoDB: Using crc32 + pclmulqdq instructions
2020-10-13  8:42:48 0 [Note] mysqld: O_TMPFILE is not supported on /tmp (disabling future attempts)
2020-10-13  8:42:48 0 [Note] InnoDB: Initializing buffer pool, total size = 2147483648, chunk size = 134217728
2020-10-13  8:42:48 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2020-10-13  8:42:48 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2020-10-13  8:42:48 0 [Note] InnoDB: Starting shutdown...
2020-10-13  8:42:48 0 [ERROR] Plugin 'InnoDB' init function returned error.
2020-10-13  8:42:48 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2020-10-13  8:42:48 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-10-13  8:42:48 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2020-10-13  8:42:48 0 [ERROR] Aborting

Comment by Daniel Black [ 2020-10-12 ]

10.3 backtrace

(gdb) bt full
#0  __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
        set = {__val = {552967, 35153230, 140737488341360, 0, 140737488341280, 1, 0, 0, 0, 0, 549755813888, 0, 0, 0, 513, 140737345887437}}
        pid = <optimized out>
        tid = <optimized out>
        ret = <optimized out>
#1  0x00007ffff751a895 in __GI_abort () at abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x1411540 <innodb_init_params()::current_dir>, sa_sigaction = 0x1411540 <innodb_init_params()::current_dir>}, sa_mask = {__val = {
              10330862, 30, 10330862, 4, 11532126, 140737488341800, 10330862, 2, 9223372036854775822, 0, 0, 0, 0, 0, 0, 0}}, sa_flags = 10330862, sa_restorer = 0x0}
        sigs = {__val = {32, 0 <repeats 15 times>}}
#2  0x00007ffff7575857 in __libc_message (action=action@entry=do_abort, fmt=fmt@entry=0x7ffff7686e1d "%s\n") at ../sysdeps/posix/libc_fatal.c:155
        ap = {{gp_offset = 24, fp_offset = 32767, overflow_arg_area = 0x7fffffffcc80, reg_save_area = 0x7fffffffcc10}}
        fd = <optimized out>
        list = <optimized out>
        nlist = <optimized out>
        cp = <optimized out>
#3  0x00007ffff757cd7c in malloc_printerr (str=str@entry=0x7ffff76891a0 "double free or corruption (out)") at malloc.c:5347
No locals.
#4  0x00007ffff757e3c0 in _int_free (av=0x7ffff76b89e0 <main_arena>, p=0x1ee49f0, have_lock=<optimized out>) at malloc.c:4314
        size = 50999472
        fb = <optimized out>
        nextchunk = 0x4f87aa0
        nextsize = <optimized out>
        nextinuse = <optimized out>
        prevsize = <optimized out>
        bck = <optimized out>
        fwd = <optimized out>
        __PRETTY_FUNCTION__ = "_int_free"
#5  0x0000000000a5aae6 in LatchCounter::~LatchCounter (this=0x1d93df8) at /home/dan/repos/mariadb-server-10.3/storage/innobase/include/sync0types.h:577
        count = 0x2
        it = 0x1ee4a00
        it = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--c
        count = <optimized out>
#6  LatchMeta<LatchCounter>::~LatchMeta (this=0x1d93dd0) at /home/dan/repos/mariadb-server-10.3/storage/innobase/include/sync0types.h:756
No locals.
#7  sync_latch_meta_destroy () at /home/dan/repos/mariadb-server-10.3/storage/innobase/sync/sync0debug.cc:1533
        it = 0x1d93dd0
        it = <optimized out>
#8  sync_check_close () at /home/dan/repos/mariadb-server-10.3/storage/innobase/sync/sync0debug.cc:1736
No locals.
#9  0x0000000000a54897 in innodb_shutdown () at /home/dan/repos/mariadb-server-10.3/storage/innobase/srv/srv0start.cc:2655
No locals.
#10 0x000000000097f9c3 in innodb_init (p=<optimized out>) at /home/dan/repos/mariadb-server-10.3/storage/innobase/handler/ha_innodb.cc:4178
        innobase_hton = <optimized out>
        count = 1
        create_new_db = false
        err = DB_SUCCESS
#11 0x00000000007fd712 in ha_initialize_handlerton (plugin=0x1cc26c8) at /home/dan/repos/mariadb-server-10.3/sql/handler.cc:549
        no_exts = {0x0}
        hton = 0x1cce7f8
#12 0x00000000006403eb in plugin_initialize (tmp_root=0x7fffffffd388, plugin=0x1cc26c8, argc=<optimized out>, argv=0x1c8b540, options_only=false) at /home/dan/repos/mariadb-server-10.3/sql/sql_plugin.cc:1433
        ret = 1
        state = 4
#13 0x00000000006400c8 in plugin_init (argc=0x13e9b58 <remaining_argc>, argv=0x1c8b540, flags=2) at /home/dan/repos/mariadb-server-10.3/sql/sql_plugin.cc:1715
        idx = 0
        hash = 0x13ec908 <plugin_hash+104>
        tmp = {name = {str = 0xe0056c "partition", length = 9}, plugin = 0x136e150 <builtin_maria_partition_plugin>, plugin_dl = 0x0, ptr_backup = 0x0, nbackups = 0, state = 4, ref_count = 0, locks_total = 0, data = 0x0, mem_root = {free = 0x0, used = 0x0, pre_alloc = 0x0, min_malloc = 0, block_size = 0, total_alloc = 0, block_num = 0, first_block_usage = 0, error_handler = 0x0, name = 0x0}, system_vars = 0x0, load_option = PLUGIN_ON}
        tmp_root = {free = 0x1d84938, used = 0x1ccc838, pre_alloc = 0x1cc3f58, min_malloc = 32, block_size = 4056, total_alloc = 69048, block_num = 10, first_block_usage = 0, error_handler = 0x0, name = 0xcc9dea "plugin_tmp"}
        MyISAM = {str = <optimized out>, length = 6}
        mandatory = <optimized out>
        reaped_mandatory_plugin = false
        i = 2
        builtins = <optimized out>
        plugin = <optimized out>
        plugin_ptr = 0x1cc26c8
        reap = 0x7fffffffd148
#14 0x0000000000585a84 in init_server_components () at /home/dan/repos/mariadb-server-10.3/sql/mysqld.cc:5423
No locals.
#15 0x00000000005817b6 in mysqld_main (argc=<optimized out>, argv=0x1c8b540) at /home/dan/repos/mariadb-server-10.3/sql/mysqld.cc:6032
        ho_error = <optimized out>
        new_thread_stack_size = <optimized out>
        please_close_stdin = <optimized out>
#16 0x00007ffff751c042 in __libc_start_main (main=0x57d850 <main(int, char**)>, argc=8, argv=0x7fffffffdae8, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffdad8) at ../csu/libc-start.c:308
        self = <optimized out>
        result = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, 9143552502133109689, 5756768, 0, 0, 0, -9143553104329362503, -9143569785095113799}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x8, 0x7fffffffdae8}, data = {prev = 0x0, cleanup = 0x0, canceltype = 8}}}
        not_first_call = <optimized out>
#17 0x000000000057d78e in _start ()
No symbol table info available.
 
(gdb) up
#5  0x0000000000a5aae6 in LatchCounter::~LatchCounter (this=0x1d93df8) at /home/dan/repos/mariadb-server-10.3/storage/innobase/include/sync0types.h:577
577				UT_DELETE(count);
(gdb) p count
$1 = (LatchCounter::Count *) 0x2
(gdb) up
#6  LatchMeta<LatchCounter>::~LatchMeta (this=0x1d93dd0) at /home/dan/repos/mariadb-server-10.3/storage/innobase/include/sync0types.h:756
756		~LatchMeta() { }
(gdb) p *this
$2 = {m_id = LATCH_ID_BUF_POOL, m_name = 0xf11028 "BUF_POOL", m_level = SYNC_BUF_POOL, m_level_name = 0xf11023 "SYNC_BUF_POOL", m_pfs_key = 0, m_counter = {m_mutex = {
      m_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
        __size = '\000' <repeats 16 times>, "\377\377\377\377", '\000' <repeats 19 times>, __align = 0}}, m_counters = std::vector of length 1, capacity 4 = {0x1ee4a00}, 
    m_active = false}}
(gdb) down
#5  0x0000000000a5aae6 in LatchCounter::~LatchCounter (this=0x1d93df8) at /home/dan/repos/mariadb-server-10.3/storage/innobase/include/sync0types.h:577
577				UT_DELETE(count);
(gdb) p *this
$3 = {m_mutex = {m_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = -1, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
      __size = '\000' <repeats 16 times>, "\377\377\377\377", '\000' <repeats 19 times>, __align = 0}}, m_counters = std::vector of length 1, capacity 4 = {0x1ee4a00}, 
  m_active = false}

Comment by Daniel Black [ 2020-10-12 ]

10.1 different crash from same cause

$ ulimit -v  1310720
 
$  mariadblocal  --lc-messages-dir=$PWD/sql/share  --memlock --innodb-buffer-pool-size=2G
 
2020-10-13  9:48:18 139789344366464 [Note] sql/mysqld (mysqld 10.1.48-MariaDB) starting as process 2657134 ...
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: The InnoDB memory heap is disabled
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: Using Linux native AIO
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: Using SSE crc32 instructions
2020-10-13  9:48:18 139789344366464 [Note] InnoDB: Initializing buffer pool, size = 2.0G
InnoDB: mmap(281018368 bytes) failed; errno 12
InnoDB: Error: Block 0x55cf49aeef28 incorrect state BUF_BLOCK_POOL_WATCH in buf_LRU_block_free_non_file_page()
201013  9:48:18 [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.1.48-MariaDB
key_buffer_size=134217728
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 = 467156 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
addr2line: 'sql/mysqld': No such file
sql/mysqld(my_print_stacktrace+0x29)[0x55cf473bfa19]
sql/mysqld(handle_fatal_signal+0x553)[0x55cf46fab2d3]
sigaction.c:0(__restore_rt)[0x7f233ebdda90]
addr2line: 'sql/mysqld': No such file
sql/mysqld(+0x8c626c)[0x55cf472f426c]
sql/mysqld(+0x8c67be)[0x55cf472f47be]
sql/mysqld(+0x8765f7)[0x55cf472a45f7]
sql/mysqld(+0x7b285d)[0x55cf471e085d]
sql/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x63)[0x55cf46fad5f3]
sql/mysqld(+0x41e128)[0x55cf46e4c128]
sql/mysqld(_Z11plugin_initPiPPci+0x8be)[0x55cf46e4d19e]
sql/mysqld(+0x379ef4)[0x55cf46da7ef4]
sql/mysqld(_Z11mysqld_mainiPPc+0x400)[0x55cf46dad500]
csu/libc-start.c:308(__libc_start_main)[0x7f233e4e8042]
addr2line: 'sql/mysqld': No such file
sql/mysqld(_start+0x2e)[0x55cf46da19de]
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.
 
The "--memlock" argument, which was enabled, uses system calls that are
unreliable and unstable on some operating systems and operating-system versions (notably, some versions of Linux).
This crash could be due to use of those buggy OS calls.
You should consider whether you really need the "--memlock" parameter and/or consult the OS distributer about "mlockall" bugs.
Segmentation fault (core dumped)

10.1 backtrace (segfault at different location(

$ coredumpctl debug
           PID: 2657134 (mysqld)
           UID: 1000 (dan)
           GID: 1000 (dan)
        Signal: 11 (SEGV)
     Timestamp: Tue 2020-10-13 09:48:18 AEDT (4min 21s ago)
  Command Line: sql/mysqld --no-defaults --skip-networking --datadir=/tmp/build-mariadb-server-10.1-datadir --socket=/tmp/build-mariadb-server-10.1.sock --verbose --lc-messages-dir=/home/dan/repos/build-mariadb-server-10.1/sql/share --memlock --innodb-buffer-pool-size=2G
    Executable: /home/dan/repos/build-mariadb-server-10.1/sql/mysqld
 Control Group: /user.slice/user-1000.slice/user@1000.service/apps.slice/apps-org.gnome.Terminal.slice/vte-spawn-c7eaff66-bf48-4748-b319-ccb7615731da.scope
          Unit: user@1000.service
     User Unit: vte-spawn-c7eaff66-bf48-4748-b319-ccb7615731da.scope
         Slice: user-1000.slice
     Owner UID: 1000 (dan)
       Boot ID: 4342e06b10cf4901aaf77de12449688a
    Machine ID: f92b0c4cdca64582a4d2b3171560f8ae
      Hostname: linux.fritz.box
       Storage: /var/lib/systemd/coredump/core.mysqld.1000.4342e06b10cf4901aaf77de12449688a.2657134.1602542898000000.lz4
       Message: Process 2657134 (mysqld) of user 1000 dumped core.
                
                Stack trace of thread 2657134:
                #0  0x00007f233e4fddbb kill (libc.so.6 + 0x3cdbb)
                #1  0x000055cf46fab1aa n/a (/home/dan/repos/build-mariadb-server-10.1/sql/mysqld + 0x57d1aa)
 
GNU gdb (GDB) Fedora 9.1-6.fc32
Copyright (C) 2020 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.
 
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /home/dan/repos/build-mariadb-server-10.1/sql/mysqld...
[New LWP 2657134]
[New LWP 2657135]
[New LWP 2657136]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Core was generated by `sql/mysqld --no-defaults --skip-networking --datadir=/tmp/build-mariadb-server-'.
Program terminated with signal SIGSEGV, Segmentation fault.
 
(gdb) bt full
#0  0x00007f233e4fddbb in kill () at ../sysdeps/unix/syscall-template.S:120
No locals.
#1  0x000055cf46fab1aa in handle_fatal_signal (sig=11) at /home/dan/repos/mariadb-server-10.1/sql/signal_handler.cc:308
        curr_time = 1602542898
        tm = {tm_sec = 18, tm_min = 48, tm_hour = 9, tm_mday = 13, tm_mon = 9, tm_year = 120, tm_wday = 2, tm_yday = 286, tm_isdst = 1, tm_gmtoff = 39600, 
          tm_zone = 0x55cf49624a90 "AEDT"}
        thd = <optimized out>
        print_invalid_query_pointer = <optimized out>
#2  <signal handler called>
No locals.
#3  mem_heap_free_func (file_name=<optimized out>, line=<optimized out>, heap=<optimized out>) at /home/dan/repos/mariadb-server-10.1/storage/xtradb/include/mem0mem.ic:574
        block = <optimized out>
        prev_block = <optimized out>
        block = <optimized out>
        prev_block = <optimized out>
#4  mem_free_func (line=1765, file_name=0x55cf47501780 "/home/dan/repos/mariadb-server-10.1/storage/xtradb/buf/buf0buf.cc", ptr=0x0)
    at /home/dan/repos/mariadb-server-10.1/storage/xtradb/include/mem0mem.ic:576
        heap = <optimized out>
#5  buf_pool_free_instance (buf_pool=0x55cf498fbd38) at /home/dan/repos/mariadb-server-10.1/storage/xtradb/buf/buf0buf.cc:1765
        chunk = <optimized out>
        chunks = <optimized out>
        bpage = 0x0
        i = <optimized out>
        chunk = <optimized out>
        chunks = <optimized out>
        bpage = <optimized out>
        i = <optimized out>
        prev_bpage = <optimized out>
        state = <optimized out>
        block = <optimized out>
        i = <optimized out>
        slot = <optimized out>
--Type <RET> for more, q to quit, c to continue without paging--c
#6  buf_pool_free (n_instances=n_instances@entry=3) at /home/dan/repos/mariadb-server-10.1/storage/xtradb/buf/buf0buf.cc:1900
        i = 2
#7  0x000055cf472f47be in buf_pool_init (total_size=<optimized out>, populate=<optimized out>, n_instances=8) at /home/dan/repos/mariadb-server-10.1/storage/xtradb/buf/buf0buf.cc:1862
        ptr = <optimized out>
        i = 3
        size = 268435456
#8  0x000055cf472a45f7 in innobase_start_or_create_for_mysql () at /home/dan/repos/mariadb-server-10.1/storage/xtradb/srv/srv0start.cc:2191
        create_new_db = 255
        flushed_lsn = 18446744073709551615
        min_arch_log_no = 18446744073709551615
        max_arch_log_no = 18446744073709551615
        sum_of_new_sizes = 18446744073709551615
        err = <optimized out>
        i = <optimized out>
        srv_n_log_files_found = 2
        io_limit = 256
        mtr = {memo = {heap = 0xffffffffffffffff, used = 18446744073709551615, data = '\377' <repeats 512 times>, base = {count = 18446744073709551615, start = 0xffffffffffffffff, end = 0xffffffffffffffff}, list = {prev = 0xffffffffffffffff, next = 0xffffffffffffffff}}, log = {heap = 0xffffffffffffffff, used = 18446744073709551615, data = '\377' <repeats 512 times>, base = {count = 18446744073709551615, start = 0xffffffffffffffff, end = 0xffffffffffffffff}, list = {prev = 0xffffffffffffffff, next = 0xffffffffffffffff}}, inside_ibuf = 1, modifications = 1, made_dirty = 1, n_log_recs = 18446744073709551615, n_freed_pages = 18446744073709551615, log_mode = 18446744073709551615, start_lsn = 18446744073709551615, end_lsn = 18446744073709551615}
        ib_bh = <optimized out>
        n_recovered_trx = <optimized out>
        logfilename = '\377' <repeats 1392 times>...
        logfile0 = 0x0
        dirnamelen = <optimized out>
        sys_datafiles_created = false
        size = <optimized out>
        unit = <optimized out>
#9  0x000055cf471e085d in innobase_init (p=<optimized out>) at /home/dan/repos/mariadb-server-10.1/storage/xtradb/handler/ha_innodb.cc:4528
        current_dir = "./"
        err = <optimized out>
        ret = <optimized out>
        default_path = <optimized out>
        format_id = <optimized out>
        num_pll_degree = <optimized out>
        innobase_hton = <optimized out>
        count = 1
#10 0x000055cf46fad5f3 in ha_initialize_handlerton (plugin=0x55cf49669ee8) at /home/dan/repos/mariadb-server-10.1/sql/handler.cc:556
        hton = 0x55cf49674018
        no_exts = {0x0}
#11 0x000055cf46e4c128 in plugin_initialize (tmp_root=tmp_root@entry=0x7ffc1724c4c0, plugin=plugin@entry=0x55cf49669ee8, argc=argc@entry=0x55cf47a2d778 <remaining_argc>, argv=argv@entry=0x55cf49621f20, options_only=options_only@entry=false) at /home/dan/repos/mariadb-server-10.1/sql/sql_plugin.cc:1410
        ret = 1
        state = <optimized out>
#12 0x000055cf46e4d19e in plugin_init (argc=argc@entry=0x55cf47a2d778 <remaining_argc>, argv=0x55cf49621f20, flags=2) at /home/dan/repos/mariadb-server-10.1/sql/sql_plugin.cc:1687
        idx = 10
        hash = 0x55cf47a2f8a8 <plugin_hash+104>
        i = 2
        builtins = <optimized out>
        plugin = <optimized out>
        tmp = {name = {str = 0x55cf477a5845 "partition", length = 9}, plugin = 0x55cf479b6f40 <builtin_maria_partition_plugin>, plugin_dl = 0x0, ptr_backup = 0x0, nbackups = 0, state = 4, ref_count = 0, locks_total = 0, data = 0x0, mem_root = {free = 0x0, used = 0x0, pre_alloc = 0x0, min_malloc = 0, block_size = 0, block_num = 0, first_block_usage = 0, error_handler = 0x0}, system_vars = 0x0, load_option = PLUGIN_ON}
        plugin_ptr = 0x55cf49669ee8
        reap = 0x7ffc1724c268
        tmp_root = {free = 0x55cf4972db38, used = 0x55cf4972bb78, pre_alloc = 0x55cf4966b738, min_malloc = 32, block_size = 4056, block_num = 10, first_block_usage = 0, error_handler = 0x0}
        reaped_mandatory_plugin = false
        mandatory = <optimized out>
        MyISAM = <optimized out>
#13 0x000055cf46da7ef4 in init_server_components () at /home/dan/repos/mariadb-server-10.1/sql/mysqld.cc:5207
No locals.
#14 0x000055cf46dad500 in mysqld_main (argc=<optimized out>, argv=<optimized out>) at /home/dan/repos/mariadb-server-10.1/sql/mysqld.cc:5802
        please_close_stdin = true
        ho_error = <optimized out>
        new_thread_stack_size = <optimized out>
#15 0x00007f233e4e8042 in __libc_start_main (main=0x55cf46d91230 <main(int, char**)>, argc=9, argv=0x7ffc1724cd28, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7ffc1724cd18) at ../csu/libc-start.c:308
        self = <optimized out>
        result = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {0, -3015674589909597267, 94348735289776, 0, 0, 0, -9061089358338833491, -8935465015481580627}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x9, 0x7ffc1724cd28}, data = {prev = 0x0, cleanup = 0x0, canceltype = 9}}}
        not_first_call = <optimized out>
#16 0x000055cf46da19de in _start () at /home/dan/repos/mariadb-server-10.1/sql/sql_list.h:195
No symbol table info available.

Comment by Daniel Black [ 2020-10-13 ]

FYI, I'm working on the 10.1-xtradb one.
buf_LRU_block_free_non_file_page - why allocating a frame in the middle of a deallocation?

Comment by Leon Heess [ 2020-10-13 ]

Maybe relevant: I have 1GB RAM on this VM

Comment by Daniel Black [ 2020-10-13 ]

leonheess I can't solve your lack of RAM problem. In your 1G you have other things running. Look through the settings of everything running and see if they can be minimized, moved to a different VM, or just get a bigger VM. Choices are yours.

In this issue I'm only going to fix the shutting down to make mariadb not abort/double-free when there is insufficient RAM to start.

Comment by Daniel Black [ 2023-09-19 ]

retested, appears to have been corrected at some stage

10.4 8bbe3a3cd2bac614bcbfcf733249d6d37e911a58

$  mariadblocal  --memlock --innodb-buffer-pool-size=2G
Installing MariaDB/MySQL system tables in '/tmp/build-mariadb-server-10.4-datadir' ...
2023-09-19 13:20:04 0 [Note] Starting MariaDB 10.4.32-MariaDB source revision 8bbe3a3cd2bac614bcbfcf733249d6d37e911a58 as process 219210
2023-09-19 13:20:04 0 [Note] InnoDB: Using Linux native AIO
2023-09-19 13:20:04 0 [Note] InnoDB: The first innodb_system data file 'ibdata1' did not exist. A new tablespace will be created!
2023-09-19 13:20:04 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-09-19 13:20:04 0 [Note] InnoDB: Uses event mutexes
2023-09-19 13:20:04 0 [Note] InnoDB: Compressed tables use zlib 1.2.13
2023-09-19 13:20:04 0 [Note] InnoDB: Number of pools: 1
2023-09-19 13:20:04 0 [Note] InnoDB: Using SSE2 crc32 instructions
2023-09-19 13:20:04 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2023-09-19 13:20:04 0 [Note] InnoDB: Completed initialization of buffer pool
2023-09-19 13:20:04 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2023-09-19 13:20:04 0 [Note] InnoDB: Setting file './ibdata1' size to 12 MB. Physically writing the file full; Please wait ...
2023-09-19 13:20:04 0 [Note] InnoDB: File './ibdata1' size is now 12 MB.
2023-09-19 13:20:04 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 50331648 bytes
2023-09-19 13:20:04 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 50331648 bytes
2023-09-19 13:20:04 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0
2023-09-19 13:20:04 0 [Note] InnoDB: New log files created, LSN=11451
2023-09-19 13:20:04 0 [Note] InnoDB: Doublewrite buffer not found: creating new
2023-09-19 13:20:04 0 [Note] InnoDB: Doublewrite buffer created
2023-09-19 13:20:04 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2023-09-19 13:20:04 0 [Note] InnoDB: Creating foreign key constraint system tables.
2023-09-19 13:20:04 0 [Note] InnoDB: Creating tablespace and datafile system tables.
2023-09-19 13:20:04 0 [Note] InnoDB: Creating sys_virtual system tables.
2023-09-19 13:20:04 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2023-09-19 13:20:04 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2023-09-19 13:20:04 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2023-09-19 13:20:04 0 [Note] InnoDB: Waiting for purge to start
2023-09-19 13:20:04 0 [Note] InnoDB: 10.4.32 started; log sequence number 0; transaction id 7
OK
2023-09-19 13:20:06 0 [Note] Starting MariaDB 10.4.32-MariaDB source revision 8bbe3a3cd2bac614bcbfcf733249d6d37e911a58 as process 219242
2023-09-19 13:20:06 0 [Note] InnoDB: Using Linux native AIO
2023-09-19 13:20:06 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2023-09-19 13:20:06 0 [Note] InnoDB: Uses event mutexes
2023-09-19 13:20:06 0 [Note] InnoDB: Compressed tables use zlib 1.2.13
2023-09-19 13:20:06 0 [Note] InnoDB: Number of pools: 1
2023-09-19 13:20:06 0 [Note] InnoDB: Using SSE2 crc32 instructions
2023-09-19 13:20:06 0 [Note] InnoDB: Initializing buffer pool, total size = 2G, instances = 8, chunk size = 128M
2023-09-19 13:20:06 0 [ERROR] InnoDB: mmap(134217728 bytes) failed; errno 12
2023-09-19 13:20:06 0 [ERROR] InnoDB: Cannot allocate memory for the buffer pool
2023-09-19 13:20:06 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error
2023-09-19 13:20:06 0 [Note] InnoDB: Starting shutdown...
2023-09-19 13:20:06 0 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
2023-09-19 13:20:06 0 [Note] Plugin 'FEEDBACK' is disabled.
2023-09-19 13:20:06 0 [ERROR] Unknown/unsupported storage engine: InnoDB
2023-09-19 13:20:06 0 [ERROR] Aborting

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