背景
组内DBA同学在日常检查中，发现某个接入我们数据库中间件的业务，后端MySQL实例负载特别高，在开启general log后发现，有大量的set names utf8mb4 COLLATE utf8mb4_general_ci和SET NAMES utf8 COLLATE utf8_general_ci查询。而且几乎每个查询都会带两次set names。经过统计，set names达到了所有查询的65%，而且由于这个业务本身的请求量非常大，导致后端MySQL实例几乎处于临界状态。
分析
基于上面的情况，开始做有关的分析。
首先，和业务确认了使用的Connector java 版本为5.1.10，jdbc连接串和参数，同时确认使用的框架不会一直发送set names，业务通过抓包也确认了上述结论。目前可以确定的这些set names请求是中间件发送到后端MySQL实例的。
通过查看中间件代码，确认中间件作为代理层，会分别尝试让前端连接和自己的charset配置，以及后端MySQL和自己的charset配置保持一致，在这个过程中，就会主动发送set names到后端MySQL进行修改。DBA同学通过抓包，也确认是中间件层发送了set names到后端MySQL。
所以，现在的问题是，为什么会几乎每个请求都带2个set names，一个utf8mb4，一个utf8。而且其他业务很少遇到这种情况？ 其实原因到这里基本快要明晰了。后面我们接着分析。
原理
再次回到connector java，这里会对比不同版本的连接初始化请求，为了方便查看，在jdbc连接串设置profileSQL=true。经过执行发现如下的结果。
INFO: Profiler Event: [QUERY] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 1 ms, connection-id: 779, statement-id: 1, resultset-id: 1, message: /* mysql-connector-java-5.1.10 ( Revision: ${svn.Revision} ) */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 = 'init_connect'
INFO: Profiler Event: [FETCH] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 11 ms, connection-id: 779, statement-id: 1, resultset-id: 1
INFO: Profiler Event: [QUERY] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 1 ms, connection-id: 779, statement-id: 1, resultset-id: 2, message: /* mysql-connector-java-5.1.10 ( Revision: ${svn.Revision} ) */SELECT @@session.auto_increment_increment
INFO: Profiler Event: [FETCH] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 1, resultset-id: 2
INFO: Profiler Event: [QUERY] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 2, resultset-id: 3, message: SHOW COLLATION
INFO: Profiler Event: [FETCH] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 1 ms, connection-id: 779, statement-id: 2, resultset-id: 3
INFO: Profiler Event: [QUERY] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 999, resultset-id: 0, message: SET character_set_results = NULL
INFO: Profiler Event: [FETCH] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 999, resultset-id: 0
INFO: Profiler Event: [FETCH] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 999, resultset-id: 0
INFO: Profiler Event: [QUERY] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 999, resultset-id: 0, message: SET autocommit=1
INFO: Profiler Event: [FETCH] at java.sql.DriverManager.getConnection(DriverManager.java:664) duration: 0 ms, connection-id: 779, statement-id: 999, resultset-id: 0
Fri May 28 10:55:41 CST 2021 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
Fri May 28 10:55:41 CST 2021 INFO: [QUERY] /* mysql-connector-java-5.1.48 ( Revision: 29734982609c32d3ab7e5cac2e6acee69ff6b4aa ) */SELECT @@session.auto_increment_increment AS auto_increment_increment, @@character_set_client AS character_set_client, @@character_set_connection AS character_set_connection, @@character_set_results AS character_set_results, @@character_set_server AS character_set_server, @@collation_server AS collation_server, @@collation_connection AS collation_connection, @@init_connect AS init_connect, @@interactive_timeout AS interactive_timeout, @@license AS license, @@lower_case_table_names AS lower_case_table_names, @@max_allowed_packet AS max_allowed_packet, @@net_buffer_length AS net_buffer_length, @@net_write_timeout AS net_write_timeout, @@performance_schema AS performance_schema, @@query_cache_size AS query_cache_size, @@query_cache_type AS query_cache_type, @@sql_mode AS sql_mode, @@system_time_zone AS system_time_zone, @@time_zone AS time_zone, @@transaction_isolation AS transaction_isolation, @@wait_timeout AS wait_timeout [Created on: Fri May 28 10:55:41 CST 2021, duration: 0, connection-id: 780, statement-id: 1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [FETCH] [Created on: Fri May 28 10:55:41 CST 2021, duration: 13, connection-id: 780, statement-id: 1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [QUERY] SET NAMES utf8mb4 COLLATE utf8mb4_general_ci [Created on: Fri May 28 10:55:41 CST 2021, duration: 0, connection-id: 780, statement-id: -1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [FETCH] [Created on: Fri May 28 10:55:41 CST 2021, duration: 1, connection-id: 780, statement-id: -1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [QUERY] SET character_set_results = NULL [Created on: Fri May 28 10:55:41 CST 2021, duration: 0, connection-id: 780, statement-id: -1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [FETCH] [Created on: Fri May 28 10:55:41 CST 2021, duration: 0, connection-id: 780, statement-id: -1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [QUERY] SET autocommit=1 [Created on: Fri May 28 10:55:41 CST 2021, duration: 0, connection-id: 780, statement-id: -1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [FETCH] [Created on: Fri May 28 10:55:41 CST 2021, duration: 1, connection-id: 780, statement-id: -1, resultset-id: 0, at java.sql.DriverManager.getConnection(DriverManager.java:664), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [QUERY] select * from test limit 10 [Created on: Fri May 28 10:55:41 CST 2021, duration: 1, connection-id: 780, statement-id: 2, resultset-id: 0, at com.igoso.me.TestJdbc$1.run(TestJdbc.java:33), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:41 CST 2021 INFO: [FETCH] [Created on: Fri May 28 10:55:41 CST 2021, duration: 0, connection-id: 780, statement-id: 2, resultset-id: 0, at com.igoso.me.TestJdbc$1.run(TestJdbc.java:33), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:43 CST 2021 INFO: [QUERY] select * from test limit 10 [Created on: Fri May 28 10:55:43 CST 2021, duration: 0, connection-id: 780, statement-id: 3, resultset-id: 0, at com.igoso.me.TestJdbc$1.run(TestJdbc.java:33), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
Fri May 28 10:55:43 CST 2021 INFO: [FETCH] [Created on: Fri May 28 10:55:43 CST 2021, duration: 2, connection-id: 780, statement-id: 3, resultset-id: 0, at com.igoso.me.TestJdbc$1.run(TestJdbc.java:33), hostNameIndex: -1, catalogIndex: -1, eventCreationPointIndex: -1]
可以看到相比5.1.10，5.1.48版本驱动加了一个主动的set names utf8mb4。经过对中间件的分析，如果收到set names的请求，会把前端连接的charset设置为发送请求的值。这也就是5.1.48版本不会出现大量set names的原因，在设置后前端连接和Proxy和后端MySQL的charset保持了一致。而经过分析5.1.10不支持utf8mb4，在它的charsetMapping类中，也没有utf8mb4的定义。后来查资料发现，只有5.1.13以后才支持了utf8mb4。
同时，经过本地验证，通过jdbc访问Proxy中间件，再通过后端MySQL的general log确认，在使用5.1.48版本的驱动后，没有再产生大量set names，而5.1.10可以完全复现业务大量set names请求到后端的情况。
在业务升级上线后，经过观察，确认问题得到解决。
结论
该问题需要升级jdbc驱动的版本，最好到5.1.48。同时我们中间件层的charset设置，如果业务没有强制要求，建议还是utf8以保持更好的兼容性，但这样可能后期不好扩展升级。
需要注意的是经过验证多个版本包括5.1.10,5.1.48,8.0.25，初始化创建连接charset(collationIndex)都依赖characterEncoding配置，这个配置不能设置为utf8mb4。
网友评论