Bug #98771 Performance impact while selecting data from a JSON type column
Submitted: 28 Feb 2020 6:29 Modified: 28 Feb 2020 11:16
Reporter: Chelluru Vidyadhar Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S2 (Serious)
Version:5.7, 5.7.29 OS:Any
Assigned to: CPU Architecture:Any
Tags: json, performance, regression

[28 Feb 2020 6:29] Chelluru Vidyadhar
Description:
We have noticed significant different in timelines while querying single json records from a table between 5.7.16 and 5.7.26. Upon further verification we noticed that some change happened starting 5.7.22 incur the issue. Even the same query executed on same table with same data showing difference in timelines. 

Below is the pstack collected from one of the query running on 5.7.22 whcih is running for long time. We can see that lot of time being spend on "wrapper_to_string"

================================================================

Thread 3 (Thread 0x7f5dcc537700 (LWP 16492)):
#0  0x00007f5df02b3c18 in __memmove_ssse3_back () from /lib64/libc.so.6
#1  0x0000000000f483cf in my_realloc (key=<optimized out>, ptr=0x7f5dad8ae320, size=2685776, flags=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/mysys/my_malloc.c:100
#2  0x0000000000debfaa in String::mem_realloc (this=0x7f5dcc535020, alloc_length=2685769, force_on_heap=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql-common/sql_string.cc:115
#3  0x0000000000c52712 in reserve (space_needed=35, this=0x7f5dcc535020) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/include/sql_string.h:490
#4  wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=true, pretty=false, func_name=0x7f5dac0491c8 "json_col", depth=7) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2090
#5  0x0000000000c52697 in wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=true, pretty=<optimized out>, func_name=0x7f5dac0491c8 "json_col", depth=6) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2059
#6  0x0000000000c52697 in wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=true, pretty=<optimized out>, func_name=0x7f5dac0491c8 "json_col", depth=5) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2059
#7  0x0000000000c52697 in wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=true, pretty=<optimized out>, func_name=0x7f5dac0491c8 "json_col", depth=4) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2059
#8  0x0000000000c52697 in wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=true, pretty=<optimized out>, func_name=0x7f5dac0491c8 "json_col", depth=3) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2059
#9  0x0000000000c528b5 in wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=32, pretty=false, func_name=0x7f5dac0491c8 "json_col", depth=2) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2129
#10 0x0000000000c528b5 in wrapper_to_string (wr=..., buffer=0x7f5dcc535020, json_quoted=false, pretty=false, func_name=0x7f5dac0491c8 "json_col", depth=1) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/json_dom.cc:2129
#11 0x0000000000801313 in Field_json::val_str (this=0x7f5dac01ff68, buf1=0x7f5dcc535020, buf2=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/field.cc:9075
#12 0x0000000000801768 in val_str (str=0x7f5dcc535020, this=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/field.h:864
#13 Field::send_text (this=<optimized out>, protocol=0x7f5dac013388) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/field.cc:1722
#14 0x0000000000cd2fa3 in THD::send_result_set_row (this=0x7f5dac012330, row_items=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_class.cc:4681
#15 0x0000000000cd308b in Query_result_send::send_data (this=0x7f5dac009c40, items=...) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_class.cc:2721
#16 0x0000000000ce4828 in end_send (join=0x7f5dac050250, qep_tab=0x7f5dac050aa8, end_of_records=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_executor.cc:2913
#17 0x0000000000ce9cfe in evaluate_join_record (join=0x7f5dac050250, qep_tab=0x7f5dac050930) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_executor.cc:1645
#18 0x0000000000ceade3 in sub_select (join=0x7f5dac050250, qep_tab=0x7f5dac050930, end_of_records=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_executor.cc:1297
#19 0x0000000000cea2ba in do_select (join=0x7f5dac050250) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_executor.cc:950
#20 JOIN::exec (this=0x7f5dac050250) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_executor.cc:199
#21 0x0000000000d54a10 in handle_query (thd=0x7f5dac012330, lex=0x7f5dac014498, result=0x7f5dac009c40, added_options=1, removed_options=0) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_select.cc:184
#22 0x0000000000d15353 in execute_sqlcom_select (thd=0x7f5dac012330, all_tables=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_parse.cc:5156
#23 0x0000000000d18bce in mysql_execute_command (thd=0x7f5dac012330, first_level=true) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_parse.cc:2792
#24 0x0000000000d1aaad in mysql_parse (thd=0x7f5dac012330, parser_state=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_parse.cc:5582
#25 0x0000000000d1bcca in dispatch_command (thd=0x7f5dac012330, com_data=0x7f5dcc536da0, command=COM_QUERY) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_parse.cc:1458
#26 0x0000000000d1cb74 in do_command (thd=0x7f5dac012330) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/sql_parse.cc:999
#27 0x0000000000dedaec in handle_connection (arg=<optimized out>) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/sql/conn_handler/connection_handler_per_thread.cc:300
#28 0x0000000001256a94 in pfs_spawn_thread (arg=0x33bdd50) at /export/home/pb2/build/sb_0-27500212-1520171728.22/mysql-5.7.22/storage/perfschema/pfs.cc:2190
#29 0x00007f5df179ddd5 in start_thread () from /lib64/libpthread.so.0
#30 0x00007f5df0256ead in clone () from /lib64/libc.so.6

================================================================

How to repeat:
1. Install any MySQL version between 5.7.16 and 5.7.21 (Prefer to install 5.7.16) and execute below comamnds:

create database jsontest;
use jsontest;
source mysql5716_clone.sql;
select * from geodata; # Call it Query1
select json_col from geodata; # Call it Query2

2. Now, Install any MySQL version between 5.7.22 and 5.7.28 (prefer to install 5.7.26) and execute below commands:

create database jsontest;
use jsontest;
source mysql5716_clone.sql;
select * from geodata; # Call it Query3
select json_col from geodata; # Call it Query4

Observations:-
We can see that the time taken to complete Query3 and Query4 are much higher compared to executions times of Query1 and Query2. The execution plan, optimizer trace, number of buffer pool pages accessed
[28 Feb 2020 11:16] MySQL Verification Team
Hello Chelluru,

Thank you for the report and test case.
Verified as described.

regards,
Umesh
[28 Feb 2020 11:17] MySQL Verification Team
Test results - 5.7.11, 5.7.22 and 5.7.29, perf report

Attachment: 98771_5.7.results (application/octet-stream, text), 113.09 KiB.

[28 Feb 2020 11:21] MySQL Verification Team
- 8.0.19 I'm not seeing any issues

mysql> pager grep non-sence
PAGER set to 'grep non-sence'
mysql> select * from geodata;
1 row in set (0.19 sec)

mysql> select json_col from geodata;
1 row in set (0.19 sec)