[问题描述]
在应用端, 偶尔看到有如下报错:
Authentication to host 'xxxx' for user 'yyyy' using method 'mysql_native_password' failed with message: Reading from the stream has failed.
表现特征:
1. 只有用 Connector.NET 出现这个问题, 用 JDBC 驱动没有类似问题.
2. 多台应用服务器, 只有一台报这个错, 因此可以排除服务器端的问题.
3. 问题非常随机, 重启一下服务器 / IIS, 就能临时解决问题.
4. 有一些场景应用服务器 CPU 并不是很高, 也会偶尔抛出这个错来.
客户端是 Windows 机器, 驱动是 MySQL Connector ADO.NET Driver for MySQL (Connector.NET) , 使用的版本是 6.9.9, 是比较新的版本.
[问题分析]
我们在应用服务器端和数据库端抓包. 两边抓到的包是一致的. 可以排除网络问题. 下面是抓到的包, 以及时间点:
编号 | 绝对时间 | 相对时间 (秒) | 源头 | 目的 | 网络包内容 |
---|---|---|---|---|---|
1 | 12:58:47 | 9.07 | 应用服务器 | 数据库服务器 | ......S. |
2 | 12:58:47 | 9.07 | 数据库服务器 | 应用服务器 | …A..S. |
3 | 12:58:47 | 9:07 | 应用服务器 | 数据库服务器 | …A…. |
4 | 12:58:47 | 9:07 | 数据库服务器 | 应用服务器 | …AP… |
5 | 12:58:47 | 9.27 | 应用服务器 | 数据库服务器 | …A…. |
6 | 12:58:57 | 19.12 | 数据库服务器 | 应用服务器 | …A…F |
7 | 12:58:57 | 19.12 | 应用服务器 | 数据库服务器 | …A…. |
8 | 12:59:10 | 32.00 | 应用服务器 | 数据库服务器 | …AP… |
9 | 12:59:10 | 32.00 | 数据库服务器 | 应用服务器 | …..R.. |
从上述网络包的交互来看, 前面三个包是 TCP 的三次握手协议. 问题出在第六个包, 数据库服务器向应用服务器发送了一个 Finish 包, 来终止数据库的连接. 数据库发送 Finish 包, 是由于数据库端发现连接超时而发送的. 这是由服务器端的 Connect_timeout 这个变量来控制. 原因在于应用端超过 10 秒未向数据库服务器端发送网络包. 从网络包交互的情况来看, 第五个包和第六个包的时间间隔刚好是 10 秒.
对比正常的数据库连接和上面异常的数据库连接. 应用服务器发送第 5 个包到数据库端后, 应该紧接着发送下面的网络包到数据库端的. 这个包主要是发送账号, 驱动版本, 操作系统信息等到数据库服务器端.[下面是部分的正常的网络包截图] . 在出现异常报错的场景, 客户端是延迟发送这个包的. 在 Frame 8 才发送的. 而此时连接已经被 Finish 了, 在 Frame 9, 数据库端发送了一个 Reset 包到应用服务器, 彻底中断连接.
我们现在具体分析, 为何客户端发送账号, 驱动版本, 操作系统信息到数据库端这么慢. 这部分的代码在 Connector.NET MySQLAuthenticationPlugin.cs 文件中. 我们修改这部分代码, 进行时间埋点, 来进一步定位问题. 下面是根据时间埋点, 打印出来的跟踪信息.
从跟踪的 Trace 来看, 有 30 秒左右的操作延时. 返回 MySQLDefs::OSDetails 的时候. 这部分代码如下:
- [DisplayName("_os_details")]
- public string OSDetails
- {
- get
- {
- string os = string.Empty;
- try
- {
- var searcher = new System.Management.ManagementObjectSearcher("SELECT * FROM Win32_OperatingSystem");
- var collection = searcher.Get();
- foreach (var mgtObj in collection)
- {
- os = mgtObj.GetPropertyValue("Caption").ToString();
- break;
- }
- }
- catch (Exception ex) {
- System.Diagnostics.Debug.WriteLine(ex.ToString());
- }
- return os;
- }
- }
这段代码是通过 WMI 查询, 来获得 Caption 信息. 也就是操作系统的版本信息. 由于是 WMI 调用, 所以依赖的关系比较多.
[问题验证]
我们把这段代码抽出来. 下面是一段简短的 Repro 代码:
- static void Main(string[] args)
- {
- Stopwatch watch = new Stopwatch();
- while (true)
- {
- watch.Restart();
- var searcher = new System.Management.ManagementObjectSearcher("SELECT * FROM Win32_OperatingSystem");
- var collection = searcher.Get();
- foreach (var mgtObj in collection)
- {
- string os = mgtObj.GetPropertyValue("Caption").ToString();
- }
- watch.Stop();
- Console.WriteLine(watch.ElapsedMilliseconds);
- if (watch.ElapsedMilliseconds>= 1000)
- {
- Console.WriteLine("-------------");
- File.AppendAllText("abc.txt", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff") +","+ watch.ElapsedMilliseconds + "\r\n");
- }
- }
- }
在有问题的应用服务器上, 我们运行上述代码, 确实可以发现 WMI 查询有超时: 下面这些点是我们抓到的超过 30 秒的点:
- 2017-11-21 17:19:30.208, 33638
- 2017-11-21 17:20:09.193, 33199
- 2017-11-21 17:20:53.086, 33201
- 2017-11-21 17:27:05.114, 32976
- 2017-11-21 17:28:19.178, 33635
- 2017-11-21 17:30:07.130, 65977
- 2017-11-21 17:30:49.051, 40478
- 2017-11-21 17:31:15.126, 26072
- 2017-11-21 17:38:16.048, 66671
- 2017-11-21 17:38:49.204, 33152
- 2017-11-21 17:39:53.161, 33828
- 2017-11-21 17:40:38.121, 33549
- 2017-11-21 17:47:09.179, 33775
- 2017-11-21 17:47:57.174, 33164
[解决思路]
WMI 查询慢, 可能是由于多种原因所致. 如操作系统 CPU 高, 或者查询本身有死锁. 这个问题有待于进一步分析. 但看代码, 我们知道做这个 WMI 查询, 只是为了获得操作系统的信息. 这个信息完全可以缓存起来. 而不必要每次连接的时候, 去进行 WMI 查询.
此处确定该错误的根本原因在于 MySQL 的 C# connector 中对操作系统信息的获取时间过久, 导致触发服务器的连接超时. 注释掉该部分 (可能导致长时间的操作), 进行进一步的验证, 再无任何的超时错误出现.
- public string OSDetails
- {
- get
- {
- dbglog.dolog("MysqlDefs::OSDetails1");
- string os = string.Empty;
- /*try
- {
- var searcher = new System.Management.ManagementObjectSearcher("SELECT * FROM Win32_OperatingSystem");
- var collection = searcher.Get();
- foreach (var mgtObj in collection)
- {
- os = mgtObj.GetPropertyValue("Caption").ToString();
- dbglog.dolog(String.Format("MysqlDefs::OSDetails::foreach{0}", os.ToString()));
- break;
- }
- }
- catch (Exception ex) { System.Diagnostics.Debug.WriteLine(ex.ToString()); }*/
- dbglog.dolog("MysqlDefs::OSDetails2");
- return os;
- }
- }
来源: http://www.linuxidc.com/Linux/2018-12/156001.htm