复盘一个Elasticsearch排序问题的剖析
程序员文章站
2022-05-11 15:09:27
...
最近线上的es查询的某个微服务接口,报了一个异常,如下:
``` nested: SearchParseException[No mapping found for [count] in order to sort on]; Caused by: SearchParseException[failed to parse search source ```
直接从异常上看,可以得到是因为mapping里面不存在排序字段的时候,而抛出的异常,正常的情况,如果某个索引不存在并且还去查询该索引,我们可以通过对索引名字后面加*通配,来避免查询报错,如下:
``` SearchRequestBuilder search=client.prepareSearch("log2019-07-11*"); search.setQuery(QueryBuilders.queryStringQuery("uid:111")); search.addSort("count", SortOrder.DESC); ```
经询问,我们的代码里面已经加了*通配符,那么又为什么会出现这个问题呢?经过对场景的分析总结,对某个字段进行sort时,可能会报上述异常,主要在两种情况下:
(1)count字段在mapping中无定义,并没有在索引名字后缀加*通配符时,必定每次都报异常
(2)count字段在mapping中有定义,使用前面的排序方法,排序有时候报错,有时候不报
对于第一种情况,mapping里不存在定义,并且没有使用通配容错,直接使用该字段排序报错很正常。
接下来主要分析第二种情况,因为这里面有个概率事件,即大多数时候都没问题,但在少数时候会抛出异常。通过分析log发现在凌晨12点刚过的时候,会有几率出现这种问题,为了找到更多的排查线索,我让运维给出了线上当时服务端es的log文件,毕竟单纯从微服务的log里面,很难观察到这个异常前后,有没有更多的上下文log输出,想要找到这个,只能查看服务端部署es节点的log了,在拿到log之后,果然从上下文里面,发现了一些关键的信息,如下:
``` [2019-07-11 00:00:05,044][INFO ][cluster.metadata ] [my_es] [log2019-07-11] creating index, cause [auto(index api)], templates [log], shards [3]/[2], mappings [_default_, log] [2019-07-11 00:00:05,409][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[log2019-07-11][0], [log2019-07-11][2], [log2019-07-11][1]] ...]). [2019-07-11 00:00:06,232][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[log2019-07-11][1], [log2019-07-11][1]] ...]). [2019-07-11 00:00:06,374][INFO ][cluster.metadata ] [my_es] [log2019-07-11] update_mapping [log] [2019-07-11 00:00:07,153][DEBUG][action.search ] [my_es] [log2019-07-11][0], node[QlHmfObMRg2K6FUuAaXXTw], [R], v[2], s[INITIALIZING], a[id=3aenuvbUQtGrFDBBxjJvCA], unassigned_info[[reason=INDEX_CREATED], at[2019-07-10T16:00:06.574Z]]: Failed to execute [org.elasticsearch.action.search.SearchRequest@22e9ea6f] lastShard [trueRemoteTransportException[[my_es_02][192.168.10.152:9300][indices:data/read/search[phase/query]]]; nested: SearchParseException[failed to parse search source [{"size":3,"query":{"bool":{"should":[{"term":{"uid":"44733065"}}]}},"sort":[{"count":{"order":"desc"}}]}]]; nested: SearchParseException[No mapping found for [count] in order to sort on]; Caused by: SearchParseException[failed to parse search source ```
注意,在报这个异常之前,有两行关键的log:
``` [2019-07-11 00:00:05,409][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[log2019-07-11][0], [log2019-07-11][2], [log2019-07-11][1]] ...]). [2019-07-11 00:00:06,232][INFO ][cluster.routing.allocation] [my_es] Cluster health status changed from [YELLOW] to [GREEN] (reason: [shards started [[log2019-07-11][1], [log2019-07-11][1]] ...]). ```
期间报异常的前2秒,es集群状态经历了从red到yellow再到green,虽然只有短暂的1秒,但却是排查问题非常关键的信息,我们知道出现这种信息的时候,代表的是es的主分片和副本分片正在做初始化或者出现了异常等待恢复,由此可以推论出这样一个场景,当凌晨12点刚过的第5秒,有写入该索引的es数据,触发了es动态索引的创建,由于这个索引有3个shard,每个shard分别有2个副本shard,也就是说共有6个shard需要初始化,假设初始化需要的时间为2秒,那么,恰巧在第6秒的时候,有个查询带排序的请求过来了,这个时候由于索引初始化并没有完成,所以在当天部分shard的mapping里面并没有查到该字段的信息,故产生了异常,之后当这个索引创建完成之后,再次收到的新查询请求是没有问题的。为了验证我们这个猜想,我们需要一段程序来做测试:
设计的复现场景有如下两步:
(1)A线程模拟查询请求,一直都在查询某一天的索引数据,起初这个索引并不存在,因为不存在所以查询使用通配符的方法,即使有排序字段,也并不会报错。
A线程的查询代码如下:
``` SearchRequestBuilder search=client.prepareSearch("log2019-07-11*"); search.setQuery(QueryBuilders.queryStringQuery("uid:111")); search.addSort("count", SortOrder.DESC); SearchResponse sr=search.get(); for ( SearchHit hit: sr.getHits()){ System.out.println(hit.getSource().toString()); } System.out.println(Thread.currentThread().getName()+"=>query"+" hit="+sr.getHits().getTotalHits()); ```
(2)B线程在A线程启动3秒后执行,然后向这个不存在的索引插入一条数据,由于第一次插入数据,这天的索引会被自动创建,里面就会涉及shard的初始化过程,这个时候同时A线程在查询就会复现出问题:
``` [No mapping found for [count] in order to sort on] ```
B线程的写入代码如下:
``` IndexRequestBuilder builder = client.prepareIndex("log2019-07-11", "log").setId("111"); builder.setCreate(true); java.util.Map<String , Object> map=new HashMap<>(); map.put("uid","111"); map.put("count","3"); builder.setSource(map); builder.execute().actionGet(); System.out.println(Thread.currentThread().getName()+" => " + "create index finished. " ); ```
知道问题后,那么如何解决这个问题呢?其实非常简单,我们只需要对于排序不存在的字段,作一下缺失容错即可,如下:
``` search.addSort("count", SortOrder.DESC); ```
改为
``` search.addSort(SortBuilders.fieldSort("count").unmappedType("integer").order(SortOrder.DESC)); ```
上面的代码,告诉es如果在排序时,遇到一个不存在的字段,我们只需要给其设置正确的排序类型即可,这样就能避免前面提到的2个导致排序失败的原因:
(1)count排序字段在mapping中无定义,并没有在索引名字后缀加*通配符时,必定每次都报异常(查询一个不存在字段,是不会报异常的,不管索引名有无后缀通配符)
(2)count排序字段在mapping中有定义,使用前面的排序方法,排序有时候报错,有时候不报(真正原因是当时shard正在做初始化导致的)
es索引本身是shemeless的结构,对于正常查询一个不存在的字段,是不会报错的,但是对于排序的字段,则有可能出现异常,所以我们在写相关的代码时,可以对排序字段加个容错处理,以提高我们程序的健壮性。
上一篇: 为什么单线程Redis性能也很出色
下一篇: 颈椎病犯了