Description:
Server crashes accessing uninitialized memory (random on production servers) when the below SELECT is executed
select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id;
(gdb) bt
#0 0x00007f2bb446faa1 in pthread_kill () from u/libpthread.so.0
#1 0x0000000001f1b647 in my_write_core (sig=<optimized out>) at /percona-server-8.0.21-12/mysys/stacktrace.cc:409
#2 0x000000000116862d in handle_fatal_signal (sig=11) at /percona-server-8.0.21-12/sql/signal_handler.cc:194
#3 <signal handler called>
#4 0x00007f2bb234dc30 in __memcpy_ssse3 () from u/libc.so.6
#5 0x00000000024b06c0 in memcpy (__len=<optimized out>, __src=<optimized out>, __dest=0x7f0f23f57e88) at /usr/include/bits/string3.h:51
#6 PFS_column_row::make_row (this=this@entry=0x7f0f23f57cf0, mdl=0x7f2b0c03e958) at /percona-server-8.0.21-12/storage/perfschema/table_helper.cc:842
#7 0x00000000024a52f4 in PFS_index_metadata_locks_by_object::match (this=0x7f109d075760, pfs=<optimized out>) at /percona-server-8.0.21-12/storage/perfschema/table_md_locks.cc:99
#8 0x00000000024a5bd6 in table_metadata_locks::index_next (this=0x7f115cadb300) at /percona-server-8.0.21-12/storage/perfschema/table_md_locks.cc:221
#9 0x0000000002451087 in ha_perfschema::index_next_same (this=0x7f10e0e5a828, buf=0x7f10e0df6c28 "", key=0x7f109d071a58 "\005", keylen=776) at /percona-server-8.0.21-12/storage/perfschema/ha_perfschema.cc:1919
#10 0x0000000000d64324 in handler::ha_index_next_same (this=0x7f10e0e5a828, buf=0x7f10e0df6c28 "", key=0x7f109d071a58 "\005", keylen=776) at /percona-server-8.0.21-12/sql/handler.cc:3713
#11 0x0000000000fda9e4 in RefIterator<false>::Read (this=0x7f109d074c98) at /percona-server-8.0.21-12/sql/sql_executor.cc:3887
#12 0x0000000001232284 in FilterIterator::Read (this=0x7f109d075078) at /percona-server-8.0.21-12/sql/composite_iterators.cc:79
#13 0x0000000001232cc7 in NestedLoopIterator::Read (this=0x7f109d0750b0) at /percona-server-8.0.21-12/sql/composite_iterators.cc:632
#14 0x0000000001232c80 in NestedLoopIterator::Read (this=0x7f109d075278) at /percona-server-8.0.21-12/sql/composite_iterators.cc:608
#15 0x0000000001232c80 in NestedLoopIterator::Read (this=0x7f109d0752c0) at /percona-server-8.0.21-12/sql/composite_iterators.cc:608
#16 0x0000000001237468 in MaterializeIterator::MaterializeQueryBlock (this=this@entry=0x7f109d075350, query_block=..., stored_rows=stored_rows@entry=0x7f0f23f58228) at /percona-server-8.0.21-12/sql/composite_iterators.cc:1031
#17 0x0000000001237d2f in MaterializeIterator::Init (this=0x7f109d075350) at /percona-server-8.0.21-12/sql/composite_iterators.cc:855
#18 0x00000000010eb2ca in SELECT_LEX_UNIT::ExecuteIteratorQuery (this=0x7f115cc5f128, thd=thd@entry=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_union.cc:1168
#19 0x00000000010eb4ac in SELECT_LEX_UNIT::execute (this=this@entry=0x7f115cc5f128, thd=thd@entry=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_union.cc:1238
#20 0x000000000107f7e9 in Sql_cmd_dml::execute_inner (this=0x7f109d27d828, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_select.cc:943
#21 0x00000000010894ed in Sql_cmd_dml::execute (this=0x7f109d27d828, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_select.cc:723
#22 0x0000000001027438 in mysql_execute_command (thd=thd@entry=0x7f110d05a000, first_level=first_level@entry=false) at /percona-server-8.0.21-12/sql/sql_parse.cc:4790
#23 0x0000000000fbd34d in mysql_open_cursor (thd=0x7f110d05a000, result=<optimized out>, pcursor=0x7f11b42cab88) at /percona-server-8.0.21-12/sql/sql_cursor.cc:148
#24 0x0000000000f7d657 in sp_lex_instr::reset_lex_and_exec_core (this=this@entry=0x7f109d27de30, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5964c, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:437
#25 0x0000000000f7e254 in sp_lex_instr::validate_lex_and_execute_core (this=this@entry=0x7f109d27de30, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5964c, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:719
#26 0x0000000000f7e499 in sp_instr_copen::execute (this=<optimized out>, thd=0x7f110d05a000, nextp=0x7f0f23f5964c) at /percona-server-8.0.21-12/sql/sp_instr.cc:1594
#27 0x0000000000f7542c in sp_head::execute (this=this@entry=0x7f109d0a8028, thd=thd@entry=0x7f110d05a000, merge_da_on_success=merge_da_on_success@entry=true) at /percona-server-8.0.21-12/sql/sp_head.cc:2222
#28 0x0000000000f78367 in sp_head::execute_procedure (this=this@entry=0x7f109d0a8028, thd=thd@entry=0x7f110d05a000, args=0x0) at /percona-server-8.0.21-12/sql/sp_head.cc:2888
#29 0x0000000000faa0a7 in Sql_cmd_call::execute_inner (this=0x7f11b433d5b8, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_call.cc:163
#30 0x00000000010894ed in Sql_cmd_dml::execute (this=0x7f11b433d5b8, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_select.cc:723
#31 0x0000000001027438 in mysql_execute_command (thd=thd@entry=0x7f110d05a000, first_level=first_level@entry=false) at /percona-server-8.0.21-12/sql/sql_parse.cc:4790
#32 0x0000000000f7b610 in sp_instr_stmt::exec_core (this=0x7f11b433d620, thd=0x7f110d05a000, nextp=0x7f0f23f5b0bc) at /percona-server-8.0.21-12/sql/sp_instr.cc:987
#33 0x0000000000f7d657 in sp_lex_instr::reset_lex_and_exec_core (this=this@entry=0x7f11b433d620, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5b0bc, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:437
#34 0x0000000000f7e254 in sp_lex_instr::validate_lex_and_execute_core (this=this@entry=0x7f11b433d620, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5b0bc, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:719
#35 0x0000000000f7f7ec in sp_instr_stmt::execute (this=0x7f11b433d620, thd=0x7f110d05a000, nextp=0x7f0f23f5b0bc) at /percona-server-8.0.21-12/sql/sp_instr.cc:897
#36 0x0000000000f7542c in sp_head::execute (this=this@entry=0x7f115cce2028, thd=thd@entry=0x7f110d05a000, merge_da_on_success=merge_da_on_success@entry=true) at /percona-server-8.0.21-12/sql/sp_head.cc:2222
#37 0x0000000000f78367 in sp_head::execute_procedure (this=this@entry=0x7f115cce2028, thd=thd@entry=0x7f110d05a000, args=args@entry=0x7f0f23f5b8b0) at /percona-server-8.0.21-12/sql/sp_head.cc:2888
#38 0x000000000116348d in Event_job_data::execute (this=this@entry=0x7f0f23f5bfc0, thd=thd@entry=0x7f110d05a000, drop=<optimized out>) at /percona-server-8.0.21-12/sql/event_data_objects.cc:1123
#39 0x000000000130ae65 in Event_worker_thread::run (this=this@entry=0x7f0f23f5c5bf, thd=thd@entry=0x7f110d05a000, event=event@entry=0x7f11ac81b450) at /percona-server-8.0.21-12/sql/event_scheduler.cc:381
#40 0x000000000130b138 in event_worker_thread (arg=arg@entry=0x7f11ac81b450) at /percona-server-8.0.21-12/sql/event_scheduler.cc:304
#41 0x000000000245546d in pfs_spawn_thread (arg=0x7f11ac9479e0) at /percona-server-8.0.21-12/storage/perfschema/pfs.cc:2881
#42 0x00007f2bb446aea5 in start_thread () from u/libpthread.so.0
#43 0x00007f2bb22fd96d in clone () from u/libc.so.6
How to repeat:
git diff
diff --git a/sql/sql_table.cc b/sql/sql_table.cc
index 5a7b4b29e97..f3fd01bb5b6 100644
--- a/sql/sql_table.cc
+++ b/sql/sql_table.cc
@@ -16193,6 +16193,8 @@ bool mysql_alter_table(THD *thd, const char *new_db, const char *new_name,
thd->variables.lock_wait_timeout))
return true;
+ DEBUG_SYNC_C("after_mdl_locks_acquire");
+
/*
If we are executing ALTER TABLE RENAME under LOCK TABLES we also need
to check that all previously orphan tables which reference new table
create mysql-test/t/pfs_fk.test
CREATE TABLE parent (
id INT NOT NULL,
PRIMARY KEY (id)
) ENGINE=INNODB;
CREATE TABLE child (
id INT,
parent_id INT,
INDEX par_ind (parent_id),
FOREIGN KEY (parent_id)
REFERENCES parent(id)
ON DELETE CASCADE
) ENGINE=INNODB;
connect (con1, localhost, root);
--connection default
SET DEBUG_SYNC= 'after_mdl_locks_acquire SIGNAL mdls_acquired WAIT_FOR resume';
--send ALTER TABLE child DROP FOREIGN KEY `child_ibfk_1`;
--connection con1
SET DEBUG_SYNC= 'now WAIT_FOR mdls_acquired';
select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id;
SET DEBUG_SYNC= 'now SIGNAL resume';
--connection default
--reap
--disconnect con1
DROP TABLE child;
DROP TABLE parent;
./mtr --mem main.pfs_fk --nocheck-testcases --valgrind
./mtr --mem main.pfs_fk --nocheck-testcases --valgrind
Logging: /home/satya/WORK/mysql-8.0/mysql-test/mysql-test-run.pl --mem main.pfs_fk --nocheck-testcases --valgrind
MySQL Version 8.0.24
Turning on valgrind for all executables
Running valgrind with options " --tool=memcheck --num-callers=16 --show-reachable=yes --suppressions=/home/satya/WORK/mysql-8.0/mysql-test/valgrind.supp "
Turning off --check-testcases to save time when valgrinding
Checking supported features
Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/home/satya/WORK/mysql-8.0/bld/mysql-test/var'
symlinking 'var' to '/dev/shm/var_auto_Kkem'
Installing system database
Using parallel: 1
==============================================================================
TEST NAME RESULT TIME (ms) COMMENT
------------------------------------------------------------------------------
CREATE TABLE parent (
id INT NOT NULL,
PRIMARY KEY (id)
) ENGINE=INNODB;
CREATE TABLE child (
id INT,
parent_id INT,
INDEX par_ind (parent_id),
FOREIGN KEY (parent_id)
REFERENCES parent(id)
ON DELETE CASCADE
) ENGINE=INNODB;
SET DEBUG_SYNC= 'after_mdl_locks_acquire SIGNAL mdls_acquired WAIT_FOR resume';
ALTER TABLE child DROP FOREIGN KEY `child_ibfk_1`;;
SET DEBUG_SYNC= 'now WAIT_FOR mdls_acquired';
select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id;
processlist_id
SET DEBUG_SYNC= 'now SIGNAL resume';
DROP TABLE child;
DROP TABLE parent;
[ 33%] main.pfs_fk [ fail ] Found warnings/errors in error log file!
Test ended at 2021-04-29 16:31:44
line
==306836== Thread 40:
==306836== Conditional jump or move depends on uninitialised value(s)
==306836== at 0x56F8111: PFS_column_row::make_row(MDL_key const*) (table_helper.cc:833)
==306836== by 0x570457A: PFS_index_metadata_locks_by_object::match(PFS_metadata_lock const*) (table_md_locks.cc:99)
==306836== by 0x5704B48: table_metadata_locks::index_next() (table_md_locks.cc:221)
==306836== by 0x568C5D5: PFS_engine_table::index_next_same(unsigned char const*, unsigned int) (pfs_engine_table.cc:855)
==306836== by 0x5671D31: ha_perfschema::index_next_same(unsigned char*, unsigned char const*, unsigned int) (ha_perfschema.cc:1955)
==306836== by 0x39902E8: handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int) (handler.cc:3457)
==306836== by 0x355D554: RefIterator<false>::Read() (sql_executor.cc:3799)
==306836== by 0x3CFF160: FilterIterator::Read() (composite_iterators.cc:83)
==306836== by 0x3D000ED: NestedLoopIterator::Read() (composite_iterators.cc:431)
.... repeated 2 times: ==306836== by 0x3D000ED: NestedLoopIterator::Read() (composite_iterators.cc:431)
==306836== by 0x3D01375: MaterializeIterator::MaterializeQueryBlock(MaterializeIterator::QueryBlock const&, unsigned long long*) (composite_iterators.cc:816)
==306836== by 0x3D00A7B: MaterializeIterator::Init() (composite_iterators.cc:629)
==306836== by 0x370AAF4: Query_expression::ExecuteIteratorQuery(THD*) (sql_union.cc:1223)
==306836== by 0x370AEDF: Query_expression::execute(THD*) (sql_union.cc:1283)
==306836== by 0x365341F: Sql_cmd_dml::execute_inner(THD*) (sql_select.cc:791)
^ Found warnings in /home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/mysqld.1.err
ok
the logfile can be found in '/home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/main.pfs_fk/pfs_fk.log'
worker[1] Valgrind report from /home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/mysqld.1.err after tests:
main.pfs_fk
------------------------------------------------------------------------------
HEAP SUMMARY:
in use at exit: 120 bytes in 3 blocks
total heap usage: 758,627 allocs, 758,624 frees, 460,187,132 bytes allocated
LEAK SUMMARY:
definitely lost: 0 bytes in 0 blocks
indirectly lost: 0 bytes in 0 blocks
possibly lost: 0 bytes in 0 blocks
still reachable: 0 bytes in 0 blocks
suppressed: 120 bytes in 3 blocks
Use --track-origins=yes to see where uninitialised values come from
For lists of detected and suppressed errors, rerun with: -s
ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0)
safe_process[306835]: Child process: 306836, exit: 42
[ 66%] shutdown_report [ pass ]
[100%] valgrind_report [ fail ]
Test ended at 2021-04-29 16:31:44
Valgrind reported failures at shutdown, see above
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 0.000 of 131 seconds executing testcases
mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/warnings' for details.
Completed: Failed 2/3 tests, 33.33% were successful.
Failing test(s): main.pfs_fk valgrind_report
The log files in var/log may give you some hint of what went wrong.
If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html
mysql-test-run: *** ERROR: there were failing test cases
Suggested fix:
Going by other fix and code around, it seems setting m_cloumn_length to 0 is sufficient. But I don't like this approach. There is something wrong with object initialization and un-initialization(reuse)
What if there is new MDL type added and m_column_length is not set to zero? (Feel free to ignore this comment/suggestion).
Anyways, simplest fix is:
git diff
diff --git a/sql/sql_table.cc b/sql/sql_table.cc
index 5a7b4b29e97..f3fd01bb5b6 100644
--- a/sql/sql_table.cc
+++ b/sql/sql_table.cc
@@ -16193,6 +16193,8 @@ bool mysql_alter_table(THD *thd, const char *new_db, const char *new_name,
thd->variables.lock_wait_timeout))
return true;
+ DEBUG_SYNC_C("after_mdl_locks_acquire");
+
/*
If we are executing ALTER TABLE RENAME under LOCK TABLES we also need
to check that all previously orphan tables which reference new table
diff --git a/storage/perfschema/table_helper.cc b/storage/perfschema/table_helper.cc
index cf8c1ed9da2..7244871bb51 100644
--- a/storage/perfschema/table_helper.cc
+++ b/storage/perfschema/table_helper.cc
@@ -800,6 +800,7 @@ int PFS_column_row::make_row(const MDL_key *mdl) {
m_object_type = OBJECT_TYPE_FOREIGN_KEY;
m_schema_name_length = mdl->db_name_length();
m_object_name_length = mdl->name_length();
+ m_column_name_length = 0;
break;
case MDL_key::CHECK_CONSTRAINT:
m_object_type = OBJECT_TYPE_CHECK_CONSTRAINT;
------------
./mtr --mem main.pfs_fk --nocheck-testcases --valgrind
Logging: /home/satya/WORK/mysql-8.0/mysql-test/mysql-test-run.pl --mem main.pfs_fk --nocheck-testcases --valgrind
MySQL Version 8.0.24
Turning on valgrind for all executables
Running valgrind with options " --tool=memcheck --num-callers=16 --show-reachable=yes --suppressions=/home/satya/WORK/mysql-8.0/mysql-test/valgrind.supp "
Turning off --check-testcases to save time when valgrinding
Checking supported features
- Binaries are debug compiled
Using 'all' suites
Collecting tests
Checking leftover processes
Removing old var directory
Creating var directory '/home/satya/WORK/mysql-8.0/bld/mysql-test/var'
- symlinking 'var' to '/dev/shm/var_auto_HN7G'
Installing system database
Using parallel: 1
==============================================================================
TEST NAME RESULT TIME (ms) COMMENT
------------------------------------------------------------------------------
CREATE TABLE parent (
id INT NOT NULL,
PRIMARY KEY (id)
) ENGINE=INNODB;
CREATE TABLE child (
id INT,
parent_id INT,
INDEX par_ind (parent_id),
FOREIGN KEY (parent_id)
REFERENCES parent(id)
ON DELETE CASCADE
) ENGINE=INNODB;
SET DEBUG_SYNC= 'after_mdl_locks_acquire SIGNAL mdls_acquired WAIT_FOR resume';
ALTER TABLE child DROP FOREIGN KEY `child_ibfk_1`;;
SET DEBUG_SYNC= 'now WAIT_FOR mdls_acquired';
select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id;
processlist_id
SET DEBUG_SYNC= 'now SIGNAL resume';
DROP TABLE child;
DROP TABLE parent;
[ 33%] main.pfs_fk [ pass ] 14278
[ 66%] shutdown_report [ pass ]
[100%] valgrind_report [ pass ]
------------------------------------------------------------------------------
The servers were restarted 0 times
The servers were reinitialized 0 times
Spent 14.278 of 128 seconds executing testcases
Completed: All 3 tests were successful.
Description: Server crashes accessing uninitialized memory (random on production servers) when the below SELECT is executed select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id; (gdb) bt #0 0x00007f2bb446faa1 in pthread_kill () from u/libpthread.so.0 #1 0x0000000001f1b647 in my_write_core (sig=<optimized out>) at /percona-server-8.0.21-12/mysys/stacktrace.cc:409 #2 0x000000000116862d in handle_fatal_signal (sig=11) at /percona-server-8.0.21-12/sql/signal_handler.cc:194 #3 <signal handler called> #4 0x00007f2bb234dc30 in __memcpy_ssse3 () from u/libc.so.6 #5 0x00000000024b06c0 in memcpy (__len=<optimized out>, __src=<optimized out>, __dest=0x7f0f23f57e88) at /usr/include/bits/string3.h:51 #6 PFS_column_row::make_row (this=this@entry=0x7f0f23f57cf0, mdl=0x7f2b0c03e958) at /percona-server-8.0.21-12/storage/perfschema/table_helper.cc:842 #7 0x00000000024a52f4 in PFS_index_metadata_locks_by_object::match (this=0x7f109d075760, pfs=<optimized out>) at /percona-server-8.0.21-12/storage/perfschema/table_md_locks.cc:99 #8 0x00000000024a5bd6 in table_metadata_locks::index_next (this=0x7f115cadb300) at /percona-server-8.0.21-12/storage/perfschema/table_md_locks.cc:221 #9 0x0000000002451087 in ha_perfschema::index_next_same (this=0x7f10e0e5a828, buf=0x7f10e0df6c28 "", key=0x7f109d071a58 "\005", keylen=776) at /percona-server-8.0.21-12/storage/perfschema/ha_perfschema.cc:1919 #10 0x0000000000d64324 in handler::ha_index_next_same (this=0x7f10e0e5a828, buf=0x7f10e0df6c28 "", key=0x7f109d071a58 "\005", keylen=776) at /percona-server-8.0.21-12/sql/handler.cc:3713 #11 0x0000000000fda9e4 in RefIterator<false>::Read (this=0x7f109d074c98) at /percona-server-8.0.21-12/sql/sql_executor.cc:3887 #12 0x0000000001232284 in FilterIterator::Read (this=0x7f109d075078) at /percona-server-8.0.21-12/sql/composite_iterators.cc:79 #13 0x0000000001232cc7 in NestedLoopIterator::Read (this=0x7f109d0750b0) at /percona-server-8.0.21-12/sql/composite_iterators.cc:632 #14 0x0000000001232c80 in NestedLoopIterator::Read (this=0x7f109d075278) at /percona-server-8.0.21-12/sql/composite_iterators.cc:608 #15 0x0000000001232c80 in NestedLoopIterator::Read (this=0x7f109d0752c0) at /percona-server-8.0.21-12/sql/composite_iterators.cc:608 #16 0x0000000001237468 in MaterializeIterator::MaterializeQueryBlock (this=this@entry=0x7f109d075350, query_block=..., stored_rows=stored_rows@entry=0x7f0f23f58228) at /percona-server-8.0.21-12/sql/composite_iterators.cc:1031 #17 0x0000000001237d2f in MaterializeIterator::Init (this=0x7f109d075350) at /percona-server-8.0.21-12/sql/composite_iterators.cc:855 #18 0x00000000010eb2ca in SELECT_LEX_UNIT::ExecuteIteratorQuery (this=0x7f115cc5f128, thd=thd@entry=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_union.cc:1168 #19 0x00000000010eb4ac in SELECT_LEX_UNIT::execute (this=this@entry=0x7f115cc5f128, thd=thd@entry=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_union.cc:1238 #20 0x000000000107f7e9 in Sql_cmd_dml::execute_inner (this=0x7f109d27d828, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_select.cc:943 #21 0x00000000010894ed in Sql_cmd_dml::execute (this=0x7f109d27d828, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_select.cc:723 #22 0x0000000001027438 in mysql_execute_command (thd=thd@entry=0x7f110d05a000, first_level=first_level@entry=false) at /percona-server-8.0.21-12/sql/sql_parse.cc:4790 #23 0x0000000000fbd34d in mysql_open_cursor (thd=0x7f110d05a000, result=<optimized out>, pcursor=0x7f11b42cab88) at /percona-server-8.0.21-12/sql/sql_cursor.cc:148 #24 0x0000000000f7d657 in sp_lex_instr::reset_lex_and_exec_core (this=this@entry=0x7f109d27de30, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5964c, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:437 #25 0x0000000000f7e254 in sp_lex_instr::validate_lex_and_execute_core (this=this@entry=0x7f109d27de30, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5964c, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:719 #26 0x0000000000f7e499 in sp_instr_copen::execute (this=<optimized out>, thd=0x7f110d05a000, nextp=0x7f0f23f5964c) at /percona-server-8.0.21-12/sql/sp_instr.cc:1594 #27 0x0000000000f7542c in sp_head::execute (this=this@entry=0x7f109d0a8028, thd=thd@entry=0x7f110d05a000, merge_da_on_success=merge_da_on_success@entry=true) at /percona-server-8.0.21-12/sql/sp_head.cc:2222 #28 0x0000000000f78367 in sp_head::execute_procedure (this=this@entry=0x7f109d0a8028, thd=thd@entry=0x7f110d05a000, args=0x0) at /percona-server-8.0.21-12/sql/sp_head.cc:2888 #29 0x0000000000faa0a7 in Sql_cmd_call::execute_inner (this=0x7f11b433d5b8, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_call.cc:163 #30 0x00000000010894ed in Sql_cmd_dml::execute (this=0x7f11b433d5b8, thd=0x7f110d05a000) at /percona-server-8.0.21-12/sql/sql_select.cc:723 #31 0x0000000001027438 in mysql_execute_command (thd=thd@entry=0x7f110d05a000, first_level=first_level@entry=false) at /percona-server-8.0.21-12/sql/sql_parse.cc:4790 #32 0x0000000000f7b610 in sp_instr_stmt::exec_core (this=0x7f11b433d620, thd=0x7f110d05a000, nextp=0x7f0f23f5b0bc) at /percona-server-8.0.21-12/sql/sp_instr.cc:987 #33 0x0000000000f7d657 in sp_lex_instr::reset_lex_and_exec_core (this=this@entry=0x7f11b433d620, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5b0bc, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:437 #34 0x0000000000f7e254 in sp_lex_instr::validate_lex_and_execute_core (this=this@entry=0x7f11b433d620, thd=thd@entry=0x7f110d05a000, nextp=nextp@entry=0x7f0f23f5b0bc, open_tables=open_tables@entry=false) at /percona-server-8.0.21-12/sql/sp_instr.cc:719 #35 0x0000000000f7f7ec in sp_instr_stmt::execute (this=0x7f11b433d620, thd=0x7f110d05a000, nextp=0x7f0f23f5b0bc) at /percona-server-8.0.21-12/sql/sp_instr.cc:897 #36 0x0000000000f7542c in sp_head::execute (this=this@entry=0x7f115cce2028, thd=thd@entry=0x7f110d05a000, merge_da_on_success=merge_da_on_success@entry=true) at /percona-server-8.0.21-12/sql/sp_head.cc:2222 #37 0x0000000000f78367 in sp_head::execute_procedure (this=this@entry=0x7f115cce2028, thd=thd@entry=0x7f110d05a000, args=args@entry=0x7f0f23f5b8b0) at /percona-server-8.0.21-12/sql/sp_head.cc:2888 #38 0x000000000116348d in Event_job_data::execute (this=this@entry=0x7f0f23f5bfc0, thd=thd@entry=0x7f110d05a000, drop=<optimized out>) at /percona-server-8.0.21-12/sql/event_data_objects.cc:1123 #39 0x000000000130ae65 in Event_worker_thread::run (this=this@entry=0x7f0f23f5c5bf, thd=thd@entry=0x7f110d05a000, event=event@entry=0x7f11ac81b450) at /percona-server-8.0.21-12/sql/event_scheduler.cc:381 #40 0x000000000130b138 in event_worker_thread (arg=arg@entry=0x7f11ac81b450) at /percona-server-8.0.21-12/sql/event_scheduler.cc:304 #41 0x000000000245546d in pfs_spawn_thread (arg=0x7f11ac9479e0) at /percona-server-8.0.21-12/storage/perfschema/pfs.cc:2881 #42 0x00007f2bb446aea5 in start_thread () from u/libpthread.so.0 #43 0x00007f2bb22fd96d in clone () from u/libc.so.6 How to repeat: git diff diff --git a/sql/sql_table.cc b/sql/sql_table.cc index 5a7b4b29e97..f3fd01bb5b6 100644 --- a/sql/sql_table.cc +++ b/sql/sql_table.cc @@ -16193,6 +16193,8 @@ bool mysql_alter_table(THD *thd, const char *new_db, const char *new_name, thd->variables.lock_wait_timeout)) return true; + DEBUG_SYNC_C("after_mdl_locks_acquire"); + /* If we are executing ALTER TABLE RENAME under LOCK TABLES we also need to check that all previously orphan tables which reference new table create mysql-test/t/pfs_fk.test CREATE TABLE parent ( id INT NOT NULL, PRIMARY KEY (id) ) ENGINE=INNODB; CREATE TABLE child ( id INT, parent_id INT, INDEX par_ind (parent_id), FOREIGN KEY (parent_id) REFERENCES parent(id) ON DELETE CASCADE ) ENGINE=INNODB; connect (con1, localhost, root); --connection default SET DEBUG_SYNC= 'after_mdl_locks_acquire SIGNAL mdls_acquired WAIT_FOR resume'; --send ALTER TABLE child DROP FOREIGN KEY `child_ibfk_1`; --connection con1 SET DEBUG_SYNC= 'now WAIT_FOR mdls_acquired'; select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id; SET DEBUG_SYNC= 'now SIGNAL resume'; --connection default --reap --disconnect con1 DROP TABLE child; DROP TABLE parent; ./mtr --mem main.pfs_fk --nocheck-testcases --valgrind ./mtr --mem main.pfs_fk --nocheck-testcases --valgrind Logging: /home/satya/WORK/mysql-8.0/mysql-test/mysql-test-run.pl --mem main.pfs_fk --nocheck-testcases --valgrind MySQL Version 8.0.24 Turning on valgrind for all executables Running valgrind with options " --tool=memcheck --num-callers=16 --show-reachable=yes --suppressions=/home/satya/WORK/mysql-8.0/mysql-test/valgrind.supp " Turning off --check-testcases to save time when valgrinding Checking supported features Binaries are debug compiled Using 'all' suites Collecting tests Checking leftover processes Removing old var directory Creating var directory '/home/satya/WORK/mysql-8.0/bld/mysql-test/var' symlinking 'var' to '/dev/shm/var_auto_Kkem' Installing system database Using parallel: 1 ============================================================================== TEST NAME RESULT TIME (ms) COMMENT ------------------------------------------------------------------------------ CREATE TABLE parent ( id INT NOT NULL, PRIMARY KEY (id) ) ENGINE=INNODB; CREATE TABLE child ( id INT, parent_id INT, INDEX par_ind (parent_id), FOREIGN KEY (parent_id) REFERENCES parent(id) ON DELETE CASCADE ) ENGINE=INNODB; SET DEBUG_SYNC= 'after_mdl_locks_acquire SIGNAL mdls_acquired WAIT_FOR resume'; ALTER TABLE child DROP FOREIGN KEY `child_ibfk_1`;; SET DEBUG_SYNC= 'now WAIT_FOR mdls_acquired'; select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id; processlist_id SET DEBUG_SYNC= 'now SIGNAL resume'; DROP TABLE child; DROP TABLE parent; [ 33%] main.pfs_fk [ fail ] Found warnings/errors in error log file! Test ended at 2021-04-29 16:31:44 line ==306836== Thread 40: ==306836== Conditional jump or move depends on uninitialised value(s) ==306836== at 0x56F8111: PFS_column_row::make_row(MDL_key const*) (table_helper.cc:833) ==306836== by 0x570457A: PFS_index_metadata_locks_by_object::match(PFS_metadata_lock const*) (table_md_locks.cc:99) ==306836== by 0x5704B48: table_metadata_locks::index_next() (table_md_locks.cc:221) ==306836== by 0x568C5D5: PFS_engine_table::index_next_same(unsigned char const*, unsigned int) (pfs_engine_table.cc:855) ==306836== by 0x5671D31: ha_perfschema::index_next_same(unsigned char*, unsigned char const*, unsigned int) (ha_perfschema.cc:1955) ==306836== by 0x39902E8: handler::ha_index_next_same(unsigned char*, unsigned char const*, unsigned int) (handler.cc:3457) ==306836== by 0x355D554: RefIterator<false>::Read() (sql_executor.cc:3799) ==306836== by 0x3CFF160: FilterIterator::Read() (composite_iterators.cc:83) ==306836== by 0x3D000ED: NestedLoopIterator::Read() (composite_iterators.cc:431) .... repeated 2 times: ==306836== by 0x3D000ED: NestedLoopIterator::Read() (composite_iterators.cc:431) ==306836== by 0x3D01375: MaterializeIterator::MaterializeQueryBlock(MaterializeIterator::QueryBlock const&, unsigned long long*) (composite_iterators.cc:816) ==306836== by 0x3D00A7B: MaterializeIterator::Init() (composite_iterators.cc:629) ==306836== by 0x370AAF4: Query_expression::ExecuteIteratorQuery(THD*) (sql_union.cc:1223) ==306836== by 0x370AEDF: Query_expression::execute(THD*) (sql_union.cc:1283) ==306836== by 0x365341F: Sql_cmd_dml::execute_inner(THD*) (sql_select.cc:791) ^ Found warnings in /home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/mysqld.1.err ok the logfile can be found in '/home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/main.pfs_fk/pfs_fk.log' worker[1] Valgrind report from /home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/mysqld.1.err after tests: main.pfs_fk ------------------------------------------------------------------------------ HEAP SUMMARY: in use at exit: 120 bytes in 3 blocks total heap usage: 758,627 allocs, 758,624 frees, 460,187,132 bytes allocated LEAK SUMMARY: definitely lost: 0 bytes in 0 blocks indirectly lost: 0 bytes in 0 blocks possibly lost: 0 bytes in 0 blocks still reachable: 0 bytes in 0 blocks suppressed: 120 bytes in 3 blocks Use --track-origins=yes to see where uninitialised values come from For lists of detected and suppressed errors, rerun with: -s ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 0 from 0) safe_process[306835]: Child process: 306836, exit: 42 [ 66%] shutdown_report [ pass ] [100%] valgrind_report [ fail ] Test ended at 2021-04-29 16:31:44 Valgrind reported failures at shutdown, see above ------------------------------------------------------------------------------ The servers were restarted 0 times The servers were reinitialized 0 times Spent 0.000 of 131 seconds executing testcases mysql-test-run: WARNING: Got errors/warnings while running tests, please examine '/home/satya/WORK/mysql-8.0/bld/mysql-test/var/log/warnings' for details. Completed: Failed 2/3 tests, 33.33% were successful. Failing test(s): main.pfs_fk valgrind_report The log files in var/log may give you some hint of what went wrong. If you want to report this error, please read first the documentation at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html mysql-test-run: *** ERROR: there were failing test cases Suggested fix: Going by other fix and code around, it seems setting m_cloumn_length to 0 is sufficient. But I don't like this approach. There is something wrong with object initialization and un-initialization(reuse) What if there is new MDL type added and m_column_length is not set to zero? (Feel free to ignore this comment/suggestion). Anyways, simplest fix is: git diff diff --git a/sql/sql_table.cc b/sql/sql_table.cc index 5a7b4b29e97..f3fd01bb5b6 100644 --- a/sql/sql_table.cc +++ b/sql/sql_table.cc @@ -16193,6 +16193,8 @@ bool mysql_alter_table(THD *thd, const char *new_db, const char *new_name, thd->variables.lock_wait_timeout)) return true; + DEBUG_SYNC_C("after_mdl_locks_acquire"); + /* If we are executing ALTER TABLE RENAME under LOCK TABLES we also need to check that all previously orphan tables which reference new table diff --git a/storage/perfschema/table_helper.cc b/storage/perfschema/table_helper.cc index cf8c1ed9da2..7244871bb51 100644 --- a/storage/perfschema/table_helper.cc +++ b/storage/perfschema/table_helper.cc @@ -800,6 +800,7 @@ int PFS_column_row::make_row(const MDL_key *mdl) { m_object_type = OBJECT_TYPE_FOREIGN_KEY; m_schema_name_length = mdl->db_name_length(); m_object_name_length = mdl->name_length(); + m_column_name_length = 0; break; case MDL_key::CHECK_CONSTRAINT: m_object_type = OBJECT_TYPE_CHECK_CONSTRAINT; ------------ ./mtr --mem main.pfs_fk --nocheck-testcases --valgrind Logging: /home/satya/WORK/mysql-8.0/mysql-test/mysql-test-run.pl --mem main.pfs_fk --nocheck-testcases --valgrind MySQL Version 8.0.24 Turning on valgrind for all executables Running valgrind with options " --tool=memcheck --num-callers=16 --show-reachable=yes --suppressions=/home/satya/WORK/mysql-8.0/mysql-test/valgrind.supp " Turning off --check-testcases to save time when valgrinding Checking supported features - Binaries are debug compiled Using 'all' suites Collecting tests Checking leftover processes Removing old var directory Creating var directory '/home/satya/WORK/mysql-8.0/bld/mysql-test/var' - symlinking 'var' to '/dev/shm/var_auto_HN7G' Installing system database Using parallel: 1 ============================================================================== TEST NAME RESULT TIME (ms) COMMENT ------------------------------------------------------------------------------ CREATE TABLE parent ( id INT NOT NULL, PRIMARY KEY (id) ) ENGINE=INNODB; CREATE TABLE child ( id INT, parent_id INT, INDEX par_ind (parent_id), FOREIGN KEY (parent_id) REFERENCES parent(id) ON DELETE CASCADE ) ENGINE=INNODB; SET DEBUG_SYNC= 'after_mdl_locks_acquire SIGNAL mdls_acquired WAIT_FOR resume'; ALTER TABLE child DROP FOREIGN KEY `child_ibfk_1`;; SET DEBUG_SYNC= 'now WAIT_FOR mdls_acquired'; select thd_blocker.processlist_id from performance_schema.metadata_locks mdl_blocker join performance_schema.metadata_locks mdl_exclusive on mdl_exclusive.object_schema=mdl_blocker.object_schema and mdl_exclusive.object_name=mdl_blocker.object_name and mdl_exclusive.owner_thread_id!=mdl_blocker.owner_thread_id join performance_schema.metadata_locks mdl_blocked on mdl_blocked.object_schema=mdl_exclusive.object_schema and mdl_blocked.object_name=mdl_exclusive.object_name and mdl_blocked.owner_thread_id!=mdl_exclusive.owner_thread_id join performance_schema.threads thd_blocker on thd_blocker.thread_id=mdl_blocker.owner_thread_id where mdl_blocker.object_type='TABLE' and mdl_blocker.lock_type like 'SHARED%' and mdl_blocker.lock_status='GRANTED' and mdl_exclusive.object_type='TABLE' and mdl_exclusive.lock_type='EXCLUSIVE' and mdl_exclusive.lock_status='PENDING' and mdl_blocked.object_type='TABLE' and mdl_blocked.lock_type like 'SHARED%' and mdl_blocked.lock_status='PENDING' group by mdl_blocker.owner_thread_id; processlist_id SET DEBUG_SYNC= 'now SIGNAL resume'; DROP TABLE child; DROP TABLE parent; [ 33%] main.pfs_fk [ pass ] 14278 [ 66%] shutdown_report [ pass ] [100%] valgrind_report [ pass ] ------------------------------------------------------------------------------ The servers were restarted 0 times The servers were reinitialized 0 times Spent 14.278 of 128 seconds executing testcases Completed: All 3 tests were successful.