[
https://issues.apache.org/jira/browse/SOLR-14314?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17057767#comment-17057767
]
Aaron Sun edited comment on SOLR-14314 at 3/12/20, 10:09 AM:
-------------------------------------------------------------
[~ichattopadhyaya] Thanks for the valuable answer. After change the JVM heap
size to 25 GB, it indeed become much better, still a bit pause in log here and
there, but much shorter, around 1~2 seconds. Is it possible to make it even
better? Also notice the pause happen more often around "HttpSolrCall Closing
out SolrRequest" which does not seem related with GC pause.
Regarding the muliple solr nodes(JVMs), I guess you refer to this page:
[https://lucene.apache.org/solr/guide/7_2/taking-solr-to-production.html#running-multiple-solr-nodes-per-host|https://lucene.apache.org/solr/guide/7_2/taking-solr-to-production.html#running-multiple-solr-nodes-per-host,]
, is that mean each solr instance have it's own solr home directory and port?
if so how to split the data? one core with one instance? Is that mean client
need to manage which solr instance to talk with?
I couldn't find good example on internet, appreciate if you could provide some
guidance.
{noformat}
2020-03-12 10:37:19.804 DEBUG (qtp1668016508-3474) [ x:aggprogram]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:37:20.543 DEBUG (qtp1668016508-4857) [ x:aggprogram]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE add\{,id=2101608110097976031}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:39:11.250 DEBUG (qtp1668016508-6123) [ x:aggasset]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:39:11.915 TRACE (qtp1668016508-3376) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2102003090810779924 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002583
refcount=1} LogPtr(1081326) map=1784607161
2020-03-12 10:40:08.746 DEBUG (qtp1668016508-382) [ x:aggasset]
o.a.s.s.HttpSolrCall Closing out SolrRequest:
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:40:09.640 DEBUG (qtp1668016508-3239) [ x:aggasset]
o.a.s.u.TransactionLog New TransactionLog
file=/data1/solr8/aggasset/data/tlog/tlog.0000000000000001116, exists=false,
size=0, openExisting=false
2020-03-12 10:40:58.182 DEBUG (qtp1668016508-3413) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:41:00.318 TRACE (qtp1668016508-381) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2101701290647113224 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002593
refcount=1} LogPtr(1940077) map=1984880505
2020-03-12 10:41:33.880 DEBUG (qtp1668016508-771) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:41:35.754 TRACE (qtp1668016508-3298) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2102003070806775224 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002598
refcount=1} LogPtr(4246525) map=1493020555
2020-03-12 10:42:23.140 DEBUG (qtp1668016508-107) [ x:agglogtrackitem]
o.a.s.u.DirectUpdateHandler2
updateDocument(add\{_version_=1660950824311848960,id=2101702170007764324})
2020-03-12 10:42:23.935 TRACE (qtp1668016508-380) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2101806210189104124 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002605
refcount=1} LogPtr(5096503) map=2041040637
{noformat}
And the QTime with 100+s still not sound too good
{noformat}
2020-03-12 11:08:27.586 INFO (qtp1668016508-15663) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory [agglogtrackitem] webapp=/solr path=/update
params=\{commit=true}{add=[2102001130729569124 (1660952325002362880),
2102001220746002624 (1660952325018091520), 2102002130766975424
(1660952325216272385), 2102003020799380624 (1660952325224660992),
2102001150733370324 (1660952325239341056), 2102003090811568924
(1660952325280235520), 2102002130766460924 (1660952325295964161),
2102001220746002024 (1660952325313789954), 2102002200779134024
(1660952325333712896), 2102002280792794524 (1660952325357830145), ... (200
adds)],commit=} 0 134457
2020-03-12 11:08:27.586 DEBUG (qtp1668016508-15663) [ x:agglogtrackitem]
o.a.s.s.HttpSolrCall Closing out SolrRequest:
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 11:08:30.588 INFO (qtp1668016508-354) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory [agglogtrackitem] webapp=/solr path=/update
params=\{commit=true}{add=[2102003030801493024 (1660952327142506496),
2101910280679323524 (1660952329722003458), 2102002280793200424
(1660952329870901249), 2102002280793200524 (1660952330735976448),
2102003030801513824 (1660952333609074688), 2102002280793203224
(1660952335028846593), 2102002280793196024 (1660952337146970113),
2102002180774885124 (1660952339094175744), 2101910280679328124
(1660952340238172160), 2101910280679298024 (1660952343581032448), ... (200
adds)],commit=} 0 135418
2020-03-12 11:08:30.588 DEBUG (qtp1668016508-354) [ x:agglogtrackitem]
o.a.s.s.HttpSolrCall Closing out SolrRequest:
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 11:08:34.284 INFO (qtp1668016508-400) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory [agglogtrackitem] webapp=/solr path=/update
params=\{commit=true}{add=[2102002200779000724 (1660952325957615618),
2102002030765009024 (1660952325973344258), 2102002130766413424
(1660952325979635712), 2102001170736628124 (1660952325984878594),
2102002250788105624 (1660952325989072896), 2102003020799080224
(1660952325993267200), 2102002170773995424 (1660952325996412929),
2102001280755164624 (1660952326000607232), 2102002250788101824
(1660952326004801537), 2102002200778996424 (1660952326008995841), ... (200
adds)],commit=} 0 140243
{noformat}
was (Author: aaronsuns):
[~ichattopadhyaya] Thanks for the valuable answer. After change the JVM heap
size to 25 GB, it indeed become much better, still a bit pause in log here and
there, but much shorter, around 1~2 seconds. Is it possible to make it even
better? Also notice the pause happen more often around "HttpSolrCall Closing
out SolrRequest" which does not seem related with GC pause.
Regarding the muliple solr nodes(JVMs), I guess you refer to this page:
[https://lucene.apache.org/solr/guide/7_2/taking-solr-to-production.html#running-multiple-solr-nodes-per-host|https://lucene.apache.org/solr/guide/7_2/taking-solr-to-production.html#running-multiple-solr-nodes-per-host,]
, is that mean each solr instance have it's own solr home directory and port?
if so how to split the data? one core with one instance? Is that mean client
need to manage which solr instance to talk with?
I couldn't find good example on internet, appreciate if you could provide some
guidance.
{noformat}
2020-03-12 10:37:19.804 DEBUG (qtp1668016508-3474) [ x:aggprogram]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:37:20.543 DEBUG (qtp1668016508-4857) [ x:aggprogram]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE add\{,id=2101608110097976031}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:39:11.250 DEBUG (qtp1668016508-6123) [ x:aggasset]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:39:11.915 TRACE (qtp1668016508-3376) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2102003090810779924 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002583
refcount=1} LogPtr(1081326) map=1784607161
2020-03-12 10:40:08.746 DEBUG (qtp1668016508-382) [ x:aggasset]
o.a.s.s.HttpSolrCall Closing out SolrRequest:
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:40:09.640 DEBUG (qtp1668016508-3239) [ x:aggasset]
o.a.s.u.TransactionLog New TransactionLog
file=/data1/solr8/aggasset/data/tlog/tlog.0000000000000001116, exists=false,
size=0, openExisting=false
2020-03-12 10:40:58.182 DEBUG (qtp1668016508-3413) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:41:00.318 TRACE (qtp1668016508-381) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2101701290647113224 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002593
refcount=1} LogPtr(1940077) map=1984880505
2020-03-12 10:41:33.880 DEBUG (qtp1668016508-771) [ x:agglogtrackitem]
o.a.s.u.p.LogUpdateProcessorFactory PRE_UPDATE
commit\{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
\{{params(commit=true),defaults(wt=json)}}
2020-03-12 10:41:35.754 TRACE (qtp1668016508-3298) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2102003070806775224 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002598
refcount=1} LogPtr(4246525) map=1493020555
2020-03-12 10:42:23.140 DEBUG (qtp1668016508-107) [ x:agglogtrackitem]
o.a.s.u.DirectUpdateHandler2
updateDocument(add\{_version_=1660950824311848960,id=2101702170007764324})
2020-03-12 10:42:23.935 TRACE (qtp1668016508-380) [ x:agglogtrackitem]
o.a.s.u.UpdateLog TLOG: added id 2101806210189104124 to
tlog\{file=/data1/solr8/agglogtrackitem/data/tlog/tlog.0000000000000002605
refcount=1} LogPtr(5096503) map=2041040637
{noformat}
> Solr does not response most of the update request some times
> ------------------------------------------------------------
>
> Key: SOLR-14314
> URL: https://issues.apache.org/jira/browse/SOLR-14314
> Project: Solr
> Issue Type: Bug
> Security Level: Public(Default Security Level. Issues are Public)
> Reporter: Aaron Sun
> Priority: Critical
> Attachments: jstack_bad_state.log, solrlog.tar.gz
>
>
> Solr version:
> {noformat}
> solr-spec
> 8.4.1
> solr-impl
> 8.4.1 832bf13dd9187095831caf69783179d41059d013 - ishan - 2020-01-10 13:40:28
> lucene-spec
> 8.4.1
> lucene-impl
> 8.4.1 832bf13dd9187095831caf69783179d41059d013 - ishan - 2020-01-10 13:35:00
> {noformat}
>
> Java process:
> {noformat}
> java -Xms100G -Xmx200G -DSTOP.PORT=8078 -DSTOP.KEY=ardsolrstop
> -Dsolr.solr.home=/ardome/solr -Djetty.port=8983
> -Dsolr.log.dir=/var/ardendo/log -jar start.jar --module=http
> {noformat}
> Run on a powerful server with 32 cores, 265GB RAM.
> The problem is that time to time it start to get very slow to update solr
> documents, for example time out after 30 minutes.
> document size is around 20k~50K each, each http request send to /update is
> around 4MB~10MB.
> /update request is done by multi processes.
> Some of the update get response, but the differences between "QTime" and
> http response time is big, one example, qtime = 66s, http response time is
> 2304s.
> According to jstack for the thread state, lots of BLOCKED state.
> thread dump log is attached.
> Any hint would be appreciate, thanks!
>
>
>
>
>
>
>
>
>
>
>
>
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
