MySQL Bugs: #99077: Crash on concurrent access to events_statements_history

Bug #99077	Crash on concurrent access to events_statements_history_long
Submitted:	26 Mar 2020 9:47	Modified:	8 Apr 2020 9:02
Reporter:	Daniel Wang	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: Performance Schema	Severity:	S1 (Critical)
Version:	5.7.29	OS:	CentOS
Assigned to:		CPU Architecture:	Any

Description:
Concurrent access (from multiple connections) to the events_statements_history_long table in performance_schema can cause a crash.

Our backtrace was the follow:

Thread pointer: 0x7f3f68000ae0
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 = 7f3fd8530e70 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xf022eb]
/usr/sbin/mysqld(handle_fatal_signal+0x461)[0x7b47b1]
/lib64/libpthread.so.0(+0xf5e0)[0x7f42c68125e0]
/usr/sbin/mysqld(_ZNK6String8numcharsEv+0xe)[0xd91a3e]
/usr/sbin/mysqld(_ZN30table_events_statements_common15make_row_part_1EP21PFS_events_statementsP18sql_digest_storage+0x488)[0x12bc928]
/usr/sbin/mysqld(_ZN36table_events_statements_history_long8make_rowEP21PFS_events_statements+0x5f)[0x12bd43f]
/usr/sbin/mysqld(_ZN36table_events_statements_history_long8rnd_nextEv+0xc8)[0x12bd538]
/usr/sbin/mysqld(_ZN13ha_perfschema8rnd_nextEPh+0x66)[0x1278d36]
/usr/sbin/mysqld(_ZN7handler11ha_rnd_nextEPh+0x17c)[0x802f5c]
/usr/sbin/mysqld(_Z13rr_sequentialP11READ_RECORD+0x20)[0xc322c0]
/usr/sbin/mysqld(_Z10sub_selectP4JOINP7QEP_TABb+0x147)[0xca0ef7]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x267)[0xc99c17]
/usr/sbin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x17d)[0xd088ad]
/usr/sbin/mysqld[0x776be4]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x4224)[0xccc3c4]
/usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x3ad)[0xcce9dd]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xa9d)[0xccf55d]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x19f)[0xcd0f7f]
/usr/sbin/mysqld(handle_connection+0x2b0)[0xd93030]
/usr/sbin/mysqld(pfs_spawn_thread+0x1b4)[0x127a504]
/lib64/libpthread.so.0(+0x7e25)[0x7f42c680ae25]
/lib64/libc.so.6(clone+0x6d)[0x7f42c52c734d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f3f68005670): select count(*) as size from performance_schema.events_statements_history_long
Connection ID (thread ID): 88
Status: NOT_KILLED

How to repeat:
Run some random traffic, for example using sysbench

Run simultaneous access to an events_statements_history_long table, for example:
mysqlslap --concurrency=10 --number-of-queries 1000000 --create-schema testdb -q "select count(*) as size from performance_schema.events_statements_history_long;" -u -p

Bug #23540008 has the similar problem,but it's not completely fixed.

The code for reading character set information from Performance Schema statement events tables (for example, events_statements_current) did not prevent simultaneous writing to that information. As a result, the SQL query text character set could be invalid, which could result in a server exit. Now an invalid character set causes SQL_TEXT column truncation. (Bug #23540008)

Suggested fix:
storage/perfschema/table_events_statements.cc

- if (statement->m_sqltext_truncated || valid_length < statement->m_sqltext_length)
+ if (statement->m_sqltext_truncated || (valid_length > 0 && valid_length < statement->m_sqltext_length))

In this way it will prevent the server to crash.

Thank you for the bug report. You are reporting a very older version 5.7.23 please check first the current release 5.7.29. Thanks.

I have tested on the current release 5.7.29,crash still happend.

Further details.
When using gdb to analyze mysql core file I got the following bt:
(gdb) bt
#0  String::numchars (this=this@entry=0x7f1f240169a8) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql-common/sql_string.cc:691
#1  0x0000000001489f40 in table_events_statements_common::make_row_part_1 (this=this@entry=0x7f1f240168e0, statement=0x7f22516a3948, digest=digest@entry=0x7f1f681d3220)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/table_events_statements.cc:375
#2  0x000000000148a9ff in table_events_statements_history_long::make_row (this=this@entry=0x7f1f240168e0, statement=<optimized out>)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/table_events_statements.cc:1019
#3  0x000000000148aae8 in table_events_statements_history_long::rnd_next (this=0x7f1f240168e0)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/table_events_statements.cc:977
#4  0x000000000144a2b6 in ha_perfschema::rnd_next (this=0x7f1f2400ec30, buf=0x7f1f2400f040 "")
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/ha_perfschema.cc:357
#5  0x000000000083ba0c in handler::ha_rnd_next (this=0x7f1f2400ec30, buf=0x7f1f2400f040 "") at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/handler.cc:2962
#6  0x0000000000c6adb0 in rr_sequential (info=0x7f1f240072c0) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/records.cc:517
#7  0x0000000000cd97a7 in sub_select (join=0x7f1f24006b88, qep_tab=0x7f1f24007270, end_of_records=<optimized out>)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_executor.cc:1287
#8  0x0000000000cd2457 in do_select (join=0x7f1f24006b88) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_executor.cc:957
#9  JOIN::exec (this=0x7f1f24006b88) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_executor.cc:206
#10 0x0000000000d4165d in handle_query (thd=thd@entry=0x7f1f24000ae0, lex=lex@entry=0x7f1f24002c50, result=result@entry=0x7f1f24006ab8, added_options=added_options@entry=0, 
    removed_options=removed_options@entry=0) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_select.cc:191
#11 0x00000000007aa3e5 in execute_sqlcom_select (thd=thd@entry=0x7f1f24000ae0, all_tables=<optimized out>)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_parse.cc:5155
#12 0x0000000000d05487 in mysql_execute_command (thd=thd@entry=0x7f1f24000ae0, first_level=first_level@entry=true)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_parse.cc:2826
#13 0x0000000000d07a6d in mysql_parse (thd=thd@entry=0x7f1f24000ae0, parser_state=parser_state@entry=0x7f1f681d4540)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_parse.cc:5584
#14 0x0000000000d086aa in dispatch_command (thd=thd@entry=0x7f1f24000ae0, com_data=com_data@entry=0x7f1f681d4de0, command=COM_QUERY)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_parse.cc:1491
#15 0x0000000000d0a11f in do_command (thd=thd@entry=0x7f1f24000ae0) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/sql_parse.cc:1032
#16 0x0000000000dcc948 in handle_connection (arg=arg@entry=0x15fd1d30)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/sql/conn_handler/connection_handler_per_thread.cc:313
#17 0x000000000144b664 in pfs_spawn_thread (arg=0x15ef3ee0) at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/pfs.cc:2197
#18 0x00007f22530abe25 in start_thread () from /lib64/libpthread.so.0
#19 0x00007f2251b6834d in clone () from /lib64/libc.so.6
(gdb) f 1
#1  0x0000000001489f40 in table_events_statements_common::make_row_part_1 (this=this@entry=0x7f1f240168e0, statement=0x7f22516a3948, digest=digest@entry=0x7f1f681d3220)
    at /export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/table_events_statements.cc:375
375	/export/home/pb2/build/sb_0-37309218-1576675139.51/rpm/BUILD/mysql-5.7.29/mysql-5.7.29/storage/perfschema/table_events_statements.cc: No such file or directory.
(gdb) p cs
$1 = (CHARSET_INFO *) 0x0
(gdb) p valid_length
$2 = 0

Thanks.

Hi Mr. Wang,

Thank you for your bug report.

Your report seems very interesting. It is also a critical one.

I would like to be able to repeat the behaviour. If I understood you correctly, you used sysbench and mysqlslap simultaneously.

I need only info on how you ran sysbench test.

Many thanks in advance.

You might try the following steps:

To change the system variable performance_schema_events_statements_history_long_size from 10000 to 800.
[mysqld]
performance_schema_events_statements_history_long_size=800

And requires that the events_statements_history_long table is enabled within performance_schema.setup_consumers.

UPDATE performance_schema.setup_consumers SET ENABLED='YES' WHERE NAME='events_statements_history_long';

Run some random traffic, for example using sysbench

sysbench --test=/usr/share/doc/sysbench/tests/db/oltp.lua --mysql-table-engine=innodb --oltp-table-size=10000 --mysql-db=testdb --oltp-tables-count=8 --mysql-user= --mysql-password= --mysql-

socket=/var/lib/mysql/mysql.sock prepare

sysbench  --test=/usr/share/doc/sysbench/tests/db/oltp.lua --mysql-table-engine=innodb --oltp-table-size=10000  --oltp-tables-count=8 --max-requests=0 --max-time=300 --num-threads=16 --mysql-

socket=/var/lib/mysql/mysql.sock --mysql-db=testdb --mysql-port=3306 --mysql-user= --mysql-password= run

Run simultaneous access to an events_statements_history_long table, for example:
mysqlslap --concurrency=10 --number-of-queries 1000000 --create-schema testdb -q "select count(*) as size from performance_schema.events_statements_history_long;" -u -p

Thanks.

Hi Mr. Wang,

I was not able to repeat your crash on either 5.7.26 nor 5.7.29.

I ran your commands exactly as you reported, except for user, password, socket and similar irrelevant differences. I ran the test twice. Each time the test took more than 35 minutes.

The only difference between your test and mine is that I used much newer version of sysbench, judging by some arguments that have changed interim. Also, my computer has 8 cores running up to 5 GHz, uses SSD and has 32 Gb of RAM.

Can you try repeating your crash on another computer and with newer version of sysbench ???

Are there any other relevant configuration variables that you have used ????

Please, let us know and we will give it one more try.

I have repeated the crash on another computer without sysbench.

Test steps:

To change the system variable performance_schema_events_statements_history_long_size from 10000 to 800.
[mysqld]
performance_schema_events_statements_history_long_size=800

Run concurrent access to an events_statements_history_long table:
mysqlslap --concurrency=32 --number-of-queries 10000000000 --create-schema testdb -q "select count(*) as size from performance_schema.events_statements_history_long;" -u -p

Next,update the setup_consumers tables:
UPDATE performance_schema.setup_consumers SET ENABLED='YES' WHERE NAME='events_statements_history_long';

You might try several more times.

Thanks.

Hi Mr. Wang,

I have done all these steps already, without success. I will try again.

However, I have to ask whether you are using our binary. If you are not using a binary available from download pages on dev.mysql.com, please give it a try. This could be an issue with a compiler.

Hi Mr. Wang,

I have ran the test exactly as you described. mysqlslap ran in parallel with a shell loop running that UPDATE all the time. P_S was set exactly as you specified.

After several hours of testing, there was not a single warning in the error log with highest verbosity.

Hence, please let us know whether you have tried using our own binary, as I described in my previous comment.

.

I have used the binary available from download pages on dev.mysql.com all the time in the earlier tests.

Try the following steps:

Frist,update the setup_consumers table only once
UPDATE performance_schema.setup_consumers SET ENABLED='NO' WHERE NAME='events_statements_history_long';

Then,Run concurrent access to an events_statements_history_long table with mysqlslap

Next,update the setup_consumers table only once
UPDATE performance_schema.setup_consumers SET ENABLED='YES' WHERE NAME='events_statements_history_long';

Hi Mr. Wang,

Still no luck.

Can you let us know more about your hardware, exact version/release of CentOS, the exact URL of the binary that you downloaded and the settings that you used, apart from that P_S settings.

Thank you in advance.

Hi Mr. Wang,

This is just to inform you that we have done some additional testing.

We ran several of your test cases on centos 7 and  fedora 31 with mysql 5.7.29 binary downloaded from our site. Everything works ok, there were no crashes, nor any error messages at all.

Can't repeat.

Hi Mr. Wang,

We have tested several more times, on CentOS,  on the similar hardware, with very similar settings as you have provided and did not manage to repeat what you reported.