From solr-user-return-148231-archive-asf-public=cust-asf.ponee.io@lucene.apache.org Wed Jun 5 16:51:58 2019 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [207.244.88.153]) by mx-eu-01.ponee.io (Postfix) with SMTP id 00D7F18065D for ; Wed, 5 Jun 2019 18:51:57 +0200 (CEST) Received: (qmail 98722 invoked by uid 500); 5 Jun 2019 16:51:52 -0000 Mailing-List: contact solr-user-help@lucene.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: solr-user@lucene.apache.org Delivered-To: mailing list solr-user@lucene.apache.org Received: (qmail 98710 invoked by uid 99); 5 Jun 2019 16:51:51 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 05 Jun 2019 16:51:51 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 63C8CC2E67 for ; Wed, 5 Jun 2019 16:51:51 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -0.199 X-Spam-Level: X-Spam-Status: No, score=-0.199 tagged_above=-999 required=6.31 tests=[DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, RCVD_IN_DNSWL_NONE=-0.0001, SPF_HELO_NONE=0.001, SPF_PASS=-0.001, URIBL_BLOCKED=0.001] autolearn=disabled Authentication-Results: spamd4-us-west.apache.org (amavisd-new); dkim=pass (2048-bit key) header.d=gmail.com Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id 9o7ddFMQ0iUg for ; Wed, 5 Jun 2019 16:51:49 +0000 (UTC) Received: from mail-pg1-f176.google.com (mail-pg1-f176.google.com [209.85.215.176]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTPS id EE2275F560 for ; Wed, 5 Jun 2019 16:51:48 +0000 (UTC) Received: by mail-pg1-f176.google.com with SMTP id h17so12732856pgv.0 for ; Wed, 05 Jun 2019 09:51:48 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:content-transfer-encoding:mime-version:subject:date:references :to:in-reply-to:message-id; bh=ExYbbLlDuwvbm+06nKrAakJfi+mNnHPlAA8yWWXRhk8=; b=aBlWMkLUP1hwoDKuV6GeqtV6dygluMWS0TUVlxgO8Sb1WZ6U0m/M7bbIXW16yC5DFK Kls9uOXY03Z7oUEQeB/JlfSCCi94A1NPeHYGs1k9oQ75Y3rcefThxXXiSRLvL9UGL4NP 416ofk0KRG9PXUuaP/9bUKNEbNubivlcKkVyBbFcuEsVNE25u0eY48Vugi8Jr0MPch2Q OxsIrdgMPkAY6DUorx5FrbxWlp3Aq7HuJ3hUTjHOeGKUyG12mAfbU679lQ742KGh6XHI 6glLk84OxGZRSHDocaJFdX3ITCkYUQiJMUNeyyXOovpskkl7lTmXgf7KjJ/BpddB5rUP o9XA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:content-transfer-encoding:mime-version :subject:date:references:to:in-reply-to:message-id; bh=ExYbbLlDuwvbm+06nKrAakJfi+mNnHPlAA8yWWXRhk8=; b=C9SnahT5qIpK678x0CWRNXhFxrCVSh5Y/ceM+dQ59JhqQvzn+xBZT7bq2BMkMxpQCv yKzMvvCEec3k9NocOOM4FXOJxcQ1Zs2qvU3lCLCAdKs72VEPx1Se04+2G2OMZT9kqX/e yTeUkm4gVudk5S3QSKVNNVLx2XS1uQRATuvj7b4EmWH7M5d4d+x2BAsdSBDVmBpqd9Kg iZ/xJTcnaW3GM+9w33sqh0jzfJZvKHlvxpvGc8sZK6AujdzKG7Tg1IWhqOeQL0D4H/fF caJCLa6ctAuyKBCIsqa7ZHK08Ac43kM7alJ76xDSzU/3DSez1rcYegnVHx4B8BC+nH0x 520g== X-Gm-Message-State: APjAAAUhS6wNGgL3vcLK47NecIkhx59n1ZxEv6xfl24B/6CaZw5/AM2P ZADfDa3nXgF3lQWWDCXaMNiCL3kC X-Google-Smtp-Source: APXvYqyqfnQ6bj/x2ohWNl4pLPiovVteKcMR+C47B+dL2uljKao3s4z67Ze01c9dCTlCdj3Yqk8d3g== X-Received: by 2002:a63:f10e:: with SMTP id f14mr5770498pgi.226.1559753507313; Wed, 05 Jun 2019 09:51:47 -0700 (PDT) Received: from [192.168.1.122] (c-73-162-90-234.hsd1.ca.comcast.net. [73.162.90.234]) by smtp.gmail.com with ESMTPSA id d10sm23201244pgh.43.2019.06.05.09.51.46 for (version=TLS1_2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Wed, 05 Jun 2019 09:51:46 -0700 (PDT) From: Erick Erickson Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\)) Subject: Re: Slow soft-commit Date: Wed, 5 Jun 2019 09:51:45 -0700 References: To: solr-user@lucene.apache.org In-Reply-To: Message-Id: <4DE21066-584D-4BAD-B2CB-A962D178D46E@gmail.com> X-Mailer: Apple Mail (2.3445.104.11) Thanks for letting us know. Yeah, many thousands of fields is an = anti-pattern. At some point I=E2=80=99d like to put in a limit or log = warning or something so people would get warning when something like = this happens. And to make matters more =E2=80=9Cinteresting=E2=80=9D, the meta-data = associated with the fields doesn=E2=80=99t go away.. ever. You need to = re-index to a new collection. Certainly the soft commits should be much faster if you re-index without = using a new collection, but there=E2=80=99s still some inefficiencies in = the meta-data being kept. Best, Erick > On Jun 4, 2019, at 1:05 AM, Andr=C3=A9 Widhani = wrote: >=20 > almost forgot to report back, maybe it helps somebody else .... it = turned > out to be caused by a feature in our software being used in a way we = did > not anticipate. >=20 > That resulted in a lot (> 100.000) of different dynamic fields which > probably is an anti-pattern on its own, but the slow commits where = related > to the fact that these fields had DocValues. After some profiling, it > clearly showed a lot of time was spent in FieldInfos' = addOrUpdateInternal() > and related code. >=20 > Andr=C3=A9 >=20 >=20 > Am Mi., 22. Mai 2019 um 18:12 Uhr schrieb Andr=C3=A9 Widhani = : >=20 >> Hi everyone, >>=20 >> I need some advice how to debug slow soft commits. >>=20 >> We use Solr for searches in a DAM system and in similar setups, soft >> commits take about one to two seconds, in this case nearly ten = seconds. >> Solr runs on a dedicated VM with eight cores and 64 GB RAM (16G = heap), >> which is common scenario with our software and the index holds about = 20 >> million documents. Queries are as fast as expected. >>=20 >> This is Solr 7.5.0, stand-alone, auto hard-commit set to 60 seconds, = no >> explicit soft-commits but documents added with commitWhitin=3D5000 or = 1000 >> depending on the use case. No warm-up queries, caches set to zero. >>=20 >> I enabled infostream and debug logging. Here is a little test case = where I >> stopped any other requests to Solr and just manually added a single >> document and then posted a soft commit request. >>=20 >> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) >> o.a.s.u.DirectUpdateHandler2 start >> = commit{_version_=3D1634245942610755584,optimize=3Dfalse,openSearcher=3Dtru= e,waitSearcher=3Dtrue,expungeDeletes=3Dfalse,softCommit=3Dtrue,prepareComm= it=3Dfalse} >> 2019-05-22 17:19:42.160 DEBUG (qtp26728049-20) o.a.s.u.UpdateLog = TLOG: >> preSoftCommit: prevMap=3D1930097580 new map=3D1023061476 >> 2019-05-22 17:19:42.160 DEBUG (qtp26728049-20) >> o.a.s.c.CachingDirectoryFactory Reusing cached directory: >> = CachedDir<> >> 2019-05-22 17:19:42.160 DEBUG (qtp26728049-20) >> o.a.s.c.CachingDirectoryFactory Releasing directory: >> /solr/core-tex73oy02hnxgx1dqc14p5o-index1 0 false >> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) = o.a.s.u.LoggingInfoStream >> [DW][qtp26728049-20]: anyChanges? numDocsInRam=3D1 deletes=3Dtrue >> hasTickets:false pendingChangesInFullFlush: false >> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) = o.a.s.u.LoggingInfoStream >> [IW][qtp26728049-20]: nrtIsCurrent: infoVersion matches: false; DW = changes: >> true; BD changes: false >> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) = o.a.s.u.LoggingInfoStream >> [IW][qtp26728049-20]: flush at getReader >> ... a lot of things logged here (omitted) that happen within = milli-seconds >> ... >> 2019-05-22 17:19:42.168 INFO (qtp26728049-20) = o.a.s.u.LoggingInfoStream >> [IW][qtp26728049-20]: getReader took 8 msec >> 2019-05-22 17:19:47.499 INFO (qtp26728049-20) = o.a.s.s.SolrIndexSearcher >> Opening [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] main] >> 2019-05-22 17:19:47.499 DEBUG (qtp26728049-20) >> o.a.s.c.CachingDirectoryFactory incRef'ed: >> = CachedDir<> >> 2019-05-22 17:19:50.233 DEBUG (qtp26728049-20) = o.a.s.s.SolrIndexSearcher >> Closing [Searcher@78d9785[core-tex73oy02hnxgx1dqc14p5o-index1] = realtime] >> 2019-05-22 17:19:50.233 INFO (qtp26728049-20) = o.a.s.u.LoggingInfoStream >> [IW][qtp26728049-20]: decRefDeleter for NRT reader version=3D10560246 >> segments=3D_22lfz(7.5.0):c1033782/56603:delGen=3D2772 >> _22lfp(7.5.0):c1025574/39055:delGen=3D2113 >> _22lfr(7.5.0):c759249/32191:delGen=3D1386 >> _26q49(7.5.0):c923418/29825:delGen=3D958 >> _22lfx(7.5.0):c684064/30952:delGen=3D1098 >> _22lfv(7.5.0):c856317/78777:delGen=3D928 >> _22lg1(7.5.0):c1062384/188447:delGen=3D1750 >> _22lg0(7.5.0):c561881/1480:delGen=3D386 >> _22lg5(7.5.0):c1104218/1004:delGen=3D139 = _22lgh(7.5.0):c1156482/46:delGen=3D33 >> _22lgf(7.5.0):c626273/27:delGen=3D19 _22lfy(7.5.0):c697224/6:delGen=3D6= >> _22lgd(7.5.0):c399283/6:delGen=3D3 _22lgg(7.5.0):c482373/3:delGen=3D3 >> _22lg4(7.5.0):c656746/2:delGen=3D2 _22lgc(7.5.0):c664274/3:delGen=3D3 >> _22lg7(7.5.0):c703377 _22lfu(7.5.0):c700340/3:delGen=3D3 >> _22lg2(7.5.0):c743334 _22lg6(7.5.0):c1091387/44659:delGen=3D946 >> _22lfs(7.5.0):c845018 _22lg8(7.5.0):c675649 _22lg9(7.5.0):c686292 >> _22lft(7.5.0):c636751/1004:delGen=3D300 _22lgb(7.5.0):c664531 >> _22lga(7.5.0):c647696/1:delGen=3D1 _22lge(7.5.0):c659794 >> _22lfw(7.5.0):c568537/1:delGen=3D1 = _22lg3(7.5.0):c837568/1426:delGen=3D423 >> _26r20(7.5.0):c63899/10456:delGen=3D257 = _273qn(7.5.0):c39076/8075:delGen=3D323 >> _27q6g(7.5.0):c40830/8111:delGen=3D195 = _27aii(7.5.0):c30182/6777:delGen=3D287 >> _27tkq(7.5.0):c57620/6234:delGen=3D162 = _27jrm(7.5.0):c33298/4797:delGen=3D202 >> _280zq(7.5.0):c60476/2341:delGen=3D173 = _28h7x(7.5.0):c48570/453:delGen=3D35 >> _28c75(7.5.0):c29536/1088:delGen=3D47 = _28h71(7.5.0):c1191/138:delGen=3D5 >> _28idl(7.5.0):c782/57:delGen=3D6 _28ihc(7.5.0):c5398/348:delGen=3D9 >> _28ig3(7.5.0):c1118/302:delGen=3D4 _28j1s(7.5.0):c917/269:delGen=3D2 >> _28iu9(7.5.0):c758/129:delGen=3D4 _28j23(7.5.0):c567/70:delGen=3D2 >> _28j3j(7.5.0):c802/11:delGen=3D1 _28j3u(7.5.0):c697/11:delGen=3D2 >> _28iz5(7.5.0):c858/116:delGen=3D4 _28j2n(7.5.0):c566/78:delGen=3D1 >> _28j3t(7.5.0):C20/11:delGen=3D1 _28j3v(7.5.0):C13/8:delGen=3D1 = _28j3y(7.5.0):C1 >> 2019-05-22 17:19:50.234 DEBUG (qtp26728049-20) >> o.a.s.c.CachingDirectoryFactory Releasing directory: >> /solr/core-tex73oy02hnxgx1dqc14p5o-index1/index 3 false >> 2019-05-22 17:19:50.234 INFO (qtp26728049-20) >> o.a.s.u.DirectUpdateHandler2 end_commit_flush >> 2019-05-22 17:19:50.234 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ...Uninverting(_28j3z(7.5.0):C1)))}] from = [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3y(7.5.0):C1)))}] >> fieldValueCache{lookups=3D0, hits=3D0, cumulative_evictions=3D0, = size=3D0, >> hitratio=3D0.0, evictions=3D0, cumulative_lookups=3D0, = cumulative_hitratio=3D0.0, >> warmupTime=3D0, inserts=3D0, cumulative_inserts=3D0, = cumulative_hits=3D0} >> 2019-05-22 17:19:50.234 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming result for = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... Uninverting(_28j3z(7.5.0):C1)))}] >> fieldValueCache >> 2019-05-22 17:19:50.234 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3z(7.5.0):C1)))}] from >> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3y(7.5.0):C1)))}] >> filterCache{lookups=3D0, hits=3D0, cumulative_evictions=3D0, size=3D0, >> hitratio=3D0.0, evictions=3D0, cumulative_lookups=3D0, = cumulative_hitratio=3D0.0, >> warmupTime=3D0, inserts=3D0, cumulative_inserts=3D0, = cumulative_hits=3D0} >> 2019-05-22 17:19:50.234 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming result for = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3z(7.5.0):C1)))}] >> filterCache >> 2019-05-22 17:19:50.235 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3z(7.5.0):C1)))}] from >> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... Uninverting(_28j3y(7.5.0):C1)))}] >> queryResultCache{lookups=3D3, hits=3D2, cumulative_evictions=3D0, = size=3D1, >> hitratio=3D0.67, evictions=3D0, cumulative_lookups=3D865, >> cumulative_hitratio=3D0.97, warmupTime=3D0, inserts=3D1, = cumulative_inserts=3D29, >> cumulative_hits=3D836} >> 2019-05-22 17:19:50.235 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming result for = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... Uninverting(_28j3z(7.5.0):C1)))}] >> queryResultCache >> 2019-05-22 17:19:50.235 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3z(7.5.0):C1)))}] from >> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3y(7.5.0):C1)))}] >> documentCache{lookups=3D0, hits=3D0, cumulative_evictions=3D0, = size=3D0, >> hitratio=3D0.0, evictions=3D0, cumulative_lookups=3D0, = cumulative_hitratio=3D0.0, >> warmupTime=3D0, inserts=3D0, cumulative_inserts=3D0, = cumulative_hits=3D0} >> 2019-05-22 17:19:50.235 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher autowarming result for = [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... Uninverting(_28j3z(7.5.0):C1)))}] >> documentCache >> 2019-05-22 17:19:50.236 INFO >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.c.SolrCore [core-tex73oy02hnxgx1dqc14p5o-index1] Registered new >> searcher Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] >> = main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz= (7.5.0):c1033782/56603:delGen=3D2772) >> ... ... Uninverting(_28j3z(7.5.0):C1)))} >> 2019-05-22 17:19:50.237 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.s.SolrIndexSearcher Closing = Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1] >> main >> fieldValueCache{lookups=3D0, hits=3D0, cumulative_evictions=3D0, = size=3D0, >> hitratio=3D0.0, evictions=3D0, cumulative_lookups=3D0, = cumulative_hitratio=3D0.0, >> warmupTime=3D0, inserts=3D0, cumulative_inserts=3D0, = cumulative_hits=3D0} >> filterCache{lookups=3D0, hits=3D0, cumulative_evictions=3D0, size=3D0, >> hitratio=3D0.0, evictions=3D0, cumulative_lookups=3D0, = cumulative_hitratio=3D0.0, >> warmupTime=3D0, inserts=3D0, cumulative_inserts=3D0, = cumulative_hits=3D0} >> queryResultCache{lookups=3D3, hits=3D2, cumulative_evictions=3D0, = size=3D1, >> hitratio=3D0.67, evictions=3D0, cumulative_lookups=3D865, >> cumulative_hitratio=3D0.97, warmupTime=3D0, inserts=3D1, = cumulative_inserts=3D29, >> cumulative_hits=3D836} >> documentCache{lookups=3D0, hits=3D0, cumulative_evictions=3D0, = size=3D0, >> hitratio=3D0.0, evictions=3D0, cumulative_lookups=3D0, = cumulative_hitratio=3D0.0, >> warmupTime=3D0, inserts=3D0, cumulative_inserts=3D0, = cumulative_hits=3D0} >> 2019-05-22 17:19:50.237 INFO >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.u.LoggingInfoStream >> = [IW][searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5= o-index1]: >> decRefDeleter for NRT reader version=3D10560244 >> segments=3D_22lfz(7.5.0):c1033782/56603:delGen=3D2772 >> _22lfp(7.5.0):c1025574/39055:delGen=3D2113 >> _22lfr(7.5.0):c759249/32191:delGen=3D1386 >> _26q49(7.5.0):c923418/29825:delGen=3D958 >> _22lfx(7.5.0):c684064/30952:delGen=3D1098 >> _22lfv(7.5.0):c856317/78777:delGen=3D928 >> _22lg1(7.5.0):c1062384/188447:delGen=3D1750 >> _22lg0(7.5.0):c561881/1480:delGen=3D386 >> _22lg5(7.5.0):c1104218/1004:delGen=3D139 = _22lgh(7.5.0):c1156482/46:delGen=3D33 >> _22lgf(7.5.0):c626273/27:delGen=3D19 _22lfy(7.5.0):c697224/6:delGen=3D6= >> _22lgd(7.5.0):c399283/6:delGen=3D3 _22lgg(7.5.0):c482373/3:delGen=3D3 >> _22lg4(7.5.0):c656746/2:delGen=3D2 _22lgc(7.5.0):c664274/3:delGen=3D3 >> _22lg7(7.5.0):c703377 _22lfu(7.5.0):c700340/3:delGen=3D3 >> _22lg2(7.5.0):c743334 _22lg6(7.5.0):c1091387/44659:delGen=3D946 >> _22lfs(7.5.0):c845018 _22lg8(7.5.0):c675649 _22lg9(7.5.0):c686292 >> _22lft(7.5.0):c636751/1004:delGen=3D300 _22lgb(7.5.0):c664531 >> _22lga(7.5.0):c647696/1:delGen=3D1 _22lge(7.5.0):c659794 >> _22lfw(7.5.0):c568537/1:delGen=3D1 = _22lg3(7.5.0):c837568/1426:delGen=3D423 >> _26r20(7.5.0):c63899/10456:delGen=3D257 = _273qn(7.5.0):c39076/8075:delGen=3D323 >> _27q6g(7.5.0):c40830/8111:delGen=3D195 = _27aii(7.5.0):c30182/6777:delGen=3D287 >> _27tkq(7.5.0):c57620/6234:delGen=3D162 = _27jrm(7.5.0):c33298/4797:delGen=3D202 >> _280zq(7.5.0):c60476/2341:delGen=3D173 = _28h7x(7.5.0):c48570/453:delGen=3D35 >> _28c75(7.5.0):c29536/1088:delGen=3D47 = _28h71(7.5.0):c1191/138:delGen=3D5 >> _28idl(7.5.0):c782/57:delGen=3D6 _28ihc(7.5.0):c5398/348:delGen=3D9 >> _28ig3(7.5.0):c1118/302:delGen=3D4 _28j1s(7.5.0):c917/269:delGen=3D2 >> _28iu9(7.5.0):c758/129:delGen=3D4 _28j23(7.5.0):c567/70:delGen=3D2 >> _28j3j(7.5.0):c802/11:delGen=3D1 _28j3u(7.5.0):c697/11:delGen=3D2 >> _28iz5(7.5.0):c858/116:delGen=3D4 _28j2n(7.5.0):c566/78:delGen=3D1 >> _28j3t(7.5.0):C20/11:delGen=3D1 _28j3v(7.5.0):C13/8:delGen=3D1 = _28j3y(7.5.0):C1 >> 2019-05-22 17:19:50.237 DEBUG >> = (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-in= dex1) >> o.a.s.c.CachingDirectoryFactory Releasing directory: >> /solr/core-tex73oy02hnxgx1dqc14p5o-index1/index 2 false >> 2019-05-22 17:19:50.237 DEBUG (qtp26728049-20) [ >> x:core-tex73oy02hnxgx1dqc14p5o-index1] = o.a.s.u.p.LogUpdateProcessorFactory >> PRE_UPDATE FINISH {{params(),defaults(wt=3Dxml)}} >> 2019-05-22 17:19:50.237 INFO (qtp26728049-20) [ >> x:core-tex73oy02hnxgx1dqc14p5o-index1] = o.a.s.u.p.LogUpdateProcessorFactory >> [core-tex73oy02hnxgx1dqc14p5o-index1] webapp=3D/solr path=3D/update >> params=3D{}{commit=3D} 0 8078 >>=20 >> You see the part (line 10 from the log excerpt) where it spends = approx. >> five seconds without logging anything. >>=20 >> Now I am aware that there could be several reasons for it, but it = would >> probably help me I knew what is actually being done in that part of = code >> where it is silent so I can look further. >>=20 >> This is not GC related, btw, this was one of the first things I = checked >> and the pause is always at the same place and it is always taking = approx. >> the same time. >>=20 >> Thanks, >> Andr=C3=A9 >>=20 >=20 >=20 > --=20 > Andr=C3=A9 Widhani > Research & Development >=20 > *Don=E2=80=99t miss our latest news! * > www.digicol.de/news >=20 > Digital Collections Content Systems GmbH > Hindenburgstra=C3=9Fe 49, 22297 Hamburg >=20 > Tel: +49 40 23535-128 > Fax: +49 40 23535-180 > E-Mail: andre.widhani@digicol.de > Internet: www.digicol.de > HRB Hamburg 48373, Gesch=C3=A4ftsf=C3=BChrer: J=C3=B6rn Olsen >=20 > Haftungsbeschr=C3=A4nkung: > Diese Nachricht enth=C3=A4lt vertrauliche Informationen und ist = ausschlie=C3=9Flich > f=C3=BCr den Adressaten bestimmt. Der Gebrauch durch Dritte ist = verboten. Das > Unternehmen ist nicht verantwortlich f=C3=BCr die ordnungsgem=C3=A4=C3=9F= e, vollst=C3=A4ndige > oder verz=C3=B6gerungsfreie =C3=9Cbertragung dieser Nachricht.