性能分析之死锁和日志（一个实例）

Posted 2021-05-01 7DGroup

这个例子在做性能测试的时候出现的。

团队在做性能测试，其实量并不大。只是我觉得没有什么明显的结果，于是我就自己把脚本拿来跑了一下。感觉怎么那么慢呢？

20 vusers：

40 vusers：

除了时间增加了，其他都没啥变化。系统资源也没上去。

当然，还有报错。

然后我就乐呵呵的找日志去了。

但是日志吧？唉，真是看不下去，那写的叫一个乱。于是我把我们的架构师小树林给拉进来了，让他看日志去（我这边就叫一个清闲，哈哈）。

看着看着，一开始吧，资源都用不上去。原因是在云服务器上用了公网iP。这种的插曲，我都不乐意截图说明了，问题低级。

修改成内网IP之后，流量就能上来了，但是还是不乐观。 

于是开始找新问题。

在性能分析的过程中一定要记得的事情是：找到时间消耗在哪。 

找的手段和过程在每个系统中都会不一样，我就不再描述了。

当小树林找到这里的时候，基本上问题点就清晰了。

20 vusers: 

 40 vusers:

数据库耗时增加了。同时也看到了如下专业的错误提示：

### Cause:com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlockfound when trying to get lock; try restarting transaction; SQL []; Deadlock found when trying to getlock; try restarting transaction; 

要知道死锁是很容易看出来的，但是数据库日志中居然没报日志。

当小树林发这个给我看的时候，我就两字怼回去：不信。 

我要能看到具体的死锁日志，谁锁了谁，为啥要死锁呢，多大的仇呢？

于是让小树林接着折腾，他查了代码逻辑是有问题的。

简单来说，就是之前这个事务是直接做update，不管有没有记录，这就导致在mysql中当没有记录时会产生X-gap锁，这时候接着做insert，但是insert还没有做完的时候；另一个session的update、insert又开始了，这个session同样没有记录，又要加X-Gap锁。于是死锁信息出现了。

其实这个吧，有开发经验的应该都知道这种的处理逻辑。

在这个例子中，当然修改不止这些。其他还有修改的是：

1. 索引。这个索引的修改并没有引起性能的飙升，所以就不再细说了。

2. 日志。日志是影响性能的很重要也是很常见的因素，尽量把日志合理的写出去，又小又巧的日志是最合理的。

3. 一些参数啥的。
   

然后，再看下测试的结果。

每秒请求数可以到400左右了。

这时候系统资源也用起来了。

性能分析吧，在每一个细节的事情里，几乎都是要关注的。现在工作中遇到的性能问题已经没有什么新鲜的了，让我都快没了写文章的欲望。

但是耐心还是很重要的，要不然就会像老司机一样开车不看路了。 

2018年给自己定了计划，就是要写不少于50篇技术文章，同时要开始写管理相关的文章，把自己的管理思路也理理顺。 

PS：本文版权归本人及小树林共同拥有。