Extended variable SET questions and possible performance regression

[pgporada]

Hi,

I am running Ubuntu 20.04 with proxysql commit 64f43e5d2b90e85cf82965b92f6fcd9677c2d559 in debug mode with

./src/proxysql -f -d 8 --idle-threads -c /etc/proxysql.cnf 

mysql -u admin -padmin --socket /var/lib/proxysql/admin.sock
LOAD DEBUG TO RUNTIME;
SET admin-debug='true'; LOAD ADMIN VARIABLES TO RUNTIME;

I'm testing that an arbitrary application using go-sql-driver/mysql v1.6 and v1.7. In v1.6 of that software, all parameters would now be set in a single transaction - the extended SET from MariaDB/MySQL docs.

The following DSN parameters are read from a configuration file:

bad-key-revoker:admin@unix(/var/lib/proxysql/sql.sock)/boulder?timeout=5s&readTimeout=60m&tx_isolation=%27READ-UNCOMMITTED%27

and these parameters are set inside the application on each session creation.

• sql_mode = 'READ-UNCOMMITTED' letsencrypt/boulder@8fd5861
• max_statement_time = 3420 and long_query_time = 2880 https://github.com/letsencrypt/boulder/blob/main/sa/database.go#L211-L212

ProxySQL outputs the following debug lines:

18013510093(7): 84543:MySQL_Session.cpp:5961:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#11#debug_mysql_query_processor LVL#5 : Parsing SET command = SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                                                   
18013510918(825): 84543:MySQL_Session.cpp:6000:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Parsing SET command SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                                                                
18013510932(14): 84543:MySQL_Session.cpp:6001:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#11#debug_mysql_query_processor LVL#5 : Parsing SET command = SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                                                  
18013510947(15): 84543:set_parser.cpp:26:parse1(): MOD#11#debug_mysql_query_processor LVL#4 : Parsing query SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                                                                                                                                 
18013516305(5358): 84543:set_parser.cpp:60:parse1(): MOD#11#debug_mysql_query_processor LVL#4 : SET parsing: v1='' , v2='' , v3='' , v4='long_query_time' , v5='2880,'                                                                                                                                                                                               
18013516359(54): 84543:set_parser.cpp:60:parse1(): MOD#11#debug_mysql_query_processor LVL#4 : SET parsing: v1='' , v2='' , v3='' , v4='max_statement_time' , v5='3420,'                                                                                                                                                                                              
18013516697(338): 84543:set_parser.cpp:60:parse1(): MOD#11#debug_mysql_query_processor LVL#4 : SET parsing: v1='' , v2='' , v3='' , v4='sql_mode' , v5='STRICT_ALL_TABLES'                                                                                                                                                                                           
18013516898(201): 84543:set_parser.cpp:60:parse1(): MOD#11#debug_mysql_query_processor LVL#4 : SET parsing: v1='' , v2='' , v3='' , v4='tx_isolation' , v5='READ-UNCOMMITTED'                                                                                                                                                                                        
18013517493(595): 84543:MySQL_Session.cpp:6009:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Processing SET variable long_query_time                                                                                                                                                                     
18013517674(181): 84543:MySQL_Variables.cpp:597:parse_variable_number(): MOD#4#debug_mysql_com LVL#5 : Changing connection long_query_time to 2880                                                                                                                                                                                                                   
18013517751(77): 84543:MySQL_Session.cpp:6009:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Processing SET variable max_statement_time                                                                                                                                                                   
18013517766(15): 84543:MySQL_Session.cpp:6009:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Processing SET variable sql_mode                                                                                                                                                                             
18013517777(11): 84543:MySQL_Session.cpp:6083:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Processing SET SQL Mode value STRICT_ALL_TABLES                                                                                                                                                              
18013517793(16): 84543:MySQL_Session.cpp:6009:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Processing SET variable tx_isolation                                                                                                                                                                         
18013517988(195): 84543:MySQL_Session.cpp:6396:handler___status_WAITING_CLIENT_DATA___STATE_SLEEP___MYSQL_COM_QUERY_qpo(): MOD#4#debug_mysql_com LVL#5 : Processing SET tx_isolation value READ-UNCOMMITTED                                                                                                                                                          
18013518039(51): 84543:MySQL_Session.cpp:7826:unable_to_parse_set_statement(): MOD#11#debug_mysql_query_processor LVL#5 : Locking hostgroup for query SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                                                                                       
18013518046(7): 84543:MySQL_Session.cpp:7830:unable_to_parse_set_statement(): MOD#11#debug_mysql_query_processor LVL#5 : SET query to cause setting lock_hostgroup: SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                                                                         
2023-03-08 22:19:07 MySQL_Session.cpp:7835:unable_to_parse_set_statement(): [WARNING] Unable to parse unknown SET query from client localhost:0. Setting lock_hostgroup. Please report a bug for future enhancements:SET long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES', tx_isolation = 'READ-UNCOMMITTED'                        
18013518654(8): 84543:MySQL_Session.cpp:3968:get_pkts_from_client(): MOD#4#debug_mysql_com LVL#5 : Received query to be processed with MariaDB Client library

What's interesting to me is that MariaDB 10.6 query logs receive this from ProxySQL.

4518 Connect  bad-key-revoker@host on boulder using TCP/IP                                                                                                                                                     
4518 Query    SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED                                                                                                                                                                                                                                                                             
4518 Query    SET long_query_time=2880                                                                                                                                                                                                                                                                                                             
4518 Query    SET sql_mode='STRICT_ALL_TABLES'                                                                                                                                                                                                                                                                                                     
4518 Query    SET tx_isolation = 'READ-UNCOMMITTED', long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES'

The line SET tx_isolation = 'READ-UNCOMMITTED', long_query_time = 2880, max_statement_time = 3420, sql_mode = 'STRICT_ALL_TABLES' is coming through as an extended SET and the syntax for that is SET var_name = expr [, var_name = expr] ....

Am I correct in understanding that long_query_time and sql_mode are being SET twice, once as a standalone SET and once in the extended SET? If so, that seems like a performance regression.

I do not see a standalone SET for max_statement_time in the MariaDB output, but I do see it in the extended SET.

I do not understand why I am seeing this from proxysql either.

[WARNING] Unable to parse unknown SET query from client localhost:0. Setting lock_hostgroup. Please report a bug for future enhancements:

Routing queries through proxysql without extended SET on go-sql-driver/mysql v1.5 produces the following messages. Keep in mind here that sql_mode = 'READ-UNCOMMITTED' is being set last which avoids problems from this issue.

2324 Connect  bad-key-revoker@host on boulder using TCP/IP
2324 Query    SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
2324 Query    SET long_query_time=2880
2324 Query    SET max_statement_time=3420
2324 Query    SET sql_mode=STRICT_ALL_TABLES 

[beautifulentropy]

Similar issue: #3644

[beautifulentropy]

I think I finally have a better grasp of this issue. The performance regression with extended SET statements stems from the fact that ProxySQL will parse, construct, and send separate SET statements for each recognized system variable. However, when it encounters an extended SET statement containing even a single variable that it doesn't recognize, it will send each variable that it does recognize as a separate statement, and then send the entire extended SET again as a single statement. This has the downside of making the MySQL Server process a SET for each system variable that it already SET, as well as the single variable that ProxySQL didn't recognize.