MySQL Bugs: #91956: Sig 6 : Assertion failure in ha

Bug #91956	Sig 6 : Assertion failure in ha_innodb.cc line 17420
Submitted:	10 Aug 2018 6:56	Modified:	10 Aug 2018 7:08
Reporter:	Ramesh Sivaraman	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.6.41, 5.7.23	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	debug

Description:
GDB info

#0  0x00007f2bd08019b1 in pthread_kill () from /lib64/libpthread.so.0
#1  0x0000000000aa23dd in my_write_core (sig=6) at /sda/qa/ms/ms56_dbg/mysys/stacktrace.c:424
#2  0x000000000072ef52 in handle_fatal_signal (sig=6) at /sda/qa/ms/ms56_dbg/sql/signal_handler.cc:230
#3  <signal handler called>
#4  0x00007f2bceb151f7 in raise () from /lib64/libc.so.6
#5  0x00007f2bceb168e8 in abort () from /lib64/libc.so.6
#6  0x0000000000aed92f in ib_logf (level=IB_LOG_LEVEL_FATAL, format=0xf807e0 " InnoDB: Unable to allocate memory of size %lu.\n") at /sda/qa/ms/ms56_dbg/storage/innobase/handler/ha_innodb.cc:17420
#7  0x0000000000b4aae6 in mem_heap_create_block_func (heap=0x0, n=1125899906843136, file_name=0xf7d118 "/sda/qa/ms/ms56_dbg/storage/innobase/log/log0log.cc", line=861, type=0) at /sda/qa/ms/ms56_dbg/storage/innobase/mem/mem0mem.cc:362
#8  0x0000000000b3a95a in mem_heap_create_func (n=1125899906843136, file_name=0xf7d118 "/sda/qa/ms/ms56_dbg/storage/innobase/log/log0log.cc", line=861, type=0) at /sda/qa/ms/ms56_dbg/storage/innobase/include/mem0mem.ic:449
#9  0x0000000000b3aa82 in mem_alloc_func (n=1125899906843136, file_name=0xf7d118 "/sda/qa/ms/ms56_dbg/storage/innobase/log/log0log.cc", line=861, size=0x0) at /sda/qa/ms/ms56_dbg/storage/innobase/include/mem0mem.ic:537
#10 0x0000000000b3c0d3 in log_init () at /sda/qa/ms/ms56_dbg/storage/innobase/log/log0log.cc:861
#11 0x0000000000c1766e in innobase_start_or_create_for_mysql () at /sda/qa/ms/ms56_dbg/storage/innobase/srv/srv0start.cc:2035
#12 0x0000000000ad80c9 in innobase_init (p=0x7f2bb2ff9b40) at /sda/qa/ms/ms56_dbg/storage/innobase/handler/ha_innodb.cc:3428
#13 0x000000000063feff in ha_initialize_handlerton (plugin=0x7f2bb33eee78) at /sda/qa/ms/ms56_dbg/sql/handler.cc:662
#14 0x00000000007ee0ad in plugin_initialize (plugin=0x7f2bb33eee78) at /sda/qa/ms/ms56_dbg/sql/sql_plugin.cc:1138
#15 0x00000000007eeafd in plugin_init (argc=0x1730268 <remaining_argc>, argv=0x7f2bccc1d8c0, flags=0) at /sda/qa/ms/ms56_dbg/sql/sql_plugin.cc:1432
#16 0x000000000062a137 in init_server_components () at /sda/qa/ms/ms56_dbg/sql/mysqld.cc:4907
#17 0x000000000062b039 in mysqld_main (argc=11, argv=0x7f2bccc1d8c0) at /sda/qa/ms/ms56_dbg/sql/mysqld.cc:5504
#18 0x000000000062058d in main (argc=11, argv=0x7fffe979ad98) at /sda/qa/ms/ms56_dbg/sql/main.cc:25

How to repeat:
Testcase

start mysql with  --innodb-log-buffer-size=1125899906842624.

Startup command.

/sda/qa/ms/MS090818-mysql-5.6.41-linux-x86_64-debug/bin/mysqld --no-defaults --basedir=/sda/qa/ms/MS090818-mysql-5.6.41-linux-x86_64-debug --datadir=/dev/shm/1533882737/data --tmpdir=/dev/shm/1533882737/tmp --port=36896 --pid-file=/dev/shm/1533882737/pid.pid --core-file --socket=/dev/shm/1533882737/socket.sock --innodb-log-buffer-size=1125899906842624 --log-error=/dev/shm/1533882737/error.log.out &

Hello Ramesh,

Thank you for the report and feedback!

thanks,
Umesh

I have a similar issue InnoDB crushed by try to allocate huge memory, not sure it is related, both has message "Unable to allocate memory ... in file ha_innodb.cc line 17420".

Version
MySQL-server-5.6.41-1.el7.x86_64

Crush & recovery log:

2018-08-29 22:09:52 7f5d803a8700 InnoDB: Error: page 3 log sequence number 7252937
InnoDB: is in the future! Current system log sequence number 6630232.
InnoDB: Your database may be corrupt or you may have copied the InnoDB
InnoDB: tablespace but not the InnoDB log files. See
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: for more information.
2018-08-29 22:09:52 13379 [ERROR] InnoDB:  InnoDB: Unable to allocate memory of size 18446744073709550360.

2018-08-29 22:09:52 7f5d803a8700  InnoDB: Assertion failure in thread 140039560005376 in file ha_innodb.cc line 17420
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
14:09:52 UTC - 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.
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.

key_buffer_size=402653184
read_buffer_size=1048576
max_used_connections=5
max_threads=151
thread_count=5
connection_count=5
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1786764 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x6404dc0
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 = 7f5d803a7e90 thread_stack 0x20000
mysqld(my_print_stacktrace+0x3b)[0x8ed7cb]
mysqld(handle_fatal_signal+0x491)[0x6794f1]
/lib64/libpthread.so.0(+0xf5e0)[0x7f5e2e6805e0]
/lib64/libc.so.6(gsignal+0x37)[0x7f5e2d27b1f7]
/lib64/libc.so.6(abort+0x148)[0x7f5e2d27c8e8]
mysqld[0x92aa3c]
mysqld[0x9671c7]
mysqld[0x96730c]
mysqld[0x9f194e]
mysqld[0x9f1f56]
mysqld[0x9d5b7f]
mysqld[0x9ccc1a]
mysqld[0x9245c1]
mysqld(_ZN7handler18index_read_idx_mapEPhjPKhm16ha_rkey_function+0x68)[0x5b7f48]
mysqld(_ZN7handler21ha_index_read_idx_mapEPhjPKhm16ha_rkey_function+0x9b)[0x5bc09b]
mysqld[0x6d6624]
mysqld(_Z21join_read_const_tableP13st_join_tableP11st_position+0xb7)[0x6d6737]
mysqld[0x84e271]
mysqld(_ZN4JOIN8optimizeEv+0x74c)[0x85046c]
mysqld(_Z12mysql_selectP3THDP10TABLE_LISTjR4ListI4ItemEPS4_P10SQL_I_ListI8st_orderESB_S7_yP13select_resultP18st_select_lex_unitP13st_select_lex+0x22f)[0x71c8cf]
mysqld(_Z13handle_selectP3THDP13select_resultm+0x195)[0x71d1a5]
mysqld[0x57e7a7]
mysqld(_Z21mysql_execute_commandP3THD+0x3253)[0x6f8953]
mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x378)[0x6fc028]
mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xf65)[0x6fd7a5]
mysqld(_Z24do_handle_one_connectionP3THD+0x152)[0x6ca6a2]
mysqld(handle_one_connection+0x40)[0x6ca760]
mysqld(pfs_spawn_thread+0x146)[0xb453d6]
/lib64/libpthread.so.0(+0x7e25)[0x7f5e2e678e25]
/lib64/libc.so.6(clone+0x6d)[0x7f5e2d33e34d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f5d4c0013c0): is an invalid pointer
Connection ID (thread ID): 11
Status: NOT_KILLED

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.
2018-08-29 22:09:52 15051 [Note] Plugin 'FEDERATED' is disabled.
2018-08-29 22:09:52 7fd493fdc740 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2018-08-29 22:09:52 15051 [Note] InnoDB: Using atomics to ref count buffer pool pages
2018-08-29 22:09:52 15051 [Note] InnoDB: The InnoDB memory heap is disabled
2018-08-29 22:09:52 15051 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-08-29 22:09:52 15051 [Note] InnoDB: Memory barrier is not used
2018-08-29 22:09:52 15051 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-08-29 22:09:52 15051 [Note] InnoDB: Using Linux native AIO
2018-08-29 22:09:52 15051 [Note] InnoDB: Using CPU crc32 instructions
2018-08-29 22:09:52 15051 [Note] InnoDB: Initializing buffer pool, size = 2.0G
2018-08-29 22:09:53 15051 [Note] InnoDB: Completed initialization of buffer pool
2018-08-29 22:09:53 15051 [Note] InnoDB: Highest supported file format is Barracuda.
2018-08-29 22:09:53 15051 [Note] InnoDB: The log sequence numbers 6629629 and 6629629 in ibdata files do not match the log sequence number 6630232 in the ib_logfiles!
2018-08-29 22:09:53 15051 [Note] InnoDB: Database was not shutdown normally!
2018-08-29 22:09:53 15051 [Note] InnoDB: Starting crash recovery.
2018-08-29 22:09:53 15051 [Note] InnoDB: Reading tablespace information from the .ibd files...
2018-08-29 22:09:53 15051 [Note] InnoDB: Restoring possible half-written data pages 
2018-08-29 22:09:53 15051 [Note] InnoDB: from the doublewrite buffer...
2018-08-29 22:09:53 15051 [Note] InnoDB: 128 rollback segment(s) are active.
2018-08-29 22:09:53 15051 [Note] InnoDB: Waiting for purge to start
2018-08-29 22:09:53 15051 [Note] InnoDB: 5.6.41 started; log sequence number 6630232
2018-08-29 22:09:53 15051 [Note] Server hostname (bind-address): '*'; port: 3308
2018-08-29 22:09:53 15051 [Note] IPv6 is available.
2018-08-29 22:09:53 15051 [Note]   - '::' resolves to '::';
2018-08-29 22:09:53 15051 [Note] Server socket created on IP: '::'.
2018-08-29 22:09:53 15051 [Warning] 'user' entry 'root@localhost.localdomain' ignored in --skip-name-resolve mode.
2018-08-29 22:09:53 15051 [Warning] 'proxies_priv' entry '@ root@localhost.localdomain' ignored in --skip-name-resolve mode.
2018-08-29 22:09:53 15051 [Note] Event Scheduler: Loaded 0 events
2018-08-29 22:09:53 15051 [Note] mysqld: ready for connections.

Bug #94096 marked as duplicate of this one