Bug #75590 SHOW VARIABLES WHERE ... materializes all variables into bigass temptable
Submitted: 22 Jan 2015 22:39 Modified: 14 Nov 2018 17:40
Reporter: Domas Mituzas Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Locking Severity:S3 (Non-critical)
Version:5.6 OS:Any
Assigned to: Marc ALFF CPU Architecture:Any

[22 Jan 2015 22:39] Domas Mituzas
Description:
JDBC client likes to call "SHOW VARIABLES WHERE ...", but MySQL server is extremely inefficient when running that. 

It will materialize a temptable in heap, allocating megabyte memory chunks, write all the stuff there, then discard. Essentially, this happens:

mysql> show variables where variable_name='';
Empty set (3.66 sec)

Unfortunately, it does huge memory allocations under a global mutex, thus leading to very poor scalability of the system. 

How to repeat:
use MySQL JDBC driver or anything else that uses SHOW VARIABLES WHERE ... syntax.

Example slow operation while holding a stats mutex:

Thread 661 (Thread 0x7f888f51b700 (LWP 358630)):
#0  0x0000000000580bd8 in arena_avail_comp (b=0x7f8680418a38, a=0x100001) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/arena.c:63
#1  arena_avail_tree_nsearch (key=0x100001, rbtree=0x7f9763e1f7c8) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/arena.c:88
#2  arena_run_alloc_large_helper (zero=false, size=1048576, arena=0x7f9763e1f700) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/arena.c:744
#3  arena_run_alloc_large (arena=arena@entry=0x7f9763e1f700, size=size@entry=1048576, zero=zero@entry=false) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/arena.c:764
#4  0x0000000000583826 in jemalloc_je_arena_malloc_large (arena=0x7f9763e1f700, size=size@entry=1047040, zero=zero@entry=false) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/arena.c:1635
#5  0x000000000057121f in jemalloc_je_arena_malloc (try_tcache=true, zero=false, size=1047040, arena=<optimized out>, tsd=<optimized out>) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/include/jemalloc/internal/arena.h:951
#6  jemalloc_je_imalloct (arena=0x0, try_tcache=true, size=1047040, tsd=<optimized out>) at include/jemalloc/internal/jemalloc_internal.h:811
#7  jemalloc_je_imalloc (size=1047040, tsd=<optimized out>) at include/jemalloc/internal/jemalloc_internal.h:820
#8  imalloc_body (usize=<synthetic pointer>, tsd=<synthetic pointer>, size=1047040) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/jemalloc.c:1278
#9  malloc (size=size@entry=1047040) at /3rdparty/jemalloc/dev/src/jemalloc.git-trunk/src/jemalloc.c:1291
#10 0x00000000008e1b55 in my_malloc (size=1047040, my_flags=my_flags@entry=16) at /whoeverwrotethis/mysys/my_malloc.c:38
#11 0x0000000000b15525 in hp_get_new_block (block=block@entry=0x7f86805d9200, alloc_length=alloc_length@entry=0x7f888f517c00) at /whoeverwrotethis/storage/heap/hp_block.c:80
#12 0x0000000000b14c22 in next_free_record_pos (info=0x7f86805d9200) at /whoeverwrotethis/storage/heap/hp_write.c:157
#13 heap_write (info=0x7f868068a800, record=0x7f86807c2810 "\375\024character_set_client") at /whoeverwrotethis/storage/heap/hp_write.c:45
#14 0x0000000000b10afa in ha_heap::write_row (this=0x7f88a8dfac10, buf=0x7f86807c2810 "\375\024character_set_client") at /whoeverwrotethis/storage/heap/ha_heap.cc:234
#15 0x00000000005ca294 in handler::ha_write_row (this=0x7f88a8dfac10, buf=0x7f86807c2810 "\375\024character_set_client") at /whoeverwrotethis/sql/handler.cc:7550
#16 0x000000000072412e in schema_table_store_record (thd=thd@entry=0x7f86635ac000, table=table@entry=0x7f86805df010) at /whoeverwrotethis/sql/sql_show.cc:2841
#17 0x0000000000727ff6 in show_status_array (thd=thd@entry=0x7f86635ac000, wild=wild@entry=0x0, variables=0x7f88a8e740e0, variables@entry=0x7f88a8e73e58, value_type=value_type@entry=OPT_SESSION, status_var=status_var@entry=0x0, prefix=prefix@entry=0xcd4e25 "", table=0x7f86805df010, ucase_names=ucase_names@entry=false, cond=cond@entry=0x7f88a8e73860, var_thd=0x7f86635ac000, var_thd@entry=0x0) at /whoeverwrotethis/sql/sql_show.cc:2750
#18 0x0000000000728645 in fill_variables (thd=thd@entry=0x7f86635ac000, tables=tables@entry=0x7f88a6ddd580, cond=0x7f88a8e73860) at /whoeverwrotethis/sql/sql_show.cc:6719
#19 0x000000000072e931 in do_fill_table (join_table=0x7f88a8e73470, table_list=0x7f88a6ddd580, thd=0x7f86635ac000) at /whoeverwrotethis/sql/sql_show.cc:7454
#20 get_schema_tables_result (join=join@entry=0x7f88a8e71010, executed_place=executed_place@entry=PROCESSED_BY_JOIN_EXEC) at /whoeverwrotethis/sql/sql_show.cc:7555
#21 0x0000000000712275 in JOIN::prepare_result (this=this@entry=0x7f88a8e71010, columns_list=columns_list@entry=0x7f888f5183e0) at /whoeverwrotethis/sql/sql_select.cc:856
#22 0x00000000006cf6e2 in JOIN::exec (this=0x7f88a8e71010) at /whoeverwrotethis/sql/sql_executor.cc:129
#23 0x0000000000716835 in mysql_execute_select (free_join=true, select_lex=0x7f86635af610, thd=0x7f86635ac000) at /whoeverwrotethis/sql/sql_select.cc:1133
#24 mysql_select (thd=thd@entry=0x7f86635ac000, tables=0x7f88a6ddd580, wild_num=0, fields=..., conds=<optimized out>, order=order@entry=0x7f86635af7d8, group=group@entry=0x7f86635af710, having=0x0, select_options=2684619520, result=result@entry=0x7f88a6dddec0, unit=unit@entry=0x7f86635aefb8, select_lex=select_lex@entry=0x7f86635af610) at /whoeverwrotethis/sql/sql_select.cc:1254
#25 0x0000000000717174 in handle_select (thd=thd@entry=0x7f86635ac000, result=result@entry=0x7f88a6dddec0, setup_tables_done_option=setup_tables_done_option@entry=0) at /whoeverwrotethis/sql/sql_select.cc:126
#26 0x00000000006fcbcc in execute_sqlcom_select (thd=thd@entry=0x7f86635ac000, all_tables=<optimized out>, last_timer=last_timer@entry=0x7f888f519af0) at /whoeverwrotethis/sql/sql_parse.cc:5694
#27 0x00000000006f3ed5 in mysql_execute_command (thd=thd@entry=0x7f86635ac000, statement_start_time=statement_start_time@entry=0x7f888f519910, post_parse=post_parse@entry=0x7f888f519af0) at /whoeverwrotethis/sql/sql_parse.cc:3105
#28 0x00000000006f945f in mysql_parse (thd=thd@entry=0x7f86635ac000, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f888f51a240, last_timer=last_timer@entry=0x7f888f519af0, async_commit=async_commit@entry=0x7f888f519ae0 "") at /whoeverwrotethis/sql/sql_parse.cc:6857
#29 0x00000000006fbce0 in dispatch_command (command=COM_QUERY, thd=0x7f86635ac000, packet=<optimized out>, packet_length=<optimized out>) at /whoeverwrotethis/sql/sql_parse.cc:1489
#30 0x00000000006fc67e in do_command (thd=<optimized out>) at /whoeverwrotethis/sql/sql_parse.cc:1061
#31 0x00000000006c7082 in do_handle_one_connection (thd_arg=<optimized out>) at /whoeverwrotethis/sql/sql_connect.cc:1021
#32 0x00000000006c7109 in handle_one_connection (arg=<optimized out>) at /whoeverwrotethis/sql/sql_connect.cc:929
#33 0x00007f9766906fa8 in start_thread () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libpthread.so.0
#34 0x00007f9764c8b5ad in clone () from /usr/local/fbcode/gcc-4.8.1-glibc-2.17/lib/libc.so.6

Suggested fix:
filter out data before writing to temptable, preallocate expected amount of data for the heap outside of mutex context, etc
[23 Jan 2015 8:32] MySQL Verification Team
related: http://bugs.mysql.com/bug.php?id=70433
[23 Jan 2015 11:35] MySQL Verification Team
as far as I can tell,  LOCK_global_system_variables should be unlocked just before calling schema_table_store_record.  Or do I miss something here?

Still amusing that the lock is locked/unlocked for every single variable?
[23 Jan 2015 11:40] MySQL Verification Team
setting as verified, there is room for improvement. At least I think it's not good to have this mutex flapping crazily if it's not requirement.
[2 Jul 2015 10:24] Murthy Sidagam
Posted by developer:
 
The query which is mentioned in the bug report(i.e show variables where variable_name='';) is not hitting the schema_table_store_record() function.
Hence moving the bug status to '30'.
[20 Jul 2015 9:12] Murthy Sidagam
Posted by developer:
 
And also in the code it is clear that the global mutex is unlocked before calling schema_table_store_record().
[30 Jul 2015 9:06] Marc ALFF
This bug is verified, no additional feedback needed.
[17 Sep 2015 9:24] Murthy Sidagam
We tried to reproduce the problem using the query below provided by the
connectors/J team.
We saw the max allocation of 127KB.

*********************************************
SHOW VARIABLES WHERE Variable_name ='language' OR Variable_name =
'net_write_timeout' OR Variable_name = 'interactive_timeout' OR Variable_name
= 'wait_timeout' OR Variable_name = 'character_set_client' OR Variable_name =
'character_set_connection' OR Variable_name = 'character_set' OR
Variable_name = 'character_set_server' OR Variable_name = 'tx_isolation' OR
Variable_name = 'transaction_isolation' OR Variable_name =
'character_set_results' OR Variable_name = 'timezone' OR Variable_name =
'time_zone' OR Variable_name = 'system_time_zone' OR Variable_name =
'lower_case_table_names' OR Variable_name = 'max_allowed_packet' OR
Variable_name = 'net_buffer_length' OR Variable_name = 'sql_mode' OR
Variable_name = 'query_cache_type' OR Variable_name = 'query_cache_size' OR
Variable_name = 'license' OR Variable_name = 'init_connect';
**********************************************

Note that with Bug#75592, the SHOW VARIABLES query generated by connector/J
has been simplified and is now much more efficient.
[18 Oct 2015 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[14 Nov 2018 17:42] MySQL Verification Team
So what we have is one connection doing this SHOW VARIABLES:

: ntdll!ZwWaitForSingleObject+0xa
: ntdll!RtlpWaitOnCriticalSection+0xe8
: ntdll!RtlEnterCriticalSection+0xd1
: ntdll!RtlpAllocateHeap+0x18a6
: ntdll!RtlAllocateHeap+0x16c
: mysqld!malloc+0x5b [f:\dd\vctools\crt_bld\self_64_amd64\crt\src\malloc.c @ 89]
: mysqld!my_malloc+0x2f [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\mysys\my_malloc.c @ 38]
: mysqld!hp_get_new_block+0x52 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\storage\heap\hp_block.c @ 80]
: mysqld!next_free_record_pos+0x87 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\storage\heap\hp_write.c @ 157]
: mysqld!heap_write+0x1f [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\storage\heap\hp_write.c @ 45]
: mysqld!ha_heap::write_row+0x49 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\storage\heap\ha_heap.cc @ 236]
: mysqld!handler::ha_write_row+0xcb [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\handler.cc @ 7274]
: mysqld!schema_table_store_record+0x1d [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 2796]
: mysqld!show_status_array+0x4db [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 2705]
: mysqld!fill_variables+0x1b1 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 6644]
: mysqld!do_fill_table+0xb9 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 7356]
: mysqld!get_schema_tables_result+0x1c4 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 7457]
: mysqld!JOIN::prepare_result+0x6e [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_select.cc @ 823]
: mysqld!JOIN::exec+0x17d [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_executor.cc @ 116]
: mysqld!mysql_execute_select+0x89 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_select.cc @ 1103]
: mysqld!handle_select+0x11b [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_select.cc @ 110]
: mysqld!execute_sqlcom_select+0x181 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_parse.cc @ 5139]

while several hundred are waiting like this :

: Call Site
: ntdll!ZwWaitForSingleObject+0xa
: ntdll!RtlpWaitOnCriticalSection+0xe8
: ntdll!RtlEnterCriticalSection+0xd1
: mysqld!fill_variables+0xd8 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 6636]
: mysqld!do_fill_table+0xb9 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 7356]
: mysqld!get_schema_tables_result+0x1c4 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_show.cc @ 7457]
: mysqld!JOIN::prepare_result+0x6e [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_select.cc @ 823]
: mysqld!JOIN::exec+0x17d [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_executor.cc @ 116]
: mysqld!mysql_execute_select+0x89 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_select.cc @ 1103]
: mysqld!handle_select+0x11b [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_select.cc @ 110]
: mysqld!execute_sqlcom_select+0x181 [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_parse.cc @ 5139]
: mysqld!mysql_execute_command+0x66f [f:\ade\build\sb_0-14808650-1427302793.22\mysqlcom-pro-5.6.24\sql\sql_parse.cc @ 2661]
<cut>
[1 Dec 2018 6:12] MySQL Verification Team
I've lodged a few more bugs related to this.

https://bugs.mysql.com/bug.php?id=93429 (mem advisors using SHOW VARIABLES unnecessarily)

https://bugs.mysql.com/bug.php?id=93202 (connector/net doesn't need to run SHOW VARIABLES)

https://bugs.mysql.com/bug.php?id=93201 (reconsider the number of SHOW [SESSION] VARIABLES commands run by connector/C++)