Hello all,
We recently moved to SOLR 7 from SOLR 6 about 2 weeks ago. Once each week
(including today) we experienced query timeout issues with corresponding GC
events. There was a spike in CPU up to 66% which is not something we
previously saw w/ Solr 6. From the SOLR logs it looks like something inside
the JVM has happend, SOLR is reporting closed connections from Jetty. Our
data size is relatively small but we do run 5 cores within the one Jetty
instance. There index sizes are anywhere between 200Mb to 2GB
Our memory consumption is relatively low:
"free":"296.1 MB",
"total":"569.6 MB",
"max":"9.6 GB",
"used":"273.5 MB (%2.8)",
We had a spike in traffic about 5 minutes prior to some longer GC events
(similar situation last week).
Any help would be appreciated. Below is my current system info along with a
GC log snippet and the corresponding SOLR log error.
*System info:*
AMZ2 linux
8 core 32 GB Mem
*Java:* 1.8.0_222-ea 25.222-b03
*Solr: *solr-spec-version":"7.7.2"
*Start options: *
"-Xms512m",
"-Xmx10g",
"-XX:NewRatio=3",
"-XX:SurvivorRatio=4",
"-XX:TargetSurvivorRatio=90",
"-XX:MaxTenuringThreshold=8",
"-XX:+UseConcMarkSweepGC",
"-XX:ConcGCThreads=4",
"-XX:ParallelGCThreads=4",
"-XX:+CMSScavengeBeforeRemark",
"-XX:PretenureSizeThreshold=64m",
"-XX:+UseCMSInitiatingOccupancyOnly",
"-XX:CMSInitiatingOccupancyFraction=50",
"-XX:CMSMaxAbortablePrecleanTime=6000",
"-XX:+CMSParallelRemarkEnabled",
"-XX:+ParallelRefProcEnabled",
"-XX:-OmitStackTraceInFastThrow",
"-verbose:gc",
"-XX:+PrintHeapAtGC",
"-XX:+PrintGCDetails",
"-XX:+PrintGCDateStamps",
"-XX:+PrintGCTimeStamps",
"-XX:+PrintTenuringDistribution",
"-XX:+PrintGCApplicationStoppedTime",
"-XX:+UseGCLogFileRotation",
"-XX:NumberOfGCLogFiles=9",
"-XX:GCLogFileSize=20M",
"-Xss256k",
"-Dsolr.log.muteconsole"
Here is an example of from the GC log:
2019-10-02T16:03:15.888+0000: 265318.624: [Full GC (Allocation
Failure) 2019-10-02T16:03:15.888+0000: 265318.624:
[CMS2019-10-02T16:03:16.134+0000: 26
5318.870: [CMS-concurrent-mark: 1.773/1.783 secs] [Times: user=13.14
sys=0.00, real=1.78 secs]
(concurrent mode failure): 7864319K->7864319K(7864320K), 9.5890129
secs] 10048895K->8863021K(10048896K), [Metaspace:
53159K->53159K(1097728K)], 9.5892061 secs] [Times: user=10.31
sys=0.00, real=9.59 secs]
Heap after GC invocations=296656 (full 546):
par new generation total 2184576K, used 998701K
[0x0000000540000000, 0x00000005e0000000, 0x00000005e0000000)
eden space 1747712K, 57% used [0x0000000540000000,
0x000000057cf4b4f0, 0x00000005aaac0000)
from space 436864K, 0% used [0x00000005aaac0000,
0x00000005aaac0000, 0x00000005c5560000)
to space 436864K, 0% used [0x00000005c5560000,
0x00000005c5560000, 0x00000005e0000000)
concurrent mark-sweep generation total 7864320K, used 7864319K
[0x00000005e0000000, 0x00000007c0000000, 0x00000007c0000000)
Metaspace used 53159K, capacity 54766K, committed 55148K,
reserved 1097728K
class space used 5589K, capacity 5950K, committed 6000K, reserved 1048576K
}
2019-10-02T16:03:25.477+0000: 265328.214: Total time for which
application threads were stopped: 9.5906157 seconds, Stopping threads
took: 0.0001274 seconds
*With the following from the SOLR log: *
[ x:core] o.a.s.s.HttpSolrCall Unable to write response, client
closed connection or we are s
hutting down
org.eclipse.jetty.io.EofException: Closed
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:665)
~[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.apache.solr.servlet.ServletOutputStreamWrapper.write(ServletOutputStreamWrapper.java:126)
~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c
1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
at
org.apache.solr.response.QueryResponseWriterUtil$1.write(QueryResponseWriterUtil.java:54)
~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fef
c589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
at java.io.OutputStream.write(OutputStream.java:116) ~[?:1.8.0_222-ea]
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
~[?:1.8.0_222-ea]
at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
~[?:1.8.0_222-ea]
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
~[?:1.8.0_222-ea]
at java.io.OutputStreamWriter.write(OutputStreamWriter.java:207)
~[?:1.8.0_222-ea]
at org.apache.solr.common.util.FastWriter.flush(FastWriter.java:140)
~[solr-solrj-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94
- j
anhoy - 2019-05-28 23:37:52]
at
org.apache.solr.common.util.FastWriter.flushBuffer(FastWriter.java:154)
~[solr-solrj-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b
94 - janhoy - 2019-05-28 23:37:52]
at
org.apache.solr.response.TextResponseWriter.close(TextResponseWriter.java:82)
~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070
a415b94 - janhoy - 2019-05-28 23:37:48]
at
org.apache.solr.response.JSONResponseWriter.write(JSONResponseWriter.java:68)
~[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070
a415b94 - janhoy - 2019-05-28 23:37:48]
at
org.apache.solr.response.QueryResponseWriterUtil.writeQueryResponse(QueryResponseWriterUtil.java:65)
~[solr-core-7.7.2.jar:7.7.2 d4c30fc285
6154f2c1fefc589eb7cd070a415b94 - janhoy - 2019-05-28 23:37:48]
at
org.apache.solr.servlet.HttpSolrCall.writeResponse(HttpSolrCall.java:789)
[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b
94 - janhoy - 2019-05-28 23:37:48]
at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:525)
[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd070a415b94 -
janh
oy - 2019-05-28 23:37:48]
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:395)
[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd0
70a415b94 - janhoy - 2019-05-28 23:37:48]
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:341)
[solr-core-7.7.2.jar:7.7.2 d4c30fc2856154f2c1fefc589eb7cd0
70a415b94 - janhoy - 2019-05-28 23:37:48]
at
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602)
[jetty-servlet-9.4.14.v20181114.jar:9.4.14.v2018111
4]
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
[jetty-servlet-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
[jetty-security-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480)
[jetty-servlet-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1557)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
at
org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220)
[jetty-server-9.4.14.v20181114.jar:9.4.14.v20181114]
*Eventually we are receiving an actual ERROR *
o.a.s.s.HttpSolrCall null:java.io.IOException:
java.util.concurrent.TimeoutExceptio
n: Idle timeout expired: 122014/120000 ms
at
org.eclipse.jetty.util.SharedBlockingCallback$Blocker.block(SharedBlockingCallback.java:235)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:217)
at org.eclipse.jetty.server.HttpOutput.write(HttpOutput.java:628)
at
org.apache.solr.servlet.ServletOutputStreamWrapper.write(ServletOutputStreamWrapper.java:126)
at
org.apache.solr.response.QueryResponseWriterUtil$1.write(QueryResponseWriterUtil.java:54)
at java.io.OutputStream.write(OutputStream.java:116)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:282)
at sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125)
at java.io.OutputStreamWriter.write(OutputStreamWriter.java:207)
at org.apache.solr.common.util.FastWriter.flush(FastWriter.java:140)
at org.apache.solr.common.util.FastWriter.write(FastWriter.java:54)
at org.apache.solr.response.JSONWriter._writeChar(JSONWriter.java:173)
at
org.apache.solr.common.util.JsonTextWriter.writeStr(JsonTextWriter.java:86)
at org.apache.solr.common.util.TextWriter.writeVal(TextWriter.java:52)
at
org.apache.solr.response.TextResponseWriter.writeVal(TextResponseWriter.java:152)
at
org.apache.solr.common.util.JsonTextWriter.writeJsonIter(JsonTextWriter.java:194)
at
org.apache.solr.common.util.JsonTextWriter.writeArray(JsonTextWriter.java:270)
at
org.apache.solr.common.util.TextWriter.writeArray(TextWriter.java:154)
at org.apache.solr.common.util.TextWriter.writeVal(TextWriter.java:80)
at
org.apache.solr.response.TextResponseWriter.writeVal(TextResponseWriter.java:152)
at
org.apache.solr.common.util.JsonTextWriter.writeNamedListAsMapWithDups(JsonTextWriter.java:386)
at
org.apache.solr.common.util.JsonTextWriter.writeNamedList(JsonTextWriter.java:292)
at org.apache.solr.common.util.TextWriter.writeVal(TextWriter.java:63)
at
org.apache.solr.response.TextResponseWriter.writeVal(TextResponseWriter.java:152)
at
org.apache.solr.common.util.JsonTextWriter.writeNamedListAsMapWithDups(JsonTextWriter.java:386)
at
org.apache.solr.common.util.JsonTextWriter.writeNamedList(JsonTextWriter.java:292)
at org.apache.solr.common.util.TextWriter.writeVal(TextWriter.java:63)
at
org.apache.solr.response.TextResponseWriter.writeVal(TextResponseWriter.java:152)
at
org.apache.solr.common.util.JsonTextWriter.writeNamedListAsMapWithDups(JsonTextWriter.java:386)
at
org.apache.solr.common.util.JsonTextWriter.writeNamedList(JsonTextWriter.java:292)
at org.apache.solr.response.JSONWriter.writeResponse(JSONWriter.java:73)
at
org.apache.solr.response.JSONResponseWriter.write(JSONResponseWriter.java:66)
at
org.apache.solr.response.QueryResponseWriterUtil.writeQueryResponse(QueryResponseWriterUtil.java:65)
at
org.apache.solr.servlet.HttpSolrCall.writeResponse(HttpSolrCall.java:789)
at org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:525)
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:395)
at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:341)
at
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1602)
at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540)
at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
at
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1588)
at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
