Solr慢查询日志参数为空且无CPU高耗时问题排查问询

问题背景 #

在Solr集群压测期间，发现slow_query日志中出现大量params={}的慢请求记录，但实际请求携带大量参数；同时这些请求耗时较高（QTime达1000+ms），却未出现CPU飙升情况。

集群配置 #

• 6节点集群
• products集合包含6个shard
• 节点硬件：16核32GB内存

相关日志与启动参数 #

慢查询日志示例 #

solr_slow_requests.log.1:2023-02-03 17:30:27.084 WARN  (qtp1961945640-50747) [c:products s:shard4 r:core_node47 x:products_shard4_replica_p44] o.a.s.c.S.SlowRequest slow: [products_shard4_replica_p44]  webapp=/solr path=/select params={} rid=10.0.61.80-5704218 hits=9309 status=0 QTime=1280
solr_slow_requests.log.1:2023-02-03 17:30:27.157 WARN  (qtp1961945640-50744) [c:products s:shard4 r:core_node47 x:products_shard4_replica_p44] o.a.s.c.S.SlowRequest slow: [products_shard4_replica_p44]  webapp=/solr path=/select params={} rid=10.0.61.80-5704223 hits=9730 status=0 QTime=1508
solr_slow_requests.log.1:2023-02-03 17:30:27.325 WARN  (qtp1961945640-50742) [c:products s:shard5 r:core_node59 x:products_shard5_replica_p56] o.a.s.c.S.SlowRequest slow: [products_shard5_replica_p56]  webapp=/solr path=/select params={} rid=10.0.61.80-5704234 hits=9309 status=0 QTime=1993
solr_slow_requests.log.1:2023-02-03 17:30:27.326 WARN  (qtp1961945640-50746) [c:products s:shard4 r:core_node47 x:products_shard4_replica_p44] o.a.s.c.S.SlowRequest slow: [products_shard4_replica_p44]  webapp=/solr path=/select params={} rid=10.0.61.80-5704235 hits=9309 status=0 QTime=1994
solr_slow_requests.log.1:2023-02-03 17:30:27.657 WARN  (qtp1961945640-50668) [c:products s:shard2 r:core_node23 x:products_shard2_replica_p20] o.a.s.c.S.SlowRequest slow: [products_shard2_replica_p20]  webapp=/solr path=/select params={} rid=10.0.61.80-5704247 hits=9730 status=0 QTime=1140
solr_slow_requests.log.1:2023-02-03 17:30:27.700 WARN  (qtp1961945640-50757) [c:products s:shard3 r:core_node35 x:products_shard3_replica_p32] o.a.s.c.S.SlowRequest slow: [products_shard3_replica_p32]  webapp=/solr path=/select params={} rid=10.0.61.80-5704249 hits=9730 status=0 QTime=1068
solr_slow_requests.log.1:2023-02-03 17:30:27.720 WARN  (qtp1961945640-50661) [c:products s:shard3 r:core_node35 x:products_shard3_replica_p32] o.a.s.c.S.SlowRequest slow: [products_shard3_replica_p32]  webapp=/solr path=/select params={} rid=10.0.61.80-5704254 hits=9309 status=0 QTime=1023
solr_slow_requests.log.1:2023-02-03 17:30:27.816 WARN  (qtp1961945640-49782) [c:products s:shard6 r:core_node71 x:products_shard6_replica_p68] o.a.s.c.S.SlowRequest slow: [products_shard6_replica_p68]  webapp=/solr path=/select params={} rid=10.0.61.80-5704262 hits=9730 status=0 QTime=1246
solr_slow_requests.log.1:2023-02-03 17:30:27.825 WARN  (qtp1961945640-50750) [c:products s:shard5 r:core_node59 x:products_shard5_replica_p56] o.a.s.c.S.SlowRequest slow: [products_shard5_replica_p56]  webapp=/solr path=/select params={} rid=10.0.61.80-5704263 hits=9730 status=0 QTime=1847
solr_slow_requests.log.1:2023-02-03 17:30:27.888 WARN  (qtp1961945640-50711) [c:products s:shard3 r:core_node35 x:products_shard3_replica_p32] o.a.s.c.S.SlowRequest slow: [products_shard3_replica_p32]  webapp=/solr path=/select params={} rid=10.0.61.80-5704266 hits=9309 status=0 QTime=1150
solr_slow_requests.log.1:2023-02-03 17:30:27.995 WARN  (qtp1961945640-50734) [c:products s:shard5 r:core_node59 x:products_shard5_replica_p56] o.a.s.c.S.SlowRequest slow: [products_shard5_replica_p56]  webapp=/solr path=/select params={} rid=10.0.61.80-5704277 hits=9730 status=0 QTime=1481

正常请求日志示例 #

solr.log.1:2023-02-06 12:02:54.090 INFO  (qtp1961945640-4677) [c:products s:shard1 r:core_node11 x:products_shard1_replica_p8] o.a.s.c.S.Request [products_shard1_replica_p8]  webapp=/solr path=/select params={df=_text_&distrib=false&fl=id&fl=score&shards.purpose=16388&start=0&fsv=true&fq=channel_identifier:632aff00940b4e27c80986f3&fq=zone_identifier:"_all_"&fq=is_available:True&fq=image_nature:("standard"+OR+"substandard"+OR+"default")&fq=product_online_date:[*+TO+NOW]&fq={!tag%3Dbrand_id}brand_id:("74"+OR+"235")&sort=popularity+desc+,id+asc&shard.url=http://IP:8983/solr/products_shard1_replica_p8/|http://IP:8983/solr/products_shard1_replica_n2/|http://IP:8983/solr/products_shard1_replica_p6/|http://IP:8983/solr/products_shard1_replica_t4/|http://IP:8983/solr/products_shard1_replica_p10/|http://IP:8983/solr/products_shard1_replica_n1/&rows=11550&rid=IP-225159&version=2&q=*:*&omitHeader=false&NOW=1675684973896&json={"query":+"*:*",+"params":+{"df":+"_text_",+"_route_":+"632aff00940b4e27c80986f3/2!",+"start":+11500,+"rows":+50},+"fields":+["*+score"],+"filter":+["channel_identifier:632aff00940b4e27c80986f3",+"zone_identifier:\"_all_\"",+"is_available:True",+"image_nature:(\"standard\"+OR+\"substandard\"+OR+\"default\")",+"product_online_date:[*+TO+NOW]",+{"#brand_id":+"brand_id:(\"74\"+OR+\"235\")"}],+"sort":+"popularity+desc+,id+asc"}&isShard=true&wt=javabin&_route_=632aff00940b4e27c80986f3/2!} hits=42585 status=0 QTime=193

Solr启动参数 #

-Djetty.home=/opt/solr/server
-Djetty.port=8983
-Dlog4j2.formatMsgNoLookups=true
-Dnewrelic.environment=[]
-Dsolr.data.home=
-Dsolr.default.confdir=/opt/solr/server/solr/configsets/_default/conf
-Dsolr.documentCache.initialSize=8339
-Dsolr.documentCache.size=8339
-Dsolr.filterCache.initialSize=8339
-Dsolr.filterCache.size=8339
-Dsolr.install.dir=/opt/solr
-Dsolr.jetty.inetaccess.excludes=
-Dsolr.jetty.inetaccess.includes=
-Dsolr.log.dir=/var/solr/data/logs
-Dsolr.log.muteconsole
-Dsolr.queryResultCache.initialSize=6671
-Dsolr.queryResultCache.size=6671
-Dsolr.solr.home=/var/solr/data/data
-Duser.timezone=UTC
-DzkClientTimeout=30000
-XX:+AggressiveOpts
-XX:+AlwaysPreTouch
-XX:+ParallelRefProcEnabled
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+UseG1GC
-XX:+UseGCLogFileRotation
-XX:+UseLargePages
-XX:-OmitStackTraceInFastThrow
-XX:-OmitStackTraceInFastThrow
-XX:ConcGCThreads=4
-XX:G1ReservePercent=10
-XX:GCLogFileSize=20M
-XX:InitiatingHeapOccupancyPercent=80
-XX:MaxGCPauseMillis=100
-XX:MaxTenuringThreshold=8
-XX:NewRatio=3
-XX:NumberOfGCLogFiles=9
-XX:OnOutOfMemoryError=/opt/solr/bin/oom_solr.sh 8983 /var/solr/data/logs
-XX:ParallelGCThreads=4
-XX:PretenureSizeThreshold=64m
-XX:SurvivorRatio=4
-Xloggc:/var/solr/data/logs/solr_gc.log
-Xms20000m
-Xmx20000m
-Xss256k
-javaagent:/opt/solr/contrib/newrelic/newrelic.jar
-verbose:gc

问题解答 #

1. 为何慢查询日志中params始终为空，实际请求却携带大量参数？ #

核心原因是这些请求的参数通过**POST请求体（JSON格式）**提交，而Solr默认的SlowRequest日志仅抓取URL上的查询参数，不会解析请求体中的JSON内容。对比正常请求日志可以看到，正常请求是把JSON参数拼到了URL的json=字段中，因此能被日志记录；而慢请求采用POST方式，参数放在请求体里，日志模板未配置读取请求体，所以显示params={}。

也可以检查Solr的log4j2配置文件，确认SlowRequest的日志格式是否包含解析请求体参数的配置，默认情况下该日志组件仅处理URL参数。

2. 为何这些请求耗时较高，但未出现CPU飙升情况？ #

QTime高但CPU不忙，说明请求的大部分时间都在等待资源，而非执行CPU密集型计算，常见情况如下：

• 磁盘IO阻塞：你的缓存配置（documentCache、filterCache大小仅8339，queryResultCache仅6671）过小，压测时缓存命中率极低，大量请求需要从磁盘读取原始索引数据，进程阻塞等待IO完成，此时CPU处于空闲状态。
• 线程排队等待：Jetty线程池最大线程数不足，压测时大量请求排队等待执行，QTime包含了排队等待的时间，但实际执行的线程数没占满CPU核心，所以CPU不会飙升。
• GC停顿：虽然配置了G1GC，但20G的堆内存在压测时可能出现长时间GC停顿（尤其是Full GC），导致请求处理被暂停，QTime变长，但GC期间应用线程暂停，CPU仅被GC线程占用部分资源，不会出现整体飙升的情况，可以查看solr_gc.log确认是否存在长GC停顿。
• 锁竞争阻塞：如果多个请求竞争同一个锁资源（比如缓存锁、索引片段锁），会导致线程阻塞等待锁释放，此时CPU没有处理业务逻辑，自然不会飙升。

内容的提问来源于stack exchange，提问作者Rajat Jain