那必定都是你的錯！- 一次FastDFS併發問題的排查經歷

時間  2019-11-30
標籤 必定 都是 一次 fastdfs 併發 問題 排查 經歷 欄目 職業生涯 简体版
原文   原文鏈接

前一段時間，業務部門同事反饋在一次生產服務器升級以後，POS消費上傳小票業務偶現異常，上傳小票業務有重試機制，有些重試三次也不會成功，他們排查了一下沒有找到緣由，但願架構部幫忙解決。html

公司使用的是FastDFS來作的圖片服務器，生產使用了六臺服務器外加一個存儲，集羣採用的是：2個tracker+4個storage，storage分爲兩個group，使用獨立的nginx作文件代理訪問。各軟件版本信息以下：java

  • 操做系統：centos6.9
  • FastDFS ：5.05
  • libfastcommon：1.0.36
  • nginx ：1.7.9
  • fastdfs-nginx-module：1.16

爲了儘量的模擬生產，我在測試環境1:1搭建了一套和生產同樣的FastDFS集羣，當時也寫了搭建過程：FastDFS 集羣 安裝 配置nginx


從日誌中找線索

業務部門同事反饋，在一次生產服務器升級以後，從新搭建了一套FastDFS集羣，而後過了幾天就開始出現上傳小票偶爾失敗的問題。根據這些信息的反饋，我懷疑是不是FastDFS搭建有問題？這個懷疑點差點把我帶到溝裏去。git

我拉取了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上傳大小的限制，是否是生成的小票出現異常，大小忽然變大。麻溜的整了半天得出結論，上傳小票失敗和這個異常沒有關係。github

接下來看了下storaged的日誌：spring

[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

除了看到一些文件不存在的警告和響應狀態不對的錯誤外，也沒有發現其它的異常。編程

最後來看應用中的錯誤日誌，其中有兩段錯誤日誌引發了個人注意：centos

第一段日誌以下：服務器

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有了更深的認識。平時解決問題也常常會這樣，有時候排查了整整一天，才發現原來是某個很是低級錯誤致使的，這就是程序員的正常工做。其實淘寶也有一個版本的FastDFS客戶端，地址在這裏FastDFS_Client。而且提供了更多的功能支持，好比斷點續傳、鏈接池等，推薦你們使用這個版本。

研究發現，在全部報告的錯誤中，大約有95%是由程序員形成的，2%是由系統軟件（編譯器和操做系統）形成的，2%是由其餘軟件形成的，1%是由硬件形成的。所以不要懷疑人生、出現什麼奇蹟、發生某些詭異的事情，那是不會發生的。

要相信編程的第一法則：永遠都是你的錯！

你應該知道那種感受。咱們全部人都曾碰到過這樣的事情：已經盯着代碼看了無數遍，但仍是沒有發現任何問題。然而，有個故障或者錯誤始終揮之不去。因而你開始懷疑，多是你開發程序所用的那臺機器出了問題，也多是操做系統的問題，或者是你使用的工具和庫出了問題。確定是它們的緣由！

然而，不管你多麼絕望，都不要往那條路上走。沿着那條路下去就是薛定諤的貓和靠運氣編程。

老是要處理一些困難的、捉摸不透的問題，這是一件使人絕望的事情，可是不要讓絕望領着你誤入歧途。做爲一名謙遜的程序員，最基本的要求就是要有意識：你寫的代碼在任什麼時候候出了問題，那必定都是你的錯。

留言分享你最波折的一次排查問題經歷。

法則參考：The First Rule of Programming: It's Always Your Fault

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程