一次压测情况下Solr部分性能调整

 

在将solr模糊词搜索从 copyfield方式修改为 qf(query function)之后，其query的性能降低不少。原来是采用将所有需要搜索的字段都copy至同一个字段中，最近要根据模糊匹配结果的权重分析，这种方式根本无法满足要求，所以就采用了query function，这样就能定义不同字段的权重了，例如我们qf可以如下定义：

 

 

product_name^2.0 category_name^1.5 category_name1^1.5

  

 

搜索出来的结果会根据不同匹配的评分进行相似度排序。

 

但在性能测试过程中，其非常耗费内存，在solr查询服务中，我们打开了solr的搜索日志 solr.log，搜索日志的格式大概如下：

 

2016-10-19 13:31:26.955 INFO  (qtp1455021010-596) [c:product s:shard1 r:core_node1 x:product] o.a.s.c.S.Request [product] webapp=/solr path=/select params={sort=salesVolume+desc&fl=product_id,salesVolume&start=0&q=brand_id:403+OR+category_id:141&wt=javabin&version=2&rows=100} hits=3098 status=0 QTime=3
2016-10-19 13:31:28.618 INFO  (qtp1455021010-594) [c:product s:shard1 r:core_node1 x:product] o.a.s.c.S.Request [product] webapp=/solr path=/select params={mm=100&facet=true&sort=psfixstock+DESC,salesVolume+DESC&facet.mincount=1&facet.limit=-1&wt=javabin&version=2&rows=10&fl=product_id&facet.query=price:[*+TO+500]&facet.query=price:[500+TO+1000]&facet.query=price:[1000+TO+2000]&facet.query=price:[2000+TO+5000]&facet.query=price:[5000+TO+10000]&facet.query=price:[10000+TO+*]&start=0&q=*:*+AND+(category_id:243+OR+category_path:243)+AND+-category_path:309+AND+brand_id:401+AND+good_stop:0+AND+product_stop:0+AND+is_check:1+AND+status:1&facet.field=category_id&facet.field=brand_id&facet.field=color_id&facet.field=gender&facet.field=ctype&qt=/select&fq=price:[1000+TO+*]&fq=psfixstock:[1+TO+*]} hits=17 status=0 QTime=5
2016-10-19 13:31:30.867 INFO  (qtp1455021010-614) [c:product s:shard1 r:core_node1 x:product] o.a.s.c.S.Request [product] webapp=/solr path=/select params={mm=100&facet=true&sort=price+ASC,goods_id+DESC&facet.mincount=1&facet.limit=-1&wt=javabin&version=2&rows=10&fl=product_id&facet.query=price:[*+TO+500]&facet.query=price:[500+TO+1000]&facet.query=price:[1000+TO+2000]&facet.query=price:[2000+TO+5000]&facet.query=price:[5000+TO+10000]&facet.query=price:[10000+TO+*]&start=0&q=*:*+AND+(category_id:10+OR+category_path:10)+AND+-category_path:309+AND+color_id:10+AND+gender:(0)+AND+good_stop:0+AND+product_stop:0+AND+is_check:1+AND+status:1&facet.field=category_id&facet.field=brand_id&facet.field=color_id&facet.field=gender&facet.field=ctype&qt=/select&fq=price:[5000+TO+*]&fq=psfixstock:[1+TO+*]} hits=9 status=0 QTime=7
2016-10-19 13:31:32.877 INFO  (qtp1455021010-594) [c:product s:shard1 r:core_node1 x:product] o.a.s.c.S.Request [product] webapp=/solr path=/select params={mm=100&facet=true&sort=psfixstock+DESC,salesVolume+DESC&facet.mincount=1&facet.limit=-1&wt=javabin&version=2&rows=10&fl=product_id&facet.query=price:[*+TO+500]&facet.query=price:[500+TO+1000]&facet.query=price:[1000+TO+2000]&facet.query=price:[2000+TO+5000]&facet.query=price:[5000+TO+10000]&facet.query=price:[10000+TO+*]&start=0&q=*:*+AND+(category_id:60+OR+category_path:60)+AND+-category_path:309+AND+brand_id:61+AND+gender:(0)+AND+good_stop:0+AND+product_stop:0+AND+is_check:1+AND+status:1&facet.field=category_id&facet.field=brand_id&facet.field=color_id&facet.field=gender&facet.field=ctype&qt=/select&fq=price:[*+TO+*]&fq=psfixstock:[1+TO+*]} hits=5 status=0 QTime=8
2016-10-19 13:31:42.896 INFO  (qtp1455021010-89) [c:product s:shard1 r:core_node1 x:product] o.a.s.c.S.Request [product] webapp=/solr path=/select params={mm=100&facet=true&sort=psfixstock+DESC,salesVolume+DESC&facet.mincount=1&facet.limit=-1&wt=javabin&version=2&rows=10&fl=product_id&facet.query=price:[*+TO+500]&facet.query=price:[500+TO+1000]&facet.query=price:[1000+TO+2000]&facet.query=price:[2000+TO+5000]&facet.query=price:[5000+TO+10000]&facet.query=price:[10000+TO+*]&start=0&q=*:*+AND+-category_path:309+AND+brand_id:323+AND+color_id:3+AND+good_stop:0+AND+product_stop:0+AND+is_check:1+AND+status:1&facet.field=category_id&facet.field=brand_id&facet.field=color_id&facet.field=gender&facet.field=ctype&qt=/select&fq=price:[*+TO+*]&fq=psfixstock:[1+TO+*]} hits=3 status=0 QTime=4

 

 

为了合理统计出query的QTime，编写了一个python脚本，用来在线分析每次solr查询的QTime和对应的查询条件：

 

 

import sys
 
if __name__ == '__main__':
    input_file = sys.argv[1]
 
    min_time = 0 if len(sys.argv) < 3 else int(sys.argv[2])
 
    try:
        with open(input_file) as file:
            while (1):
                line = file.readline().strip()
                if not line:
                    break
                splits = line.split(" ")
                if not splits[len(splits) - 1].startswith("QTime"):
                    continue
                q_time = int(splits[len(splits) - 1].replace('\n', '').replace('QTime=', ''))
                if q_time <= min_time:
                    continue
 
                date = splits[0]
                time = splits[1]
                params = splits[13].split("&")
 
                dict = {}
                for param in params:
                    keyValuePair = param.split("=")
                    dict[keyValuePair[0]] = keyValuePair[1]
 
                query = dict.get('q', None)
                if query:
                    print "%s - %s , QTime=% 5d, Query = %s" % (date, time, q_time, query)
    except IOError as error:
        print error

 

 

 

该脚本中可以分析solr.log中的日志并过滤出大于某端时间（毫秒）的QTime。经过分析发现此时的QTime大于1000ms的占据很大比例，说明我们配置的query function性能并不理想，至少相对于copy field来说。

 

通过jvisualvm监测发现full gc发生的频率非常高，cpu占用居高不下，请求响应时间发生抖动，且抖动的时候都是在该服务器的CPU使用率下降时发生的。

 

将线上的堆栈dump出来，经过JProfiler分析的hprof文件，占据大头的都是solr、lucene相关的类：

 

 
 

 

而且发现另外一个情况，老年代用400M左右常驻内存，而通常老年代涨到500M左右时就会发生一次Full GC（发生得非常频繁）。

 

需要我们调整JVM内部各个部分内存占用的比例，但收效甚微，接近10：1（MinorGC：FullGC）的GC，过多的FullGC次数使得应用程序的整体处理请求速度变慢：

 

 

 

 

初步分析觉得应该是Survivor的空间不足以存放某个大对象，使得新生代未被回收的对象直接晋升到老年代导致频繁GC，但是调高SurvivorRatio比例之后，发现该问题仍然没有得到解决。

 

当前solr的GC回收策略为CMSGC，据网上查找的该垃圾回收策略，可能会出现promotion failed和concurrent mode failure，经过我们查看当天的压测日志，确实这种情况非常多：

 

> grep "concurrent mode failure" solr_gc_log_20161018_* | wc -l
4919
> grep "promotion failed" solr_gc_log_20161018_* | wc -l
127

 

 

网上推荐的做法是：

 

http://blog.csdn.net/chenleixing/article/details/46706039 写道

promotion failed是在进行Minor GC时，survivor space放不下、对象只能放入老年代，而此时老年代也放不下造成的；concurrent mode failure是在执行CMS GC的过程中同时有对象要放入老年代，而此时老年代空间不足造成的（有时候“空间不足”是CMS GC时当前的浮动垃圾过多导致暂时性的空间不足触发Full GC）。
应对措施为：增大survivor space、老年代空间或调低触发并发GC的比率，但在JDK 5.0+、6.0+的版本中有可能会由于JDK的bug29导致CMS在remark完毕后很久才触发sweeping动作。对于这种状况，可通过设置-XX: CMSMaxAbortablePrecleanTime=5（单位为ms）来避免。

 

 

 

但经过综合考虑，没有能够正常调通该种策略，决定提升JVM的进程Heap内存至3.5G，并将原有响应式CMSGC替换成吞吐量优先的方式，减少FullGC次数和总体时间：

 

-Xmn2048m \
-XX:-UseAdaptiveSizePolicy \
-XX:SurvivorRatio=4 \
-XX:TargetSurvivorRatio=90 \
-XX:MaxTenuringThreshold=8 \
-XX:+UseParallelGC -XX:+UseParallelOldGC

  

 

经过这样调整后：Heap总体内存为3.5G，老年代1.5G，新生代总体2G，Eden区1.3G，两个Survivor区分别为300M。

 

但是空间提高之后也会出现其他的问题，发现老年代空间导致的一个重大问题就是，单次FullGC的时间会变得非常大，第一次gc时间居然超过5s，这也是由于单次回收的空间过高引起的：

 

 

 

原来总是以为是survivor区的空间不够大，当调大之后发现也不是这个问题，不过这种情况下运行一段时间后，总体还算是比较稳定，次数和时间也控制下来了，只不过进行FullGC时可能会发生STW（Stop The World），引起较长时间的停顿，如果是CMS方式就不会出现这种问题。

 

SurvivorRatio=2的设置也并不是非常合理，后续还是将其降低为4-5。

 

  

 

经过solr部分的测试，基本的结论还是比较符合预期的，相同条件下，对于analysed字段（进行分词操作的），其响应时间（Response Time）会比非analysed字段长很多，尤其是在压测条件下（图中最后一行就是模糊匹配，其他两个为精确匹配）。

 

  

 

SolrCloud导致的另外一些问题

 

经过solrCloud线上和测试环境对比验证，发现线上的多台服务性能居然要比单台要低，经过数据比对分析发现，我们当前的数据量还没有达到需要进行分片的要求，分片反而会导致性能下降，下面是我们当前的core部署结构，分成两个shard

 

 

 

在solr的debugQuery模式下，可以看到最终的QTime为两个QTime增加后的总和还要多一点，多出的时间应该是合并结果的时间。在数据量比较大的情况下，多分片会降低某一台服务器的负载。

 

如果将其做成单个shard，通过zookeeper连接solrCloud，增加replica的情况下，则只会将压力打到单台服务器上，这样做虽然比分片要快（在小数据集的情况下），但造成了服务资源的浪费。

 

 

 

我们决定采用折中方案，使用solrCloud来保证4台solr服务器的数据一致性（我们当前的数据变化不频繁），然后每台应用服务器选择一台solr服务器进行单机连接，这样也有一个问题就是损失了高可用性，但是在电商做活动期间，这样临时做是没有问题的，但需要保证每台服务器的其他core都是存在全面的数据，否则会出现某些节点没有对应core的错误。