一次慢请求优化

前言

最近的项目中，有一个用户数据导入的需求，导入的数据量大致应该是几百条左右。 但是由于每条用户数据都包含有其它子数据，并需要对这些数据进行单一处理，所以 预期处理时间比较长。

在完成接口之后，进行测试，大致在2秒左右可以完成300条左右数据导入，基本符合预期。

由于最近项目上了opentracing这个性能监控工具，所以想找一找倒底是哪里出现处理时间过长的问题。

性能预估

首先预估了一下可能会出现处理慢的两处地方：数据转换、数据存储。

猜测理由：

• 数据转换
  因为每一条用户数据可能需要10多次处理，每条处理规则可能不同，所以造成总数据处理时间会很长。

• 数据存储
  因为数据总量比较大，所以入库时候可能会比较慢。由于在应用层进行了数据拼接，所以入库时间应该不会特别慢。但是，可能会出现SQL过长的问题。

压力测试

首先，对可能出现慢处理的地方做了压力测试。

用户数据转换:

BenchmarkEntry2User   	   20000	     73788 ns/op

可以看到，这里的每一条用户数据转换大概需要的时间为: 73788ns = 73.788µs = 0.073ms，速度非常快。 这里的结果有点出乎意外，本以为会处理比较慢的地方，其实处理非常快。

在相应代码处添加上opentracing的监控代码后，得到请求图如下：

可以看到，请求图上效果与压力测试基本一致，用户转换花费时间并不长。而数据存储入库的时间明显不正常。

猜想优化

由于数据存储时间很长，所以很简单地认为是数据库出现了问题，对数据库进行一系列的优化。 然而，优化之后几乎没有任何效果。由于原数据是拼接而成的，于是猜想可能是SQL过长过大问题导致的。 将SQL改成事务后，依然没有任何积极的效果，反而进一步拉长了存储时间。

分析代码

由于对数据库进行优化没有收到任何效果，让我把目光再一次放到了代码上面。 经过仔细分析，发现了一条可能会比较耗时的操作：

user.Salt = utils.GenSalt()
pass := utils.GenPassword()
user.Password = utils.EncryptPassword(pass, user.Salt)

这里会对每一个导入的用户随机生成用户密码和盐，然后还有一次加密处理。

对EncryptPassword这个函数进行压测可得:

BenchmarkEncryptPassword   	     500	   3514588 ns/op

由上可知，每一次加密动作耗时为: 3514588ns = 3514.588µs = 3.514588ms。 可知每一次加密需要耗时约3ms，而300个用户耗时可能接近1s。由于测试服务器性能相对于开发机更弱， 所以耗时轻松达到1s以上。至此，问题已然大白。

修正问题

在正确定位问题后，即可对症下药。 经过修改，事务型存储结果如下：

而通过拼接SQL存储结果如下：

其它

本次优化过程中使用到的相关东西：

• Opentracing 与 Opentracing-Go
• Zipkin 与 Zipkin-Go
• Golang Test Benchmark