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] Umesh Shastry
Hello Domas,

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

Thanks,
Umesh
[30 Jul 2015 7:32] Umesh Shastry
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.