初学写代码的同学容易写出死循环的代码,想不到我们多年的老鸟也栽在了死循环上面。有个查询solr的服务死循环了,导致了solr cpu狂涨。查了许久才问题原因来。
一,背景
有一个Rails项目中有一个服务原来查询数据库的,存在一个很难优化的慢查询,于是想迁移到使用solr查询。修改之后,当天中午上线,到1点左右,运维就发现solr的CPU在狂涨。于是马上想到可能是刚刚上线的查询可能有问题。分析了一下刚刚上线的查询业务,solr中保存的是商品的各种信息,刚刚上线的功能是要查询中所有符合某种条件的商品。分析了一下代码,发现可能是符合条件的商品数量较多,而实际可能使用不了这么多商品,于是想到限制一下查询的总量,即查询到大约5W个商品的时候就结束。然后上线,但情况依旧,又经过了几小时的排查,才发现第二次上线时,使用passenger重启服务失败了,于是找运维手工kill掉旧进程,启动了新进程,问题解决!
上面是遇到的情况以及排查的大概过程。但有两个事情无法解释:
- 这个查询业务,查询条件并不算复杂,怎么会导致solr的cpu使用量狂涨?
- Rails进程为什么会重启失败?
二,问题原因
排查还遇到一个奇怪的现象,正是这个现象成为了抓住原凶的突破口。我们让运维导出了solr的访问日志,发现solr查询中存在一个极大的offset,要查询的是满足某种条件的所有商品,目前线上满足这个条件的商品数量大概有15w左右,但从日志中发现有高达300w以上的offset,这远远大于我们需要查询的数据量。于是开始怀疑这个查询存在死循。分析了代码之后,果然是存在这种可能的。
查询solr的代码,简化之后大概为这样:
def get_all_product_id
page = 1
ids = []
begin
result = solr_query(page: page, per: 500)
ids += result.ids
ids.uniq!
page += 1
end while result.total > ids.size
ids
end
上面代码中solr_query代表一次solr的查询,代码中一次查询最多500个数据,返回的result中,ids代表本次查询返回的id,result.total代表solr中所有满足条件的商品总数。
这段代码在线下运行完全没有问题,可以正常的查询回数据,不存在死循环。但在线上,solr的offset却一直涨到比要查询的数据量大很多。线上和线下solr的区别在于,线上的solr另外存在一个更新的任务,不断的在更新solr中的数据,这可能是造成循环停不下来的原因。
下面模拟了一下可能出现的情况,假如有一个列表,以下图所示,蓝色背景的是我们需要查询出来的数据,白色背景的是不满足条件的数据,注意第2个数据现在是不满足查询条件的。
假如我们按每页3个元素,那么第一页查询,我们将会获得元素[1,3,4],然而这个列表可能是会动态变化的,当我们查询第二页的时候,列表可能变成了下面这样:
此时,第2个元素又满足条件了,此时查询到的第2页数据将会是:[4,5,6],我们可以看到2被漏掉了,而且重复出现的元素4,然后观察上面的代码,发现我们对id去了重ids.uniq!,此时可以发现,我们查询了所有满足条件的元素一共只有5个(1,3,4,5,6),而实际满足条件的total数量为6,所以上面代码中的停止循环的条件永远达不到,于是代码死循环了!
三,解决方案
其实上面的问题,在查询数据库时,也是可能遇到的,上面导致死循环的一个重要的原因是对查出的数据去了重,这导致查询的数量可能永远达不到total的量,所以循环不会停下来。但也可以从业务上来优化一下,也许我们使用不了这么多数据,当查询到一定量之后,就停止查询。或者需要设定一个强制退出的条件,比如查询次数超过一定值时,强制退出来。
然后大概也可以解释为什么rails进程重启失败了,进程中存在死循环的时候,passenger在重启的时候会认为进程的请求还未处理完,进程为因此hang住。另外,其实rails项目多是采用多进程方式部署,实际的进程数量是非常有限,一旦有死循环存在,很容易让整个系统崩溃。