handle_fatal_signal in Item_func_case::cleanup()

[Konrad Bechler]

Hello,

We're experiencing random Percona Server crashes. As this server handles 140+ databases, it's hard to identify what is causing this problem. Crashes seems to be very random. Sometimes occurs after few seconds, sometimes after many hours.

My OS is CentOS 6, kernel 2.6.32-696.10.3.el6.x86_64, glibc 2.12-1.149.el6_6.5.

It crashes with such logs:
17:59:29 UTC - 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.
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=67108864
read_buffer_size=131072
max_used_connections=77
max_threads=151
thread_count=42
connection_count=42
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 125262 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7f55983154a0
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 = 7f56d81f0d40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xed355c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7a15c1]
/lib64/libpthread.so.0(+0xf710)[0x7f5715c23710]
/usr/sbin/mysqld(_ZN14Item_func_case7cleanupEv+0x21)[0x830711]
/usr/sbin/mysqld(_Z13cleanup_itemsP4Item+0x21)[0xca80b1]
/usr/sbin/mysqld(_ZN5TABLE16cleanup_gc_itemsEv+0x34)[0xd524d4]
/usr/sbin/mysqld(_Z19close_thread_tablesP3THD+0x5f)[0xc4eeef]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x687)[0xcaaf47]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x5d5)[0xcb2305]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xaba)[0xcb2e4a]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b7)[0xcb4897]
/usr/sbin/mysqld(handle_connection+0x2a0)[0xd79660]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xef0464]
/lib64/libpthread.so.0(+0x79d1)[0x7f5715c1b9d1]
/lib64/libc.so.6(clone+0x6d)[0x7f5713f148fd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f55983d7aa0): is an invalid pointer
Connection ID (thread ID): 185464
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.

Here's my my.cnf:
[mysqld]
pid-file=/var/run/mysqld/mysqld.pid
log-error=/var/log/mysqld.log
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
skip-name-resolve
symbolic-links=0
ignore-db-dir = lost+found
slow_query_log = 1
slow_query_log_file = /var/log/mysql/mysqld-slow.log
userstat = 1
wait_timeout = 7200
interactive_timeout = 7200
query_cache_limit = 64MB
max_heap_table_size = 64MB
key_buffer_size = 64MB
max_heap_table_size = 128MB
key_buffer_size = 128MB
query_cache_limit = 128MB
log_warnings = 2
tmp_table_size = 64MB
max_connections = 250
max_allowed_packet = 16M
max_connections = 150
max_heap_table_size = 64MB
key_buffer_size = 64MB
long_query_time = 10
[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

mysqlchech --all-databases took a while, but showed no errors.

The exact version of Percona: 5.7.18-14-log

Regards,
Konrad

[Roel Van de Paar (roel11)]

I checked the error log excerpt against known bug strings, nothing there.

[Roel Van de Paar (roel11)]

Demangled stack

/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xed355c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7a15c1]
/lib64/libpthread.so.0(+0xf710)[0x7f5715c23710]
/usr/sbin/mysqld(Item_func_case::cleanup()+0x21)[0x830711]
/usr/sbin/mysqld(cleanup_items(Item*)+0x21)[0xca80b1]
/usr/sbin/mysqld(TABLE::cleanup_gc_items()+0x34)[0xd524d4]
/usr/sbin/mysqld(close_thread_tables(THD*)+0x5f)[0xc4eeef]
/usr/sbin/mysqld(mysql_execute_command(THD*, bool)+0x687)[0xcaaf47]
/usr/sbin/mysqld(mysql_parse(THD*, Parser_state*)+0x5d5)[0xcb2305]
/usr/sbin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0xaba)[0xcb2e4a]
/usr/sbin/mysqld(do_command(THD*)+0x1b7)[0xcb4897]
/usr/sbin/mysqld(handle_connection+0x2a0)[0xd79660]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xef0464]
/lib64/libpthread.so.0(+0x79d1)[0x7f5715c1b9d1]
/lib64/libc.so.6(clone+0x6d)[0x7f5713f148fd]

[Roel Van de Paar (roel11)]

Text string; ZN14Item_func_case7cleanupEv

[Roel Van de Paar (roel11)]

Konrad, are all the crashes the same (please compare the stacks in the error log)? Could you upload a coredump + mysqld binary + ldd files (see; https://www.percona.com/blog/2015/08/17/mysql-is-crashing-a-support-engineers-point-of-view/ for more information)?

[Konrad Bechler (kbechler)]

Hello,

Looks that they're identical. Threat pointer is different of course, but rest of stacktrace is the same. Here's another one:

20:02:41 UTC - mysqld got signal 11 ;
[...]
key_buffer_size=67108864
read_buffer_size=131072
max_used_connections=75
max_threads=151
thread_count=40
connection_count=40
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 125262 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7fab54073770
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 = 7fac2858dd40 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0xed355c]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7a15c1]
/lib64/libpthread.so.0(+0xf710)[0x7fac4b28d710]
/usr/sbin/mysqld(_ZN14Item_func_case7cleanupEv+0x21)[0x830711]
/usr/sbin/mysqld(_Z13cleanup_itemsP4Item+0x21)[0xca80b1]
/usr/sbin/mysqld(_ZN5TABLE16cleanup_gc_itemsEv+0x34)[0xd524d4]
/usr/sbin/mysqld(_Z19close_thread_tablesP3THD+0x5f)[0xc4eeef]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x687)[0xcaaf47]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x5d5)[0xcb2305]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xaba)[0xcb2e4a]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x1b7)[0xcb4897]
/usr/sbin/mysqld(handle_connection+0x2a0)[0xd79660]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0xef0464]
/lib64/libpthread.so.0(+0x79d1)[0x7fac4b2859d1]
/lib64/libc.so.6(clone+0x6d)[0x7fac4957e8fd]

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

coredumps were not enabled. the are now, but have to wait for another crash.

Please find attached tgz with mysqld binary and libraries it links to.

Regards,
Konrad

[Konrad Bechler (kbechler)]

gdb_*.txt from last crash attached

[Roel Van de Paar (roel11)]

Thank you. Not much I can see yet from the stacks. Some other threads busy. Would be interesting to see if you can get the running queries out. Ref https://www.percona.com/blog/2013/11/11/how-to-extract-all-running-queries-including-the-last-executed-statement-from-a-core-file/

[Konrad Bechler (kbechler)]

Have some problems with collecting running queries.

Here a dump of my console (after "gdb `which mysqld` ./core.32320"):
(gdb) thread 1
[Switching to thread 1 (Thread 0x7f3e6fa59700 (LWP 1174))]#0 0x00007f3e8a8088ac in pthread_kill () from /lib64/libpthread.so.0
(gdb) print do_command::thd->query_string.string.str
A syntax error in expression, near `::thd->query_string.string.str'.

As I'm not familiar with gdb, please advise what I'm doing wrong.

[Sveta Smirnova (svetasmirnova)]

Thank you for the feedback.

Which version of gdb are you using?

I also noticed crash happens in cleanup_gc_items which cleans resources, associated with generated columns. Do you have many tables with generated columns? If not much, could you please check for queries which can use them?

[Sveta Smirnova (svetasmirnova)]

There are no generated columns in 5.5 and 5.6, so this is 5.7-only

[Shahriyar Rzayev (rzayev-sehriyar)]

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