那一定都是你的错!- 一次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 F a s t C l a s s B y C G L I B FastClassByCGLIB FastClassByCGLIB5debf81b.invoke()
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 F a s t C l a s s B y C G L I B FastClassByCGLIB FastClassByCGLIB5debf81b.invoke()
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个,修改后再进行测试还是报错;没办法改成一个线程来运行,果然程序可以正常上传小票了,确认是并发导致的问题。
这样可以得出预判,在业务高峰期间产生并发导致部分小票上传业务失败,那为什么这个问题一直没有发现呢?有两方面的因素:第一,可能业务初期并发量并不是很高,上传小票也不是主干业务,偶尔出现一两笔失败也有重试机制来后补;