percona 5.7.18-16 crash (btr_insert_on_non_leaf_level_funcm)

[Alexey Manikin]

We use Percona on more than 300 servers. We have the latest version of 5.7.18-16

Crach report:

2017-08-16 19:17:49 0x7ff112dfb700 InnoDB: Assertion failure in thread 140673380497152 in file btr0btr.cc line 2196
InnoDB: Failing assertion: err == DB_SUCCESS
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
16:17:49 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=6428192768
read_buffer_size=5406720
max_used_connections=64
max_threads=310
thread_count=12
connection_count=12
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 10242011 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7ff00891b180 db: ibraal_magas
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 = 7ff112dfae40 thread_stack 0x200000
/usr/bin/mysqld(my_print_stacktrace+0x2c)[0xe619cc]
/usr/bin/mysqld(handle_fatal_signal+0x31d)[0x78186d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7ffb57fc8340]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x39)[0x7ffb5630ff79]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7ffb56313388]
/usr/bin/mysqld[0x75642f]
/usr/bin/mysqld(_Z33btr_insert_on_non_leaf_level_funcmP12dict_index_tmP8dtuple_tPKcmP5mtr_t+0x2e5)[0x104cb35]
/usr/bin/mysqld(_Z25btr_page_split_and_insertmP9btr_cur_tPPmPP16mem_block_info_tPK8dtuple_tmP5mtr_t+0xe81)[0x104f6e1]
/usr/bin/mysqld(_Z26btr_cur_pessimistic_insertmP9btr_cur_tPPmPP16mem_block_info_tP8dtuple_tPPhPP9big_rec_tmP9que_thr_tP5mtr_t+0x1cf)[0x105cabf]
/usr/bin/mysqld[0xf78833]
/usr/bin/mysqld[0xf938f1]
/usr/bin/mysqld(_ZN11ha_innobase25intrinsic_table_write_rowEPh+0x3d)[0xe9e8ed]
/usr/bin/mysqld(_ZN11ha_innobase9write_rowEPh+0x275)[0xea7755]
/usr/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x174)[0x7e70c4]
/usr/bin/mysqld[0xc0d3c1]
/usr/bin/mysqld[0xc0984a]
/usr/bin/mysqld(_Z10sub_selectP4JOINP7QEP_TABb+0x170)[0xc0ef00]
/usr/bin/mysqld[0xc0984a]
/usr/bin/mysqld(_Z10sub_selectP4JOINP7QEP_TABb+0x170)[0xc0ef00]
/usr/bin/mysqld[0xc0984a]
/usr/bin/mysqld(_Z10sub_selectP4JOINP7QEP_TABb+0x170)[0xc0ef00]
/usr/bin/mysqld(_ZN4JOIN4execEv+0x370)[0xc07b10]
/usr/bin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x233)[0xc78b93]
/usr/bin/mysqld[0x74a9e1]
/usr/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x4385)[0xc3a6b5]
/usr/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x645)[0xc3e155]
/usr/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x101b)[0xc3f1cb]
/usr/bin/mysqld(_Z10do_commandP3THD+0x1b7)[0xc405c7]
/usr/bin/mysqld(handle_connection+0x2a0)[0xd02b60]
/usr/bin/mysqld(pfs_spawn_thread+0x1b4)[0x1192024]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7ffb57fc0182]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7ffb563d430d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7ff0089b0580): SELECT p.*, u.nickname as author, u.login, u.is_deleted, b.allow_who as blog_allow_who, b.seolink as bloglink, b.title as blog_title, b.owner as owner FROM cms_blog_posts p INNER JOIN cms_blogs b ON b.id = p.blog_id LEFT JOIN cms_users u ON u.id = p.user_id WHERE p.published = 1 AND b.owner = 'user' AND (b.allow_who = 'all') AND (p.allow_who = 'all') ORDER BY p.pubdate DESC LIMIT 0, 50
Connection ID (thread ID): 1719077
Status: NOT_KILLED

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.

MySQL configuration:

################################################################################
# Main config
################################################################################
[mysqld]

################################################################################
# Common
################################################################################

# wait timeout (drop long sleeping clients)
interactive_timeout = 30
wait_timeout = 30

# system setting
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
basedir = /usr
datadir = /home/mysql
tmpdir = /home/tmpfs

# bind settings
# see conf.d

# external locking for myisam tables
skip_external_locking = ON
delay_key_write = ON

# default character set
character-set-server = UTF8
collation-server = utf8_general_ci

# threads settings
thread_stack = 2048K
thread_cache_size = 68

# extra connections
extra_port = 3308
extra_max_connections = 10

# connections
max_user_connections = 50
max_connections = 300
back_log = 20000

# beget cgroups

# per-connections buffers
# (join_buffer_size + read_buffer_size + sort_buffer_size + read_rnd_buffer_size) * max_connections
# (2703491 + 5406982 + 8110473 + 8110473) * 300 = 7299425700
join_buffer_size = 2703491
read_buffer_size = 5406982
read_rnd_buffer_size = 8110473
sort_buffer_size = 8110473

# disable query cache
# (due to global mutex we may have degraded performance in high concurrence environment)
query_cache_type = 2
query_cache_size = 50000000
query_cache_limit = 1048576
query_cache_strip_comments = 1
query_cache_min_res_unit = 4096

# max blob size
max_allowed_packet = 33554432
group_concat_max_len = 1024

# sql mode (bitrix requirement)
sql_mode =

# tmp tables
tmp_table_size = 8110473216
max_heap_table_size = 8110473216

# max errors before kick client out
max_connect_errors = 65000
max_error_count = 65000

# open files limit (maximum possible)
open_files_limit = 1048576

# open table cache
table_open_cache = 50000
table_definition_cache = 50000
table_open_cache_instances = 50

# disable auto flush by default (do it manually by cron)
flush_time = 0

# general log settings
log_error = /var/log/mysql/error.log
log_warnings = 2

# slow log settings
slow_query_log = ON
slow_query_log_file = /var/log/mysql/slow.log
long_query_time = 2

# low priority updates
low_priority_updates = ON

# metadata locks
metadata_locks_hash_instances = 28

# insert buffer
bulk_insert_buffer_size = 16M

# delayed insert
delayed_insert_limit = 1
max_delayed_threads = 0

#max search depth for query optimizer
optimizer_search_depth = 62

# performance schema
performance_schema = OFF

# enable percona userstat feature
userstat = ON

# preload buffer
preload_buffer_size = 65535

# query alloc size
query_alloc_block_size = 16384
query_prealloc_size = 16384

# transactions alloc size
transaction_alloc_block_size = 16384
transaction_prealloc_size = 16384

# transaction isolation level
transaction-isolation = READ-COMMITTED

# case sensitivity
lower_case_table_names = 0

################################################################################
# MyISAM
################################################################################

# recover type
myisam_recover_options = BACKUP

# recovery buffer
myisam_sort_buffer_size = 512M

# key buffer
key_buffer_size = 6428193587

#fulltext
ft_min_word_len = 4

################################################################################
# InnoDB
################################################################################

# separate tablespace
innodb_file_per_table = ON

# file format
innodb_file_format = 'Barracuda'

# log files
innodb_log_file_size = 256M
innodb_log_files_in_group = 4

# open files
innodb_open_files = 50000

# innodb threads
innodb_thread_concurrency = 40
innodb_adaptive_max_sleep_delay = 10000
innodb_concurrency_tickets = 5000
innodb_read_io_threads = 8
innodb_write_io_threads = 16
innodb_purge_threads = 16
innodb_sync_array_size = 64
innodb_lock_wait_timeout = 50

# I/O optimization
innodb_random_read_ahead = ON
innodb_read_ahead_threshold = 32
innodb_flush_log_at_trx_commit = 2
innodb_flush_method = O_DIRECT

# buffer pools
innodb_buffer_pool_instances = 64
innodb_buffer_pool_size = 27034910720
innodb_log_buffer_size = 256M
innodb_sort_buffer_size = 64M

# preload buffer pool
innodb_buffer_pool_load_at_startup = ON
innodb_buffer_pool_dump_at_shutdown = ON

# percona specific feature
innodb_corrupt_table_action = warn
innodb_kill_idle_transaction = 30

# innodb fulltext
innodb_ft_enable_stopword = ON
innodb_ft_min_token_size = 3
innodb_ft_max_token_size = 84

# innodb large prefix
innodb_large_prefix = 1

# interval between successive column values
auto-increment-increment = 1
auto-increment-offset = 1

# innodb strict mode
innodb_strict_mode = 0

# innodb old block sublist
innodb_old_blocks_pct = 30

# innodb temp data file
innodb_temp_data_file_path = ibtmp1:104857600:autoextend:max:8589934592

# innodb numa policy
innodb_numa_interleave = 0

################################################################################
# client settings
################################################################################

[mysqldump]
quick
quote-names
max_allowed_packet = 32M

[mysql]

[isamchk]
key_buffer = 32M

[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock

[mysqld_safe]
socket = /var/run/mysqld/mysqld.sock
nice = 0

[Sveta Smirnova (svetasmirnova)]

Thank you for the report.

Could you please check if crash is always repeatable if you run

SELECT p.*, u.nickname as author, u.login, u.is_deleted, b.allow_who as blog_allow_who, b.seolink as bloglink, b.title as blog_title, b.owner as owner FROM cms_blog_posts p INNER JOIN cms_blogs b ON b.id = p.blog_id LEFT JOIN cms_users u ON u.id = p.user_id WHERE p.published = 1 AND b.owner = 'user' AND (b.allow_who = 'all') AND (p.allow_who = 'all') ORDER BY p.pubdate DESC LIMIT 0, 50

[Alexey Manikin (alexey-x)]

Greetings.

Unfortunately, no, this issue doesn't come up regularly, for every 100 servers it happens only a couple of times a day. Out of the last failures i assume that:

```
2017-10-05T08:28:42.999856Z 700710 [ERROR] /usr/bin/mysqld: The table '/home/tmpfs/#sql_7_8' is full
2017-10-05 11:28:43 0x7f98bb9fc700 InnoDB: Assertion failure in thread 140293959567104 in file btr0btr.cc line 2196
InnoDB: Failing assertion: err == DB_SUCCESS
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
08:28:43 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=1349390336
read_buffer_size=1347584
max_used_connections=108
max_threads=170
thread_count=22
connection_count=22
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1814054 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f976e9f5c80 db: lexavotb_inst1
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 = 7f98bb9fbe40 thread_stack 0x200000
/usr/bin/mysqld(my_print_stacktrace+0x2c)[0xe6778c]
/usr/bin/mysqld(handle_fatal_signal+0x31d)[0x78269d]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f9ba5b7e340]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x39)[0x7f9ba3ec5f79]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f9ba3ec9388]
/usr/bin/mysqld[0x757263]
/usr/bin/mysqld(_Z33btr_insert_on_non_leaf_level_funcmP12dict_index_tmP8dtuple_tPKcmP5mtr_t+0x2e5)[0x1053d35]
/usr/bin/mysqld(_Z25btr_page_split_and_insertmP9btr_cur_tPPmPP16mem_block_info_tPK8dtuple_tmP5mtr_t+0xe81)[0x10568e1]
/usr/bin/mysqld(_Z26btr_cur_pessimistic_insertmP9btr_cur_tPPmPP16mem_block_info_tP8dtuple_tPPhPP9big_rec_tmP9que_thr_tP5mtr_t+0x1cf)[0x1063cbf]
/usr/bin/mysqld(_Z29row_ins_clust_index_entry_lowmmP12dict_index_tmP8dtuple_tmP9que_thr_tb+0xbbf)[0xf7f12f]
/usr/bin/mysqld(_Z25row_ins_clust_index_entryP12dict_index_tP8dtuple_tP9que_thr_tmb+0x195)[0xf83c45]
/usr/bin/mysqld[0xf99e11]
/usr/bin/mysqld(_ZN11ha_innobase25intrinsic_table_write_rowEPh+0x3d)[0xea48fd]
/usr/bin/mysqld(_ZN11ha_innobase9write_rowEPh+0x275)[0xead885]
/usr/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x174)[0x7e7f54]
/usr/bin/mysqld[0xc10911]
/usr/bin/mysqld(_ZN10JOIN_CACHE24generate_full_extensionsEPh+0x8e)[0xdb...

[Launchpad Janitor (janitor)]

[Expired for Percona Server because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3732