Bug #77863 slowdown caused by memset in sql_digest_storage.reset()

Submitted: 28 Jul 2015 19:00 Modified: 30 Jul 2015 13:05
Reporter: Domas Mituzas Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Performance Schema Severity:S5 (Performance)
Version:5.6.26 OS:Any
Assigned to: Marc ALFF CPU Architecture:Any

[28 Jul 2015 19:00] Domas Mituzas
Description:
reading from table_events_statements writes that many bytes:
#define MAX_DIGEST_STORAGE_SIZE (1024*1024) 

into memory for each row being fetched from it, like in this stack:

(gdb) bt
#0  0x00007fe3803c32f2 in __memset_sse2 () from /lib64/libc.so.6
#1  0x00000000009101d2 in reset (this=0x7fdf3d16bd90, pfs_thread=0x7fe36c400c40, statement=0x7fe35f9464a0) at /root/mysql-5.6.26/sql/sql_digest.h:70
#2  reset (this=0x7fdf3d16bd90, pfs_thread=0x7fe36c400c40, statement=0x7fe35f9464a0) at /root/mysql-5.6.26/sql/sql_digest.h:60
#3  table_events_statements_current::make_row (this=0x7fdf3d16bd90, pfs_thread=0x7fe36c400c40, statement=0x7fe35f9464a0) at /root/mysql-5.6.26/storage/perfschema/table_events_statements.cc:721
#4  0x00000000009104b8 in table_events_statements_current::rnd_next (this=0x7fdf3d16bd90) at /root/mysql-5.6.26/storage/perfschema/table_events_statements.cc:668
#5  0x00000000008f7977 in ha_perfschema::rnd_next (this=0x19b4b10, buf=0x19b4f00 "") at /root/mysql-5.6.26/storage/perfschema/ha_perfschema.cc:332
#6  0x000000000058caa4 in handler::ha_rnd_next (this=0x19b4b10, buf=0x19b4f00 "") at /root/mysql-5.6.26/sql/handler.cc:2687
#7  0x000000000081ab1e in rr_sequential (info=0x7fdf3c2828a0) at /root/mysql-5.6.26/sql/records.cc:480
#8  0x00000000006b58a9 in sub_select (join=0x7fdf3c281b28, join_tab=0x7fdf3c282810, end_of_records=<value optimized out>) at /root/mysql-5.6.26/sql/sql_executor.cc:1259
#9  0x00000000006b7035 in do_select (this=0x7fdf3c281b28) at /root/mysql-5.6.26/sql/sql_executor.cc:933
#10 JOIN::exec (this=0x7fdf3c281b28) at /root/mysql-5.6.26/sql/sql_executor.cc:194
#11 0x00000000006fce88 in mysql_execute_select (thd=0x2a20110, tables=0x7fdf3c2814d8, wild_num=0, fields=<value optimized out>, conds=0x0, order=<value optimized out>, group=0x2a226a8, having=0x0, select_options=2147748608, result=0x7fdf3c281b00, unit=0x2a21f60, select_lex=0x2a225a8) at /root/mysql-5.6.26/sql/sql_select.cc:1100
#12 mysql_select (thd=0x2a20110, tables=0x7fdf3c2814d8, wild_num=0, fields=<value optimized out>, conds=0x0, order=<value optimized out>, group=0x2a226a8, having=0x0, select_options=2147748608, result=0x7fdf3c281b00, unit=0x2a21f60, select_lex=0x2a225a8) at /root/mysql-5.6.26/sql/sql_select.cc:1221
#13 0x00000000006fd77f in handle_select (thd=0x2a20110, result=0x7fdf3c281b00, setup_tables_done_option=0) at /root/mysql-5.6.26/sql/sql_select.cc:110
#14 0x00000000006d71e5 in execute_sqlcom_select (thd=0x2a20110, all_tables=0x7fdf3c2814d8) at /root/mysql-5.6.26/sql/sql_parse.cc:5134
#15 0x00000000006dc212 in mysql_execute_command (thd=0x2a20110) at /root/mysql-5.6.26/sql/sql_parse.cc:2656
#16 0x00000000006de9f7 in mysql_parse (thd=0x2a20110, rawbuf=<value optimized out>, length=<value optimized out>, parser_state=<value optimized out>) at /root/mysql-5.6.26/sql/sql_parse.cc:6386
#17 0x00000000006e034c in dispatch_command (command=COM_QUERY, thd=0x2a20110, packet=0x2a241d1 "", packet_length=1009258926) at /root/mysql-5.6.26/sql/sql_parse.cc:1340
#18 0x00000000006a734d in do_handle_one_connection (thd_arg=<value optimized out>) at /root/mysql-5.6.26/sql/sql_connect.cc:982
#19 0x00000000006a7482 in handle_one_connection (arg=0x2a20110) at /root/mysql-5.6.26/sql/sql_connect.cc:898
#20 0x0000000000924057 in pfs_spawn_thread (arg=0x2a281e0) at /root/mysql-5.6.26/storage/perfschema/pfs.cc:1860
#21 0x00007fe3814bda51 in start_thread () from /lib64/libpthread.so.0
#22 0x00007fe38042792d in clone () from /lib64/libc.so.6
(gdb) frame 1
#1  0x00000000009101d2 in reset (this=0x7fdf3d16bd90, pfs_thread=0x7fe36c400c40, statement=0x7fe35f9464a0) at /root/mysql-5.6.26/sql/sql_digest.h:70
70	      memset(m_token_array, 0, m_token_array_length);
(gdb) print m_token_array_length
$1 = 1048576

That makes querying it very very inefficient. 
Disabling statement digests makes it faster, but that should not be an excuse for this kind of behavior :( 

How to repeat:
SELECT * FROM table_events_statements

perf top.

Suggested fix:
don't use large constants in dynamic environment
[30 Jul 2015 7:29] MySQL Verification Team
Hello Domas,

Thank you for the report.
Confirmed this with 5.6.26 source build.

Thanks,
Umesh
[30 Jul 2015 7:32] MySQL Verification Team
test results

Attachment: 77863_5-6_26.results (application/octet-stream, text), 12.39 KiB.

[30 Jul 2015 13:05] Paul DuBois
Noted in 5.6.26, 5.7.9, 5.8.0 changelogs.

An unnecessary memset() call invoked during Performance Schema digest
operations has been removed, which improves performance by reducing
overhead.

Portions of this website are copyright © 2001, 2002 The PHP Group

Page generated in 0.053 sec. using MySQL 8.4.7-u6-cloud

Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the respective copyright holders.
It is not reviewed in advance by Oracle and does not necessarily represent the opinion of Oracle or any other party.