FastDFS并發(fā)會有bug,其實我也不太信?- 一次并發(fā)問題的排查經(jīng)歷
前一段時間,業(yè)務部門同事反饋在一次生產(chǎn)服務器升級之后,POS消費上傳小票業(yè)務偶現(xiàn)異常,上傳小票業(yè)務有重試機制,有些重試三次也不會成功,他們排查了一下沒有找到原因,希望架構(gòu)部幫忙解決。
公司使用的是FastDFS來做的圖片服務器,生產(chǎn)使用了六臺服務器外加一個存儲,集群采用的是:2個tracker+4個storage,storage分為兩個group,使用獨立的nginx做文件代理訪問。各軟件版本信息如下:
- 操作系統(tǒng):centos6.9
- FastDFS :5.05
- libfastcommon:1.0.36
- nginx :1.7.9
- fastdfs-nginx-module:1.16
為了盡可能的模擬生產(chǎn),我在測試環(huán)境1:1搭建了一套和生產(chǎn)一樣的FastDFS集群,當時也寫了搭建過程:FastDFS 集群 安裝 配置
從日志中找線索
業(yè)務部門同事反饋,在一次生產(chǎn)服務器升級之后,重新搭建了一套FastDFS集群,然后過了幾天就開始出現(xiàn)上傳小票偶爾失敗的問題。根據(jù)這些信息的反饋,我懷疑是否是FastDFS搭建有問題?這個懷疑點差點把我?guī)У綔侠锶ァ?/p>
我拉取了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
根據(jù)tracker的日志信息可以看出,不時有一些小票文件的大小大于最大傳輸值8192,跟著這個線索順著上傳的那條線進行了排查,比如nginx上傳大小的限制,tracker上傳大小的限制,是不是生成的小票出現(xiàn)異常,大小突然變大。麻溜的整了半天得出結(jié)論,上傳小票失敗和這個異常沒有關(guān)系。
接下來看了下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
除了看到一些文件不存在的警告和響應狀態(tài)不對的錯誤外,也沒有發(fā)現(xiàn)其它的異常。
最后來看應用中的錯誤日志,其中有兩段錯誤日志引起了我的注意:
第一段日志如下:
- 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中的源碼的douploadfile方法,有這么一段:
- 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中封裝好的參數(shù)類,其中FDFSGROUPNAMEMAXLEN的值為16,代碼的意思就是當讀取的大小小于16字節(jié)的時候,拋出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)
日志中關(guān)于空指針的異常最多,跟蹤了fastdfs-client-java的源碼,空指針都出現(xiàn)在以下幾段代碼:
第一處:
- ...
- 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;
- }
- }
大家有沒有發(fā)現(xiàn)這三段代碼都有一個共同之處?就是存在storageServer變量的使用,并且在調(diào)用的地方出現(xiàn)了空指針異常,難道fastdfs-client-java有bug?覺得不太可能,畢竟那么多人使用,會不會是我們使用的版本太舊或者使用方式不對呢?
日志中的IP地址和公司信息均已進行脫敏
FastDFS提供的Jar包有問題?
帶著上面的懷疑我準備搞個多線程壓測一下,看是不是并發(fā)的時候產(chǎn)生的問題。使用CountDownLatch讓線程集中執(zhí)行,代碼如下:
- 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能夠使一個線程等待其他線程完成各自的工作后再執(zhí)行。
使用Executors.newFixedThreadPool創(chuàng)建固定大小的線程池,剛開始設置的是12,每個線程執(zhí)行一萬次上傳請求。
- 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); //上傳到分布式文件系統(tǒng)
- System.out.println(fileAbsolutePath);
- } catch (Exception e1) {
- e1.printStackTrace();
- }
- ...
再進行一些封裝之后,最終調(diào)用fastdfs-client-java的 upload_file()方法
- ....
- uploadResults = storageClient.upload_file(file.getContent(), file.getExt(), meta_list);
- ....
-
壓測代碼寫完之后,迫不及待的運行了起來,準備驗證一把,結(jié)果非常出意料,剛一啟動就不斷的報空指針異常,看到這個空指針異常我卻一陣歡喜,這個異常和我在生產(chǎn)看到的異常一模一樣。平時最棘手的問題,就是生產(chǎn)偶現(xiàn)測試環(huán)境又不能復現(xiàn)的問題,很難定位異常的原因,一旦可以在測試環(huán)境復現(xiàn)問題,那就意味著問題解決了一半。
接下來,我將線程池的個數(shù)減少到6個,啟動測試后還是狂報異常;接著將線程數(shù)減到2個,每個線程數(shù)執(zhí)行的數(shù)量由以前的10000改為100個,修改后再進行測試還是報錯;沒辦法改成一個線程來運行,果然程序可以正常上傳小票了,確認是并發(fā)導致的問題。
這樣可以得出預判,在業(yè)務高峰期間產(chǎn)生并發(fā)導致部分小票上傳業(yè)務失敗,那為什么這個問題一直沒有發(fā)現(xiàn)呢?有兩方面的因素:第一,可能業(yè)務初期并發(fā)量并不是很高,上傳小票也不是主干業(yè)務,偶爾出現(xiàn)一兩筆失敗也有重試機制來后補;第二,生產(chǎn)環(huán)境使用了六臺服務器做負載,請求被均勻分發(fā)到六臺服務器中,在某種程度上也避免了單臺服務器的并發(fā)量,只有業(yè)務并發(fā)量進一步擴大才出現(xiàn)明顯的異常。
嘗試著去解決
既然異常都發(fā)生在upload_file方法storageServer出現(xiàn)的地方,那么我們就研究研究這個storageServer是個什么鬼?storageServer根據(jù)屬性名可以看出來,storageServer是上傳文件的storage存儲節(jié)點,每次上傳文件的時候從trackerServer中獲取。
跟蹤源碼可以發(fā)現(xiàn),storageServer會在兩個地方進行初始化:第一,在初始化storageClient的時候
- storageClient = new StorageClient(trackerServer, storageServer);
這里的storageServer可以為空;如果為空會自動從trackerServer中獲取,如果需要指定具體的storage可以在這里進行初始化。
第二,在調(diào)用 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()方法的開頭,會根據(jù)條件運行 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進行初始化。初始化之后douploadfile()方法會根據(jù)拿到的storageServer進行文件上傳操作。
接下來到了全文最關(guān)鍵的地方的了,douploadfile()方法會在上傳文件結(jié)束的時候,將storageServer關(guān)閉并賦值為空,相關(guān)代碼如下:
- } 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;
- }
- }
- }
當然這個邏輯是沒有問題的,每次方法執(zhí)行的時候獲取一個可用的storageServer,結(jié)束的時候進行回收,避免多次請求使用同一個storage。如果程序沒有任何并發(fā)這段代碼是沒有問題的,如果出現(xiàn)并發(fā)呢,出現(xiàn)小的并發(fā)也不一定會出現(xiàn)問題,當并發(fā)量稍微大一點的時候就一定會出現(xiàn)問題,這是為什么呢?
我們來繼續(xù)跟蹤storageServer,發(fā)現(xiàn)storageServer是StorageClient類的一個全局屬性,當并發(fā)特別大的時候就有可能出現(xiàn)這樣一個現(xiàn)象:第一個線程進這個方法的時候,看到storageServer沒有初始化于是進行賦值并繼續(xù)往下執(zhí)行;這時候第二個線程又開始進入這個方法,發(fā)現(xiàn)storageServer已經(jīng)進行了初始化,就不再初始化,繼續(xù)往下執(zhí)行;當?shù)谝粋€線程執(zhí)行結(jié)束的時候,將storageServer關(guān)閉并賦值為null,然后拍屁股走人了;這個時候可苦逼第二個線程了,方法剛剛執(zhí)行了一半,當需要使用storageServer的時候,才發(fā)現(xiàn)storageServer已經(jīng)被置為了null,于是在使用storageServer的地方都有可能會出現(xiàn)空指針異常,第二個線程,在掛掉的時候一定在想,真XX的坑爹。
于是上面的這個故事,過一段時間就偷偷的在我們生產(chǎn)環(huán)境中上演。
后面我繼續(xù)看了一下StorageClient源碼,不但是douploadfile()會存在此問題,StorageClient類中只要這樣使用storageServer的地方都會出現(xiàn)類似的并發(fā)問題,如:domodifyfile方法、delete_file方法等等。
那么既然找到了問題的根因,到底如何解決這個問題呢?解決這個問題的本質(zhì)就是解決共享變量的并發(fā)問題,那解決共享變量并發(fā)有哪些手段呢?最常用有加鎖或者使用Threadlocal,看了一下使用Threadlocal進行改造工作量比較大,因此我最后選擇使用了Synchronized同步鎖來解決這個問題,就是在每個使用storageServer方法上面添加一個Synchronized關(guān)鍵字。
- protected Synchronized String[] do_upload_file()
在github上面將源碼down下來 fastdfs-client-java,修改完之后再進行壓測,妥妥的再不會報空指針異常類了。
峰回路轉(zhuǎn)
大家以為這樣就結(jié)束了嗎?當時我也是這樣認為的。后來回頭一想,這樣雖然解決了問題,但是并發(fā)數(shù)卻急劇降低,F(xiàn)astDFS不會這么傻吧!肯定還是自己出了問題,第二天將項目中FastDFS使用的代碼又擼了一遍,果然發(fā)現(xiàn)問題了。
FileManager是我們封裝好的FastDFS工具類,在啟動的時候會對storageClient進行初始化,這樣每次項目調(diào)研的時候都會復用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進行調(diào)用,也就意味著每次請求使用的是同一個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;
- }
-
重點是添加了這段代碼: StorageClientstorageClient=newStorageClient(trackerServer,storageServer);
也就是說,每次調(diào)用的時候會重新new一個StorageClient()實例,這樣每次請求拿到的就是不同的StorageClient,也就意味著每個請求會獲取到不同的storageServer,這樣就不存在共享變量,也就避免了出現(xiàn)并發(fā)的空指針問題。
根據(jù)上面的分析可以看出,最好的解決方案就是每次調(diào)用的時候new一個新的實例去使用。也提醒大家在使用FastDFS的時候,盡量不要重用StorageClient!
后來我在github上面給FastDFS提交了pull來說明這個問題,有一個網(wǎng)友也給出了同樣的理解:解決并發(fā)空指針問題 (https://github.com/happyfish100/fastdfs-client-java/pull/28);文中的測試代碼我放到了這里:(https://github.com/ityouknow/spring-examples),感興趣的同學可以繼續(xù)去了解。
最后
問題終于解決了,雖然走了彎路,卻讓我對FastDFS有了更深的認識。平時解決問題也經(jīng)常會這樣,有時候排查了整整一天,才發(fā)現(xiàn)原來是某個非常低級錯誤導致的,這就是程序員的正常工作。其實淘寶也有一個版本的FastDFS客戶端,地址在這里(https://github.com/tobato/FastDFS_Client)。并且提供了更多的功能支持,比如斷點續(xù)傳、連接池等,推薦大家使用這個版本。
研究發(fā)現(xiàn),在所有報告的錯誤中,大約有95%是由程序員造成的,2%是由系統(tǒng)軟件(編譯器和操作系統(tǒng))造成的,2%是由其他軟件造成的,1%是由硬件造成的。因此不要懷疑人生、出現(xiàn)什么奇跡、發(fā)生某些詭異的事情,那是不會發(fā)生的。
要相信編程的第一法則:永遠都是你的錯!
你應該知道那種感覺。我們所有人都曾碰到過這樣的事情:已經(jīng)盯著代碼看了無數(shù)遍,但還是沒有發(fā)現(xiàn)任何問題。然而,有個故障或者錯誤始終揮之不去。于是你開始懷疑,可能是你開發(fā)程序所用的那臺機器出了問題,也可能是操作系統(tǒng)的問題,或者是你使用的工具和庫出了問題??隙ㄊ撬鼈兊脑?!
然而,無論你多么絕望,都不要往那條路上走。沿著那條路下去就是薛定諤的貓和靠運氣編程。
總是要處理一些困難的、捉摸不透的問題,這是一件令人絕望的事情,但是不要讓絕望領著你誤入歧途。作為一名謙遜的程序員,最基本的要求就是要有意識:你寫的代碼在任何時候出了問題,那一定都是你的錯。
【本文為51CTO專欄作者“純潔的微笑”的原創(chuàng)稿件,轉(zhuǎn)載請通過微信公眾號聯(lián)系作者獲取授權(quán)】