Connector Java 字符设置导致服务负载过高问题记录

背景

组内DBA同学在日常检查中,发现某个接入我们数据库中间件的业务,后端MySQL实例负载特别高,在开启general log后发现,有大量的set names utf8mb4 COLLATE utf8mb4_general_ciSET 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。

参考资料

1.jdbc 字符设置简要分析
2.mysql charset bugs
3.jdbc参数设置

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 151,688评论 1 330
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 64,559评论 1 273
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 101,749评论 0 226
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 42,581评论 0 191
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 50,741评论 3 271
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 39,684评论 1 192
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 31,122评论 2 292
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 29,847评论 0 182
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 33,441评论 0 228
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 29,939评论 2 232
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 31,333评论 1 242
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 27,783评论 2 236
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 32,275评论 3 220
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 25,830评论 0 8
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 26,444评论 0 180
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 34,553评论 2 249
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 34,618评论 2 249

推荐阅读更多精彩内容