讲个故事：关于一次接口性能优化的心里路程

这是一个程序猿写的第一个故事，请各位懂行的客官静下心来，慢慢品读。就知道我为什么要单独写一个文章来记录这次过程了，因为实在是太坎坷了......

背景介绍

近期项目投产时遇到一个问题，投产后在验证时发现大部分用户系统登录非常慢。由于没有找到具体原因。只能回退到投产前的版本。

后来通过分析生产的日志，发现是登录接口中有段代码涉及到频繁切换数据源,这段代码耗时比较长。

到这里我先简单说下项目，用到oracle和gbase数据库,oracle数据库和业务相关，gbase数据库主要用来存在一些日志的。默认数据源是oracle。项目的一个filter里会把所有请求后台接口的相关信息记录在gbase库中，另外登录接口也会把登录成功与否的情况也记录在gbase库。

比较耗时的代码就是登录接口有两处分别向gbase库不同表写日志,每次都需要先切换到gbase，写完要切回oracle数据源，而且这2个逻辑紧挨着。所以这里就会4次切换数据源。本次投产增加了其中一次向gbase写库，还有就是本次投产filter向gbase写库的逻辑。

到这里，基本所有背景交代完了。我先把这次投产向gbase写库的代码注释了。发现登录耗时确实下来了。通过工具性能压测响应时间下来了，但是tps非常低，不到10。这个接口优化路程才真正开始了.........

#排查过程#

第一季：老子代码没问题，怀疑网络节点限流

我们去掉了一次想gbase写库的逻辑，也就减少了2切换数据源,还剩一次原代码就保留的写gbase库。但是发现这个写gbase还是比较耗时，大概900ms左右，其他业务代码耗时200ms。我就加了线程池，把写gbase库的逻辑放到线程里，包括2次切换数据源。按理说这时候tps会提升不少，结果出人意料，tps还不到10.还是很低。（这里压测的都是测试环境的登录接口。并发量分别50、100、150）测试人员各种并发量压测，tps都是非常低。

到这里开始怀疑不是代码问题，是不是pod之外的网络节点(比如F5)做了限制。为了验证这个想法我让测试人员在测试环境压测健康检查的接口，健康检查接口非常简单，没有数据库交互，直接返回固定的字符串。竟然发现这个健康检查接口压测的tps也是不到10。这更坚定了我猜测的中间网络节点限流了。健康检查接口的tps都不到10，这肯定是网络节点限流了啊。

后来通过找相关人员，得到结论F5没有限制任何请求。我靠，奔溃了，那问题在哪啊？？？？？？

这时突然想起，以前的一个同事给项目在filter加过一个流控。（好像发现了新大陆），经过了解这个流控的阈值是每秒请求1000。我们的还不到10呢，人家流控肯本限制不了我们，但是还是不死心，把流控的代码逻辑注释了，果然tps还是很低，和流控没有任何关系.........

第二季：压测本地健康检查接口，发现代码猫腻

网络节点没问题，流控没问题。说真的不知道是哪里出问题了。一个简单的健康检查接口都tps不到10。怎么才能排除是不是网络节点的问题呢？压测我本地代码，同时把filter的流控的逻辑注释了，还是压测健康检查接口。结果是tps还是非常低不到10。

完犊子了，这个tps就跨不过10了吗？

由于被压测结果震惊了，却忽略了这次压测测试的目的是什么？直接压测我本地，tps还很低，这中间可没有了任何网络节点，流控也注释了，那只能是我代码问题了。只要找到方向，那就好说了，虽然具体原因还是不清楚。

上次投产回退的代码，我在filter里加了向gbase写日志的逻辑，难道、或许，应该是这里出问题了吧。那这个好办，把filter里写gbase的逻辑放到线程池里完成，你在耗时去子线程里耗时去吧，别干扰我主线程。

修改代码后，继续让测试人员压测我本地的健康检查接口。

结果呢？结果就是tps还是不到10。我当时就原地石化了.........

第三季：成也线程池，败也线程池

程序猿轻易不言败，我们就是踩不死的小强。

我放了个大招，把filter里写gbase库的逻辑注释了，继续压测我本地健康检查接口。奇迹终于出现了，tps到了190左右。这就不对了，为什么线程池没解决问题呢？我用的线程是实现了Callable，我们都知道这个线程有返回值。我们可以获取每个线程的返回结果。但是我们记录日志，不需要等待返回结果。我就换了一种实现方法，就是实现Runable接口，这个线程就是不会返回结果。（这里只讲故事，不讲技术啊，我就不帖想代码了，如果还有不了解这些的小伙伴，可以参考我以前的关于线程池的文章，关于线程池我写过好几篇文章，其中一篇是：ThreadPoolExecutor线程池详解）

把线程池相关逻辑更改后，压测本地健康检查接口，tps终于上来了，到达200左右。既然找到问题了，就继续优化我的登录接口，把写gbase库的逻辑放到线程里，以前登录接口的线程也是实现Callable接口，都改成实现Runable接口，奶奶滴，以前还真不知道，这两种写法差别这么大。说实话这块的知识点，还真不知道，以前只知道，要想得到线程执行结果用Callable，不需要线程结果用Runable。我就想了反正都是线程，用哪个不是用，就用Callable呗，万一以后领导想要每个线程执行结果呢？毕竟领导脑袋里想啥，我们有不知道。跑偏了，我们继续讲故事，不吐槽领导了

登录结果代码的线程池优化后，继续压测我本地的登录接口的tps到155了，这个完全可以满足我们的业务需求了。毕竟是内部系统，没那么大请求量。

然后就是在测试环境验证，测试环境压测登录接口，50并发情况下，tps到190左右，嗯，还不错，就是偶尔测试环境会慢........

各位看官，是不是认为到这里就结束了，因为解决了登录慢问题，tps也上来了嘛。嗯，我也是这么认为的，就这样我们就投产了。。。。。

第四季：忽略小细节，造成大隐患

路漫漫其修远兮，吾将上下而求索！信心满满，经过这段时间折腾，终于解决了这个问题。终于可以投产了.......啦啦啦啦啦

然而，现实很残酷，没想到打脸来的如此之快，脸打的如此之响！！！！我们又双叒叕投产失败，回退了..........啊啊啊啊啊。

这次投产后，登录是没问题，不慢了，就是登录系统后，首页的某些特定操作比较慢，其他的大部分功能都正常。这就很奇怪，如果说我这次优化失败了，测试环境没问题，就是生产也是就某些操作慢而已嘛，怎么是我代码问题呢，绝对不是。当然这是我内心的想法。

后来发现，慢的操作的接口里有写gbase库，什么这里也写gbase库？

后来想想，写也没事啊，gbase是本来就是大数据的应用场景，TB级别的数据查询库比oracle快多了。反正就是内心深处不认为是我代码问题，这是不是程序猿的通病啊.......

通过分析生产的日志发现，filter里大部分线程写gbase库的耗时达到了23s左右(幸亏我当时在线程里记录了耗时情况，看了多打印日志还是比较好的，要不这次问题很难发现)。那问题就明朗了，gbase不抗揍啊。

这里再简单交代下项目，系统登录后，首页加载会调用大概20多个后端接口获取数据，如果刚投产成功，会存在好多用户登录验证功能，一个用户登录后就调20个接口，如果是50个用户同时登录，就是1000次调用后台接口，这时filter就会同时写gbase库1000次。所以登录后其他操作涉及到写gbase库的都比较慢。

这时候我突然想到测试环境压测时，偶尔会出现某些操作比较慢，由于我们的关注点一直在登录接口的tps上，把这个忽略了。还有个关键点，就是我们在测试环境压测，是在晚上加班时压测的，这时间点用我们系统的人少，也没人反应，只是测试人员登录测试环境发现的，也是偶然现象，因为并不是所有操作都慢嘛，只有涉及的写gbase库的操作才会慢。也就没有当回事。

通过这次发现gbase和oracle的区别。打个比喻吧。oracle和gbase是2个剑客高手。

oracle剑客的优点是，面对众多对手都是小卡拉米、菜鸟时，得心应手。但是对手中有几个高手，那oracle就不行了。

gbase剑客的优点是，对手是多个和自己水平一样的高手，这能轻松应对。但是对手是一群菜鸟，那gbase就难应付了。

注：这里得小卡拉米、菜鸟指的是每次和数据库交互的数据量大小。