【問(wèn)題描述】

在應(yīng)用端，偶爾看到有如下報(bào)錯(cuò)：

Authentication to host 'xxxx' for user 'yyyy' using method 'mysql_native_password' failed with message: Reading from the stream has failed.

表現(xiàn)特征：

    1.只有用Connector/NET 出現(xiàn)這個(gè)問(wèn)題， 用JDBC驅(qū)動(dòng)沒(méi)有類(lèi)似問(wèn)題。

    2.多臺(tái)應(yīng)用服務(wù)器，只有一臺(tái)報(bào)這個(gè)錯(cuò)，因此可以排除服務(wù)器端的問(wèn)題。

    3.問(wèn)題非常隨機(jī)，重啟一下服務(wù)器/IIS，就能臨時(shí)解決問(wèn)題。

    4.有一些場(chǎng)景應(yīng)用服務(wù)器CPU并不是很高，也會(huì)偶爾拋出這個(gè)錯(cuò)來(lái)。

客戶端是Windows機(jī)器， 驅(qū)動(dòng)是MySQL Connector ADO.NET Driver for MySQL (Connector/NET) ，使用的版本是6.9.9，是比較新的版本。

下面話不多說(shuō)了，來(lái)一起看看詳細(xì)的分析與解決思路吧

【問(wèn)題分析】

我們?cè)趹?yīng)用服務(wù)器端和數(shù)據(jù)庫(kù)端抓包。兩邊抓到的包是一致的?？梢耘懦W(wǎng)絡(luò)問(wèn)題。下面是抓到的包，以及時(shí)間點(diǎn)：

從上述網(wǎng)絡(luò)包的交互來(lái)看， 前面三個(gè)包是TCP的三次握手協(xié)議。問(wèn)題出在第六個(gè)包，數(shù)據(jù)庫(kù)服務(wù)器向應(yīng)用服務(wù)器發(fā)送了一個(gè)Finish包，來(lái)終止數(shù)據(jù)庫(kù)的連接。數(shù)據(jù)庫(kù)發(fā)送Finish包，是由于數(shù)據(jù)庫(kù)端發(fā)現(xiàn)連接超時(shí)而發(fā)送的。 這是由服務(wù)器端的Connect_timeout這個(gè)變量來(lái)控制。原因在于應(yīng)用端超過(guò)10秒未向數(shù)據(jù)庫(kù)服務(wù)器端發(fā)送網(wǎng)絡(luò)包。從網(wǎng)絡(luò)包交互的情況來(lái)看，第五個(gè)包和第六個(gè)包的時(shí)間間隔剛好是10秒。

對(duì)比正常的數(shù)據(jù)庫(kù)連接和上面異常的數(shù)據(jù)庫(kù)連接。 應(yīng)用服務(wù)器發(fā)送第5個(gè)包到數(shù)據(jù)庫(kù)端后， 應(yīng)該緊接著發(fā)送下面的網(wǎng)絡(luò)包到數(shù)據(jù)庫(kù)端的。這個(gè)包主要是發(fā)送賬號(hào)，驅(qū)動(dòng)版本，操作系統(tǒng)信息等到數(shù)據(jù)庫(kù)服務(wù)器端?！鞠旅媸遣糠值恼５木W(wǎng)絡(luò)包截圖】。在出現(xiàn)異常報(bào)錯(cuò)的場(chǎng)景，客戶端是延遲發(fā)送這個(gè)包的。在Frame 8才發(fā)送的。而此時(shí)連接已經(jīng)被Finish了，在Frame 9，數(shù)據(jù)庫(kù)端發(fā)送了一個(gè)Reset包到應(yīng)用服務(wù)器，徹底中斷連接。

我們現(xiàn)在具體分析，為何客戶端發(fā)送賬號(hào)，驅(qū)動(dòng)版本，操作系統(tǒng)信息到數(shù)據(jù)庫(kù)端這么慢。這部分的代碼在Connector/NET MySQLAuthenticationPlugin.cs文件中。 我們修改這部分代碼，進(jìn)行時(shí)間埋點(diǎn)，來(lái)進(jìn)一步定位問(wèn)題。下面是根據(jù)時(shí)間埋點(diǎn)，打印出來(lái)的跟蹤信息。

從跟蹤的Trace來(lái)看，有30秒左右的操作延時(shí)。返回MySQLDefs::OSDetails的時(shí)候。這部分代碼如下：

[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;

}

}

這段代碼是通過(guò)WMI查詢(xún)，來(lái)獲得Caption信息。也就是操作系統(tǒng)的版本信息。由于是WMI調(diào)用，所以依賴(lài)的關(guān)系比較多。

【問(wèn)題驗(yàn)證】

我們把這段代碼抽出來(lái)。下面是一段簡(jiǎn)短的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");

}

}

}

在有問(wèn)題的應(yīng)用服務(wù)器上，我們運(yùn)行上述代碼，確實(shí)可以發(fā)現(xiàn)WMI查詢(xún)有超時(shí)：下面這些點(diǎn)是我們抓到的超過(guò)30秒的點(diǎn)：

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查詢(xún)慢，可能是由于多種原因所致。如操作系統(tǒng)CPU高，或者查詢(xún)本身有死鎖。這個(gè)問(wèn)題有待于進(jìn)一步分析。但看代碼，我們知道做這個(gè)WMI查詢(xún)，只是為了獲得操作系統(tǒng)的信息。這個(gè)信息完全可以緩存起來(lái)。而不必要每次連接的時(shí)候，去進(jìn)行WMI查詢(xún)。

此處確定該錯(cuò)誤的根本原因在于MySQL的C# connector中對(duì)操作系統(tǒng)信息的獲取時(shí)間過(guò)久，導(dǎo)致觸發(fā)服務(wù)器的連接超時(shí)。注釋掉該部分（可能導(dǎo)致長(zhǎng)時(shí)間的操作），進(jìn)行進(jìn)一步的驗(yàn)證，再無(wú)任何的超時(shí)錯(cuò)誤出現(xiàn)。

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;
}
}

總結(jié)

以上就是這篇文章的全部?jī)?nèi)容了，希望本文的內(nèi)容對(duì)大家的學(xué)習(xí)或者工作具有一定的參考學(xué)習(xí)價(jià)值，如果有疑問(wèn)大家可以留言交流，謝謝大家對(duì)腳本之家的支持。

最新評(píng)論