记一次线上产品的性能问题的分析

生产环境上有个调用很频繁的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也会用到，但这段代码实在是性能瓶颈，需要重构。