Percona Server moved to https://jira.percona.com/projects/PS

Assertion `(old_mh->m_key == key) || (old_mh->m_key == 0)' failed in mysys/my_malloc.c:80

Bug #1534874 reported by Ramesh Sivaraman
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.1
Invalid
Undecided
Unassigned
5.5
Invalid
Undecided
Unassigned
5.6
Invalid
Undecided
Unassigned
5.7
Fix Released
High
Laurynas Biveinis
Percona Server moved to https://jira.percona.com/projects/PS 5.7.10-2rc2

Bug Description

GDB info:

#0 0x00007f0e39bd6771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000001811888 in my_write_core (sig=6) at /sda/percona-server_dbg/mysys/stacktrace.c:247
#2 0x0000000000e60b43 in handle_fatal_signal (sig=6) at /sda/percona-server_dbg/sql/signal_handler.cc:223
#3 <signal handler called>
#4 0x00007f0e37d635d7 in raise () from /lib64/libc.so.6
#5 0x00007f0e37d64cc8 in abort () from /lib64/libc.so.6
#6 0x00007f0e37d5c546 in __assert_fail_base () from /lib64/libc.so.6
#7 0x00007f0e37d5c5f2 in __assert_fail () from /lib64/libc.so.6
#8 0x000000000180c103 in my_realloc (key=117, ptr=0x7f0dfd050110, size=128, flags=88) at /sda/percona-server_dbg/mysys/my_malloc.c:80
#9 0x000000000153965f in alloc_and_copy_thd_dynamic_variables (thd=0x7f0dfd019000, global_lock=false) at /sda/percona-server_dbg/sql/sql_plugin.cc:2870
#10 0x0000000001539969 in intern_sys_var_ptr (thd=0x7f0dfd019000, offset=72, global_lock=false) at /sda/percona-server_dbg/sql/sql_plugin.cc:2950
#11 0x000000000153a5a9 in sys_var_pluginvar::real_value_ptr (this=0x7f0e267ea108, thd=0x7f0dfd019000, type=OPT_SESSION) at /sda/percona-server_dbg/sql/sql_plugin.cc:3327
#12 0x000000000153a674 in sys_var_pluginvar::do_value_ptr (this=0x7f0e267ea108, running_thd=0x7f0dfd019000, target_thd=0x7f0dfd019000, type=OPT_SESSION, base=0x7f0e3a18a810) at /sda/percona-server_dbg/sql/sql_plugin.cc:3356
#13 0x000000000153d224 in sys_var_pluginvar::session_value_ptr (this=0x7f0e267ea108, running_thd=0x7f0dfd019000, target_thd=0x7f0dfd019000, base=0x7f0e3a18a810) at /sda/percona-server_dbg/sql/sql_plugin.cc:287
#14 0x000000000144cd06 in sys_var::value_ptr (this=0x7f0e267ea108, running_thd=0x7f0dfd019000, target_thd=0x7f0dfd019000, type=OPT_SESSION, base=0x7f0e3a18a810) at /sda/percona-server_dbg/sql/set_var.cc:276
#15 0x000000000156fbac in get_one_variable_ext (running_thd=0x7f0dfd019000, target_thd=0x7f0dfd019000, variable=0x7f0dfd084638, value_type=OPT_SESSION, show_type=SHOW_DOUBLE, status_var=0x0, charset=0x7f0e3a18ad58, buff=0x7f0e3a18a940 "ON", length=0x7f0e3a18ad48) at /sda/percona-server_dbg/sql/sql_show.cc:2824
#16 0x00000000018e2fee in System_variable::init (this=0x7f0e3a18a930, target_thd=0x7f0dfd019000, show_var=0x7f0dfd084638, query_scope=OPT_SESSION) at /sda/percona-server_dbg/storage/perfschema/pfs_variable.cc:536
#17 0x00000000018e2e4c in System_variable::System_variable (this=0x7f0e3a18a930, target_thd=0x7f0dfd019000, show_var=0x7f0dfd084638, query_scope=OPT_SESSION) at /sda/percona-server_dbg/storage/perfschema/pfs_variable.cc:502
#18 0x00000000018e2245 in PFS_system_variable_cache::do_materialize_all (this=0x7f0dfd200028, unsafe_thd=0x7f0dfd019000) at /sda/percona-server_dbg/storage/perfschema/pfs_variable.cc:230
#19 0x0000000001915a86 in PFS_variable_cache<System_variable>::materialize_all (this=0x7f0dfd200028, unsafe_thd=0x7f0dfd019000) at /sda/percona-server_dbg/storage/perfschema/pfs_variable.h:521
#20 0x000000000191549e in table_session_variables::rnd_init (this=0x7f0dfd200000, scan=true) at /sda/percona-server_dbg/storage/perfschema/table_session_variables.cc:95
#21 0x00000000018ae536 in ha_perfschema::rnd_init (this=0x7f0dfd037f30, scan=true) at /sda/percona-server_dbg/storage/perfschema/ha_perfschema.cc:315
#22 0x0000000000eefab3 in handler::ha_rnd_init (this=0x7f0dfd037f30, scan=true) at /sda/percona-server_dbg/sql/handler.cc:2948
#23 0x000000000143cc17 in init_read_record (info=0x7f0dfd1fe728, thd=0x7f0dfd019000, table=0x7f0e35c73620, qep_tab=0x7f0dfd1fe6d8, use_record_cache=1, print_error=true, disable_rr_cache=false) at /sda/percona-server_dbg/sql/records.cc:314
#24 0x00000000014c2dfd in join_init_read_record (tab=0x7f0dfd1fe6d8) at /sda/percona-server_dbg/sql/sql_executor.cc:2463
#25 0x00000000014c005a in sub_select (join=0x7f0dfd1fe030, qep_tab=0x7f0dfd1fe6d8, end_of_records=false) at /sda/percona-server_dbg/sql/sql_executor.cc:1271
#26 0x00000000014bf9ee in do_select (join=0x7f0dfd1fe030) at /sda/percona-server_dbg/sql/sql_executor.cc:944
#27 0x00000000014bd96f in JOIN::exec (this=0x7f0dfd1fe030) at /sda/percona-server_dbg/sql/sql_executor.cc:199
#28 0x000000000155955a in handle_query (thd=0x7f0dfd019000, lex=0x7f0dfd01b5d0, result=0x7f0dfd02cd68, added_options=0, removed_options=0) at /sda/percona-server_dbg/sql/sql_select.cc:184
#29 0x000000000150e357 in execute_sqlcom_select (thd=0x7f0dfd019000, all_tables=0x7f0dfd02c548) at /sda/percona-server_dbg/sql/sql_parse.cc:5347
#30 0x0000000001507751 in mysql_execute_command (thd=0x7f0dfd019000, first_level=true) at /sda/percona-server_dbg/sql/sql_parse.cc:2882
#31 0x000000000150f30e in mysql_parse (thd=0x7f0dfd019000, parser_state=0x7f0e3a18c500) at /sda/percona-server_dbg/sql/sql_parse.cc:5786
#32 0x0000000001504325 in dispatch_command (thd=0x7f0dfd019000, com_data=0x7f0e3a18cc90, command=COM_QUERY) at /sda/percona-server_dbg/sql/sql_parse.cc:1445
#33 0x000000000150323f in do_command (thd=0x7f0dfd019000) at /sda/percona-server_dbg/sql/sql_parse.cc:1008
#34 0x000000000163ab1b in handle_connection (arg=0x7f0e25ffec10) at /sda/percona-server_dbg/sql/conn_handler/connection_handler_per_thread.cc:313
#35 0x00000000018b0fa4 in pfs_spawn_thread (arg=0x7f0e257f1220) at /sda/percona-server_dbg/storage/perfschema/pfs.cc:2192
#36 0x00007f0e39bd1df5 in start_thread () from /lib64/libpthread.so.0
#37 0x00007f0e37e241ad in clone () from /lib64/libc.so.6

Testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
update performance_schema.setup_instruments SET enabled='YES';
SET STATEMENT myisam_sort_buffer_size=0,myisam_repair_threads=0,sort_buffer_size=0,binlog_format=row,keep_files_on_create=ON,max_join_size=0 FOR CALL p0();
INSTALL PLUGIN example SONAME 'ha_example.so';# NOERROR
show session variables like 'log_error';

How to reproduce the issue :

$ vi 1452850231_mybase # STEP1: Update the base path in this file (usually the only change required!). If you use a non-binary distribution, please update SOURCE_DIR location also
$ ./1452850231_init # STEP2: Initializes the data dir
$ ./1452850231_start # STEP3: Starts mysqld
$ ./1452850231_cl # STEP4: To check mysqld is up
$ ./1452850231_run_pquery # STEP5: Run the testcase with the pquery binary
$ ./1452850231_run # OPTIONAL: Run the testcase with the mysql CLI (may not reproduce the issue, as the pquery binary was used for the original testcase reduction)
$ vi /dev/shm/1452850231/error.log.out # STEP6: Verify the error log
$ ./1452850231_gdb # OPTIONAL: Brings you to a gdb prompt with gdb attached to the used mysqld and attached to the generated core
$ ./1452850231_parse_core # STEP7: Creates 1452850231_STD.gdb and 1452850231_FULL.gdb; standard and full variables gdb stack traces

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Laurynas Biveinis (laurynas-biveinis)
tags: added: qa57 set-statement
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Can you please provide the server error log (IIRC the bug bundles used to contain in the past?), and the CLI output? The expected errors, if any, for SET STATEMENT and INSTALL PLUGIN statements are interesting here.

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :

Please find the CLI output and error log. Error log will not be available in pquery bug bundle. With RQG bug we used attach error log.

mysql> DROP DATABASE test;CREATE DATABASE test;USE test;
Query OK, 0 rows affected (0.00 sec)

Query OK, 1 row affected (0.00 sec)

Database changed
mysql> update performance_schema.setup_instruments SET enabled='YES';
Query OK, 718 rows affected (0.01 sec)
Rows matched: 1053 Changed: 718 Warnings: 0

mysql> SET STATEMENT myisam_sort_buffer_size=0,myisam_repair_threads=0,sort_buffer_size=0,binlog_format=row,keep_files_on_create=ON,max_join_size=0 FOR CALL p0();
ERROR 1305 (42000): PROCEDURE test.p0 does not exist
mysql> INSTALL PLUGIN example SONAME 'ha_example.so';# NOERROR
Query OK, 0 rows affected (0.00 sec)

mysql> show session variables like 'log_error';
ERROR 2013 (HY000): Lost connection to MySQL server during query
mysql>

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Ramesh, can you please try running server under Valgrind in your environment? Do you see any Valgrind errors in the error log then?

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :

Tested with valgrind build, but did not see any valgrind related error.

Startup command used :

valgrind --suppressions=/sda/ps5.7/PS-mysql-5.7.10-1rc1-linux-x86_64-valgrind/mysql-test/valgrind.supp --num-callers=40 --show-reachable=yes --track-origins=yes /sda/ps5.7/PS-mysql-5.7.10-1rc1-linux-x86_64-valgrind/bin/mysqld --no-defaults --basedir=/sda/ps5.7/PS-mysql-5.7.10-1rc1-linux-x86_64-valgrind --datadir=/dev/shm/1452850231/data --tmpdir=/dev/shm/1452850231/tmp --port=31962 --pid-file=/dev/shm/1452850231/pid.pid --core-file --socket=/dev/shm/1452850231/socket.sock --log-error=/dev/shm/1452850231/error.log.out --event-scheduler=ON

Attached error log.

Build command :

cmake . -DWITH_ZLIB=system -DCMAKE_BUILD_TYPE=Debug -DBUILD_CONFIG=mysql_release -DFEATURE_SET=community -DDEBUG_EXTNAME=OFF -DENABLE_DOWNLOADS=1 -DDOWNLOAD_BOOST=1 -DWITH_BOOST=/tmp -DWITH_SSL=system -DWITH_PAM=ON -DWITH_VALGRIND=ON

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

The assert shows PFS memory key mix-up (realloc is happening with key_memory_THD_variables, I don't see the malloc key, of course it could be related that SET STATEMENT introduced key_memory_per_query_vars).

Aligning the keys should resolve the issue but this also could show underlying issue to restore SET STATEMENT original values (see i.e. bug 1341606, or early DBUG_RETURNs for LOCK TABLES / UNLOCK TABLES in mysql_execute_command)

Ramesh, could you get a core dump bundle please?

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :

Laurynas, please find the core dump.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Please make it a "bundle", i.e. your mysqld binary and shared libs too.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Early DBUG_RETURNs logged as bug 1538535, and is not the cause here. Waiting for the core dump bundle to be completed to proceed.

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :

Bug bundle is uploaded in google drive : https://drive.google.com/open?id=0BxfPM27P03cEYXJ6NHZYLWEyNkE

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

https://github.com/percona/percona-server/pull/335

Revision history for this message
Roel Van de Paar (roel11) wrote :

Thanks Laurynas. It was removed from our filtering list.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.