【本人禿頂程式設計師】一次FastDFS併發問題的排查經歷
←←←←←←←←←←←← 我都禿頂了，還不點關注！
前一段時間，業務部門同事反饋在一次生產伺服器升級之後，POS消費上傳小票業務偶現異常，上傳小票業務有重試機制，有些重試三次也不會成功，他們排查了一下沒有找到原因，希望架構部幫忙解決。
公司使用的是FastDFS來做的圖片伺服器，生產使用了六臺伺服器外加一個儲存，叢集採用的是：2個tracker+4個storage，storage分為兩個group，使用獨立的nginx做檔案代理訪問。各軟體版本資訊如下：
- 作業系統：centos6.9
- FastDFS ：5.05
- libfastcommon：1.0.36
- nginx ：1.7.9
- fastdfs-nginx-module：1.16
為了儘可能的模擬生產，我在測試環境1:1搭建了一套和生產一樣的FastDFS叢集，當時也寫了搭建過程：FastDFS 叢集 安裝 配置
從日誌中找線索
業務部門同事反饋，在一次生產伺服器升級之後，重新搭建了一套FastDFS叢集，然後過了幾天就開始出現上傳小票偶爾失敗的問題。根據這些資訊的反饋，我懷疑是否是FastDFS搭建有問題？這個懷疑點差點把我帶到溝裡去。
我拉取了FastDFS的日誌，tracker伺服器日誌如下：
[2017-09-19 09:13:52] ERROR - file: tracker_nio.c, line: 306, client ip: 192.168.0.1, pkg length: 15150 > max pkg size: 8192 [2017-09-19 10:34:57] ERROR - file: tracker_nio.c, line: 306, client ip: 192.168.0.1, pkg length: 16843 > max pkg size: 8192 [2017-09-19 10:34:57] ERROR - file: tracker_nio.c, line: 306, client ip: 192.168.0.1, pkg length: 16843 > max pkg size: 8192 [2017-09-19 11:31:08] ERROR - file: tracker_nio.c, line: 306, client ip: 192.168.03, pkg length: 23955 > max pkg size: 8192 [2017-09-19 11:42:56] ERROR - file: tracker_nio.c, line: 306, client ip: 192.168.01, pkg length: 12284 > max pkg size: 8192 [2017-09-19 12:10:28] ERROR - file: tracker_service.c, line: 2452, cmd=103, client ip: 192.168.0.3, package size 6258 is too long, exceeds 144
根據tracker的日誌資訊可以看出，不時有一些小票檔案的大小大於最大傳輸值8192，跟著這個線索順著上傳的那條線進行了排查，比如nginx上傳大小的限制，tracker上傳大小的限制，是不是生成的小票出現異常，大小突然變大。麻溜的整了半天得出結論，上傳小票失敗和這個異常沒有關係。
接下來看了下storaged的日誌：
[2017-09-25 14:22:38] WARNING - file: storage_service.c, line: 7135, client ip: 192.168.1.11, logic file: M00/D1/04/wKg5ZlnIoKWAAkNRAAAY86__WXA920.jpg-m not exist [2017-09-25 14:22:39] WARNING - file: storage_service.c, line: 7135, client ip: 192.168.1.11, logic file: M00/D1/04/wKg5ZlnIoKuAUXeVAAAeASIvHGw673.jpg not exist [2017-09-25 14:22:50] ERROR - file: storage_nio.c, line: 475, client ip: 192.168.1.13, recv failed, errno: 104, error info: Connection reset by peer [2017-09-25 14:22:56] ERROR - file: tracker_proto.c, line: 48, server: 192.168.1.11:23001, response status 2 != 0 [2017-09-25 14:23:06] ERROR - file: tracker_proto.c, line: 48, server: 192.168.1.11:23001, response status 2 != 0 [2017-09-25 14:23:11] ERROR - file: storage_service.c, line: 3287, client ip:192.168.1.13, group_name: group2 not correct, should be: group1
除了看到一些檔案不存在的警告和響應狀態不對的錯誤外，也沒有發現其它的異常。
最後來看應用中的錯誤日誌，其中有兩段錯誤日誌引起了我的注意：
第一段日誌如下：
org.csource.common.MyException: body length: 0 <= 16
at org.csource.fastdfs.StorageClient.do_upload_file(StorageClient.java:799)
at org.csource.fastdfs.StorageClient.upload_file(StorageClient.java:208)
at org.csource.fastdfs.StorageClient.upload_file(StorageClient.java:226)
at com.xxx.neo.fastdfs.FileManager.upload(FileManager.java:86)
at com.xxx.neo.controller.QpayUploadSignController.saveSign(QpayUploadSignController.java:84)
at com.xxx.neo.controller.QpayUploadSignController.uploadSign(QpayUploadSignController.java:65)
at com.xxx.neo.controller.QpayUploadSignController$$FastClassByCGLIB$$5debf81b.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
跟了一下fastdfs-client-java中的原始碼的do_upload_file方法，有這麼一段：
ProtoCommon.RecvPackageInfo pkgInfo = ProtoCommon.recvPackage(storageSocket.getInputStream(),
ProtoCommon.STORAGE_PROTO_CMD_RESP, -1);
//省略中間程式碼
if (pkgInfo.body.length <= ProtoCommon.FDFS_GROUP_NAME_MAX_LEN) {
throw new MyException("body length: " + pkgInfo.body.length + " <= " + ProtoCommon.FDFS_GROUP_NAME_MAX_LEN);
}
pkgInfo是封裝好的檔案流資訊，ProtoCommon是fastdfs-client-java中封裝好的引數類，其中FDFS_GROUP_NAME_MAX_LEN的值為16，程式碼的意思就是當讀取的大小小於16位元組的時候，丟擲MyException異常。
第二段日誌如下：
[ INFO] [http://*:8083-69096 2017-09-25 14:07:32] (FileManager.java:upload:92) upload_file time used:76 ms
[ INFO] [http://*:8083-69096 2017-09-25 14:07:32] (FileManager.java:upload:103) upload file successfully!!!group_name:group2, remoteFileName: M00/3C/A8/wKg5Z1nInSOAaHSNAAAdNipAyrQ611.jpg
upload file successfully!!!group_name:group2, remoteFileName: M00/3C/A8/wKg5Z1nInSOAaHSNAAAdNipAyrQ611.jpg
[Ljava.lang.String;@17584701
[ERROR] [http://*:8083-69087 2017-09-25 14:07:32] (FileManager.java:upload:90) Non IO Exception when uploadind the file:520
java.lang.NullPointerException
at org.csource.fastdfs.StorageClient.do_upload_file(StorageClient.java:842)
at org.csource.fastdfs.StorageClient.upload_file(StorageClient.java:208)
at org.csource.fastdfs.StorageClient.upload_file(StorageClient.java:226)
at com.xxx.neo.fastdfs.FileManager.upload(FileManager.java:86)
at com.xxx.neo.controller.QpayUploadSignController.saveSign(QpayUploadSignController.java:84)
at com.xxx.neo.controller.QpayUploadSignController.uploadSign(QpayUploadSignController.java:65)
at com.xxx.neo.controller.QpayUploadSignController$$FastClassByCGLIB$$5debf81b.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:191)
at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
日誌中關於空指標的異常最多，跟蹤了fastdfs-client-java的原始碼，空指標都出現在以下幾段程式碼：
第一處：
...
storageSocket = this.storageServer.getSocket();
ext_name_bs = new byte[ProtoCommon.FDFS_FILE_EXT_NAME_MAX_LEN];
Arrays.fill(ext_name_bs, (byte) 0);
...
第二處：
if (!bNewConnection) {
try {
this.storageServer.close();
} catch (IOException ex1) {
ex1.printStackTrace();
} finally {
this.storageServer = null;
}
第三處：
if (bNewConnection) {
try {
this.storageServer.close();
} catch (IOException ex1) {
ex1.printStackTrace();
} finally {
this.storageServer = null;
}
}
大家有沒有發現這三段程式碼都有一個共同之處？就是存在storageServer變數的使用，並且在呼叫的地方出現了空指標異常，難道fastdfs-client-java有bug？覺得不太可能，畢竟那麼多人使用，會不會是我們使用的版本太舊或者使用方式不對呢?
日誌中的IP地址和公司資訊均已進行脫敏
FastDFS提供的Jar包有問題？
帶著上面的懷疑我準備搞個多執行緒壓測一下，看是不是併發的時候產生的問題。使用CountDownLatch讓執行緒集中執行，程式碼如下：
private static void latchTest() throws InterruptedException {
final CountDownLatch start = new CountDownLatch(1);
final CountDownLatch end = new CountDownLatch(poolSize);
ExecutorService exce = Executors.newFixedThreadPool(poolSize);
for (int i = 0; i < poolSize; i++) {
Runnable run = new Runnable() {
@Override
public void run() {
try {
start.await();
testLoad();
} catch (InterruptedException e) {
e.printStackTrace();
} finally {
end.countDown();
}
}
};
exce.submit(run);
}
start.countDown();
end.await();
exce.shutdown();
}
CountDownLatch是Java多執行緒同步器的四大金剛之一，CountDownLatch能夠使一個執行緒等待其他執行緒完成各自的工作後再執行。
使用Executors.newFixedThreadPool建立固定大小的執行緒池，剛開始設定的是12，每個執行緒執行一萬次上傳請求。
public static void testLoad() {
String filePath="C:\\Users\\xxx\\Pictures\\xz.jpg";
File file=new File(filePath);
String serverUrl="http://localhost:8080/uploadSign";
for (int i=0;i<10000;i++){
HttpClientUtils.uploadFile(file,serverUrl);
}
}
Controller層接到請求後，組裝FastDFSFile進行上傳
....
byte[] file_buff = null;
if(inputStream!=null){
int len1 = inputStream.available();
file_buff = new byte[len1];
inputStream.read(file_buff);
}
FastDFSFile file = new FastDFSFile("520", file_buff, "jpg");
try {
fileAbsolutePath = FileManager.upload(file); //上傳到分散式檔案系統
System.out.println(fileAbsolutePath);
} catch (Exception e1) {
e1.printStackTrace();
}
...
再進行一些封裝之後，最終呼叫fastdfs-client-java的upload_file()方法
....
uploadResults = storageClient.upload_file(file.getContent(), file.getExt(), meta_list);
....
壓測程式碼寫完之後，迫不及待的運行了起來，準備驗證一把，結果非常出意料，剛一啟動就不斷的報空指標異常，看到這個空指標異常我卻一陣歡喜，這個異常和我在生產看到的異常一模一樣。平時最棘手的問題，就是生產偶現測試環境又不能復現的問題，很難定位異常的原因，一旦可以在測試環境復現問題，那就意味著問題解決了一半。
接下來，我將執行緒池的個數減少到6個，啟動測試後還是狂報異常；接著將執行緒數減到2個，每個執行緒數執行的數量由以前的10000改為100個，修改後再進行測試還是報錯；沒辦法改成一個執行緒來執行，果然程式可以正常上傳小票了，確認是併發導致的問題。
這樣可以得出預判，在業務高峰期間產生併發導致部分小票上傳業務失敗，那為什麼這個問題一直沒有發現呢？有兩方面的因素：第一，可能業務初期併發量並不是很高，上傳小票也不是主幹業務，偶爾出現一兩筆失敗也有重試機制來後補；第二，生產環境使用了六臺伺服器做負載，請求被均勻分發到六臺伺服器中，在某種程度上也避免了單臺伺服器的併發量，只有業務併發量進一步擴大才出現明顯的異常。
嘗試著去解決
既然異常都發生在upload_file方法storageServer出現的地方，那麼我們就研究研究這個storageServer是個什麼鬼？storageServer根據屬性名可以看出來，storageServer是上傳檔案的storage儲存節點，每次上傳檔案的時候從trackerServer中獲取。
跟蹤原始碼可以發現，storageServer會在兩個地方進行初始化：第一，在初始化storageClient的時候
storageClient = new StorageClient(trackerServer, storageServer);
這裡的storageServer可以為空；如果為空會自動從trackerServer中獲取，如果需要指定具體的storage可以在這裡進行初始化。
第二，在呼叫do_upload_file()方法開頭中，下面程式碼擷取於do_upload_file()方法。
bUploadSlave = ((group_name != null && group_name.length() > 0) &&
(master_filename != null && master_filename.length() > 0) &&
(prefix_name != null));
if (bUploadSlave) {
bNewConnection = this.newUpdatableStorageConnection(group_name, master_filename);
} else {
bNewConnection = this.newWritableStorageConnection(group_name);
}
try {
storageSocket = this.storageServer.getSocket();
...
在do_upload_file()方法的開頭，會根據條件執行this.newUpdatableStorageConnection(group_name, master_filename)方法或者this.newWritableStorageConnection(group_name)方法，在這兩個方法中都會有對storageServer進行初始化。我們來看newWritableStorageConnection(group_name)方法的原始碼：
/**
* check storage socket, if null create a new connection
*
* @param group_name the group name to upload file to, can be empty
* @return true if create a new connection
*/
protected boolean newWritableStorageConnection(String group_name) throws IOException, MyException {
if (this.storageServer != null) {
return false;
} else {
TrackerClient tracker = new TrackerClient();
this.storageServer = tracker.getStoreStorage(this.trackerServer, group_name);
if (this.storageServer == null) {
throw new MyException("getStoreStorage fail, errno code: " + tracker.getErrorCode());
}
return true;
}
}
這個方法比較簡單，首先判斷storageServer是否進行過初始化，如果沒有初始化，則從tracker中獲取一個可用的storageServer進行初始化。初始化之後do_upload_file()方法會根據拿到的storageServer進行檔案上傳操作。
接下來到了全文最關鍵的地方的了，do_upload_file()方法會在上傳檔案結束的時候，將storageServer關閉並賦值為空，相關程式碼如下：
} catch (IOException ex) {
if (!bNewConnection) {
try {
this.storageServer.close();
} catch (IOException ex1) {
ex1.printStackTrace();
} finally {
this.storageServer = null;
}
}
throw ex;
} finally {
if (bNewConnection) {
try {
this.storageServer.close();
} catch (IOException ex1) {
ex1.printStackTrace();
} finally {
this.storageServer = null;
}
}
}
當然這個邏輯是沒有問題的，每次方法執行的時候獲取一個可用的storageServer，結束的時候進行回收，避免多次請求使用同一個storage。如果程式沒有任何併發這段程式碼是沒有問題的，如果出現併發呢，出現小的併發也不一定會出現問題，當併發量稍微大一點的時候就一定會出現問題，這是為什麼呢？
我們來繼續跟蹤storageServer，發現storageServer是StorageClient類的一個全域性屬性，當併發特別大的時候就有可能出現這樣一個現象：第一個執行緒進這個方法的時候，看到storageServer沒有初始化於是進行賦值並繼續往下執行；這時候第二個執行緒又開始進入這個方法，發現storageServer已經進行了初始化，就不再初始化，繼續往下執行；當第一個執行緒執行結束的時候，將storageServer關閉並賦值為null，然後拍屁股走人了；這個時候可苦逼第二個執行緒了，方法剛剛執行了一半，當需要使用storageServer的時候，才發現storageServer已經被置為了null，於是在使用storageServer的地方都有可能會出現空指標異常，第二個執行緒，在掛掉的時候一定在想，真XX的坑爹。
於是上面的這個故事，過一段時間就偷偷的在我們生產環境中上演。
後面我繼續看了一下StorageClient原始碼，不但是do_upload_file()會存在此問題，StorageClient類中只要這樣使用storageServer的地方都會出現類似的併發問題，如：do_modify_file方法、delete_file方法等等。
那麼既然找到了問題的根因，到底如何解決這個問題呢？解決這個問題的本質就是解決共享變數的併發問題，那解決共享變數併發有哪些手段呢？最常用有加鎖或者使用Threadlocal，看了一下使用Threadlocal進行改造工作量比較大，因此我最後選擇使用了Synchronized同步鎖來解決這個問題，就是在每個使用storageServer方法上面新增一個Synchronized關鍵字。
protected Synchronized String[] do_upload_file()
在github上面將原始碼down下來 fastdfs-client-java，修改完之後再進行壓測，妥妥的再不會報空指標異常類了。
峰迴路轉
大家以為這樣就結束了嗎？當時我也是這樣認為的。後來回頭一想，這樣雖然解決了問題，但是併發數卻急劇降低，FastDFS不會這麼傻吧！肯定還是自己出了問題，第二天將專案中FastDFS使用的程式碼又擼了一遍，果然發現問題了。
FileManager是我們封裝好的FastDFS工具類，在啟動的時候會對storageClient進行初始化，這樣每次專案調研的時候都會複用storageClient例項。
public class FileManager implements FileManagerConfig {
private static StorageClient storageClient;
static {
try {
//省略一部分程式碼
trackerClient = new TrackerClient();
trackerServer = trackerClient.getConnection();
storageClient = new StorageClient(trackerServer, storageServer);
} catch (Exception e) {
logger.error(e);
}
}
}
upload()方法每次會從全域性變數中獲取storageClient進行呼叫，也就意味著每次請求使用的是同一個storageClient例項，當然也包括例項中的變數storageServer。
public static String[] upload(FastDFSFile file) {
try {
uploadResults = storageClient.upload_file(file.getContent(), file.getExt(), meta_list);
} catch (Exception e) {
logger.error("Exception when uploadind the file:" + file.getName(), e);
}
//省略一部分程式碼
return uploadResults;
}
如果我將上面的 upload()方法改造成下面這樣呢：
public static String[] upload(FastDFSFile file) {
try {
StorageClient storageClient = new StorageClient(trackerServer, storageServer);
uploadResults = storageClient.upload_file(file.getContent(), file.getExt(), meta_list);
} catch (Exception e) {
logger.error("Exception when uploadind the file:" + file.getName(), e);
}
//省略一部分程式碼
return uploadResults;
}
重點是添加了這段程式碼：
StorageClient storageClient = new StorageClient(trackerServer, storageServer);
也就是說，每次呼叫的時候會重新new一個StorageClient()例項，這樣每次請求拿到的就是不同的StorageClient，也就意味著每個請求會獲取到不同的storageServer，這樣就不存在共享變數，也就避免了出現併發的空指標問題。
根據上面的分析可以看出，最好的解決方案就是每次呼叫的時候new一個新的例項去使用。也提醒大家在使用FastDFS的時候，儘量不要重用StorageClient！
後來我在github上面給FastDFS提交了pull來說明這個問題，有一個網友也給出了同樣的理解：解決併發空指標問題 ；文中的測試程式碼我放到了這裡：spring-examples，感興趣的同學可以繼續去了解。
最後
問題終於解決了，雖然走了彎路，卻讓我對FastDFS有了更深的認識。平時解決問題也經常會這樣，有時候排查了整整一天，才發現原來是某個非常低階錯誤導致的，這就是程式設計師的正常工作。
研究發現，在所有報告的錯誤中，大約有95%是由程式設計師造成的，2%是由系統軟體（編譯器和作業系統）造成的，2%是由其他軟體造成的，1%是由硬體造成的。因此不要懷疑人生、出現什麼奇蹟、發生某些詭異的事情，那是不會發生的。
要相信程式設計的第一法則：永遠都是你的錯！
你應該知道那種感覺。我們所有人都曾碰到過這樣的事情：已經盯著程式碼看了無數遍，但還是沒有發現任何問題。然而，有個故障或者錯誤始終揮之不去。於是你開始懷疑，可能是你開發程式所用的那臺機器出了問題，也可能是作業系統的問題，或者是你使用的工具和庫出了問題。肯定是它們的原因！
然而，無論你多麼絕望，都不要往那條路上走。沿著那條路下去就是薛定諤的貓和靠運氣程式設計。
總是要處理一些困難的、捉摸不透的問題，這是一件令人絕望的事情，但是不要讓絕望領著你誤入歧途。作為一名謙遜的程式設計師，最基本的要求就是要有意識：你寫的程式碼在任何時候出了問題，那一定都是你的錯。
寫在最後：
禿頂程式設計師的不易，看到這裡，點了關注吧！
點關注，不迷路，持續更新！！！