记一次线上产品的性能问题的分析
生产环境上有个调用很频繁的service,性能不太好。表现为平均500次调用有5,6次极慢以至于客户端超时,也就是说失败率为百分之一。在高并发的情况下尤其明显。
这个问题摆到了我的面前。暂且叫这个service为A吧
还有什么办法,从日志入手吧。
首先,从海量日志中过滤出有关A的调用,方法很多,我用了vim中的正则表达式匹配,这个问题按下不表,以后有机会再专门谈正则表达式。过滤出来的日志记录了A的调用发生时间,结束时间,调用状态,SessionID等重要信息。
第二,分析一下吧,该服务从晚上22:15:37开始,到22:20:01结束,一共不到五分钟
总调用数: |
491 |
平均值: |
8.185484 |
标准差: |
17.575592 |
小于5秒的调用数: |
421 |
大于5秒的调用数: |
70 |
调用失败的个数 |
6 |
最小调用时间: |
0.32004 |
最大调用时间 |
64.9905 |
这不到5分钟的时间里,发生了近500次的调用,其中调用时间正常的有421次,绝大部分的调用时间都在0到2秒以内。其中有6次失败为数据库失败,出错信息为:1) failed: [GetCustomer] failed: Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.
继续分析日志,可以得出,在数据库出错先后,服务调用的返回时间在30秒和60秒这个量级,远远高于正常水平。
<!--[endif]-->
地方又发现,该服务A返回时间的长短和并发数量有显著的关系。
该图的横轴是时间轴,纵轴的指标有两个,蓝色代表服务执行的时间,红色代表并发量,由图上可以看到,两个阶段服务时间的延迟是由于并发量突然增大而导致。
第三,分析代码
为啥在并发量突然增大的情况下,该服务的调用时间会有指数级别的增加?还得回到代码分析。
这段代码首先关闭当前的Customer,在根据已经有的参数重新装入。此处用了C#锁的机制,根据UserId和CustomerId来限制进入这段代码的线程数量。但由于不同的User打开的Customer不一定相同,所以应该不能限制访问该代码的线程数量,于是大量的数据库请求涌入数据库连接池。CloseCustomer与LoadCustomer都是非常费是时的操作,导致许多线程得不到数据库连接,处于等待状态,甚至超时,失败返回。
结论,
根据以上分析,我给出了两个结论
1. 增大数据库连接池的大小
2. LoadCustomer不但本Service要用,其他的Service也会用到,但这段代码实在是性能瓶颈,需要重构。