[jira] [Commented] (OAK-9184) Very slow, potential endless loop in LucenePropertyIndex.loadDocs()

2020-08-31 Thread Thomas Mueller (Jira)


[ 
https://issues.apache.org/jira/browse/OAK-9184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17187714#comment-17187714
 ] 

Thomas Mueller commented on OAK-9184:
-

http://svn.apache.org/r1881341 (1.22 branch)

> Very slow, potential endless loop in LucenePropertyIndex.loadDocs()
> ---
>
> Key: OAK-9184
> URL: https://issues.apache.org/jira/browse/OAK-9184
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Affects Versions: 1.22.4, 1.32.0, 1.8.23
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
> Fix For: 1.34.0
>
>
> We found one case of a very slow, possibly endless loop in this method. 
> {noformat}
> java.lang.Thread.State: RUNNABLE at 
> org.apache.lucene.search.TopScoreDocCollector$InOrderPagingScoreDocCollector.collect(TopScoreDocCollector.java:85)
>  at org.apache.lucene.search.Scorer.score(Scorer.java:65) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:491) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:448) at 
> org.apache.lucene.search.IndexSearcher.searchAfter(IndexSearcher.java:243) at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.loadDocs(LucenePropertyIndex.java:434)
>  at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.computeNext(LucenePropertyIndex.java:353)
> {noformat}
> Background: Many threads are waiting to lock here:
> {noformat}
>   - waiting to lock <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.acquireIndexNode(IndexTracker.java:202)
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null;
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path); <<= synchronized method
> }
> }
> {noformat}
> And the thread that is holding that (synchronized) lock on IndexTracker is 
> also waiting to get a write lock here:
> {noformat}
> "oak-lucene-992" #21559 daemon prio=1 os_prio=0 tid=0x7ed0280ad000 
> nid=0x1be8 waiting on condition [0x7fb96c352000]
>java.lang.Thread.State: WAITING (parking)
>   at sun.misc.Unsafe.park(Native Method)
>   - parking to wait for  <0x7fbedad77210> (a 
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
>   at 
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexNodeManager.close(IndexNodeManager.java:174)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.close(IndexTracker.java:104)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:114)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   void close() throws IOException {
> lock.writeLock().lock(); <<== waiting here
> try {
> checkState(!closed);
> closed = true;
> } finally {
> lock.writeLock().unlock();
> }
> {noformat}
> It looks like a read lock is not released. The places where a read lock is 
> acquired:
> {noformat}
> IndexNode acquire() {
> lock.readLock().lock();
>   (released if the method returns null or throws an exception)
> private void release() {
> lock.readLock().unlock();
> }
> {noformat}
> acquire() is called in acquireIndexNode:
> {noformat}
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null; <<== 
> here
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path);
> }
> }
> private synchronized IndexNode findIndexNode(String path) {
> // Retry the lookup from acquireIndexNode now that we're
> 

[jira] [Commented] (OAK-9184) Very slow, potential endless loop in LucenePropertyIndex.loadDocs()

2020-08-31 Thread Thomas Mueller (Jira)


[ 
https://issues.apache.org/jira/browse/OAK-9184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17187704#comment-17187704
 ] 

Thomas Mueller commented on OAK-9184:
-

http://svn.apache.org/r1881340 (1.8 branch)

> Very slow, potential endless loop in LucenePropertyIndex.loadDocs()
> ---
>
> Key: OAK-9184
> URL: https://issues.apache.org/jira/browse/OAK-9184
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Affects Versions: 1.22.4, 1.32.0, 1.8.23
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
> Fix For: 1.34.0
>
>
> We found one case of a very slow, possibly endless loop in this method. 
> {noformat}
> java.lang.Thread.State: RUNNABLE at 
> org.apache.lucene.search.TopScoreDocCollector$InOrderPagingScoreDocCollector.collect(TopScoreDocCollector.java:85)
>  at org.apache.lucene.search.Scorer.score(Scorer.java:65) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:491) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:448) at 
> org.apache.lucene.search.IndexSearcher.searchAfter(IndexSearcher.java:243) at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.loadDocs(LucenePropertyIndex.java:434)
>  at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.computeNext(LucenePropertyIndex.java:353)
> {noformat}
> Background: Many threads are waiting to lock here:
> {noformat}
>   - waiting to lock <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.acquireIndexNode(IndexTracker.java:202)
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null;
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path); <<= synchronized method
> }
> }
> {noformat}
> And the thread that is holding that (synchronized) lock on IndexTracker is 
> also waiting to get a write lock here:
> {noformat}
> "oak-lucene-992" #21559 daemon prio=1 os_prio=0 tid=0x7ed0280ad000 
> nid=0x1be8 waiting on condition [0x7fb96c352000]
>java.lang.Thread.State: WAITING (parking)
>   at sun.misc.Unsafe.park(Native Method)
>   - parking to wait for  <0x7fbedad77210> (a 
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
>   at 
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexNodeManager.close(IndexNodeManager.java:174)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.close(IndexTracker.java:104)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:114)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   void close() throws IOException {
> lock.writeLock().lock(); <<== waiting here
> try {
> checkState(!closed);
> closed = true;
> } finally {
> lock.writeLock().unlock();
> }
> {noformat}
> It looks like a read lock is not released. The places where a read lock is 
> acquired:
> {noformat}
> IndexNode acquire() {
> lock.readLock().lock();
>   (released if the method returns null or throws an exception)
> private void release() {
> lock.readLock().unlock();
> }
> {noformat}
> acquire() is called in acquireIndexNode:
> {noformat}
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null; <<== 
> here
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path);
> }
> }
> private synchronized IndexNode findIndexNode(String path) {
> // Retry the lookup from acquireIndexNode now that we're
>  

[jira] [Commented] (OAK-9184) Very slow, potential endless loop in LucenePropertyIndex.loadDocs()

2020-08-28 Thread Thomas Mueller (Jira)


[ 
https://issues.apache.org/jira/browse/OAK-9184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17186321#comment-17186321
 ] 

Thomas Mueller commented on OAK-9184:
-

http://svn.apache.org/r1881271 (trunk)

Now need to backport to Oak 1.8

> Very slow, potential endless loop in LucenePropertyIndex.loadDocs()
> ---
>
> Key: OAK-9184
> URL: https://issues.apache.org/jira/browse/OAK-9184
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Affects Versions: 1.22.4, 1.32.0, 1.8.23
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> We found one case of a very slow, possibly endless loop in this method. 
> {noformat}
> java.lang.Thread.State: RUNNABLE at 
> org.apache.lucene.search.TopScoreDocCollector$InOrderPagingScoreDocCollector.collect(TopScoreDocCollector.java:85)
>  at org.apache.lucene.search.Scorer.score(Scorer.java:65) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:491) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:448) at 
> org.apache.lucene.search.IndexSearcher.searchAfter(IndexSearcher.java:243) at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.loadDocs(LucenePropertyIndex.java:434)
>  at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.computeNext(LucenePropertyIndex.java:353)
> {noformat}
> Background: Many threads are waiting to lock here:
> {noformat}
>   - waiting to lock <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.acquireIndexNode(IndexTracker.java:202)
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null;
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path); <<= synchronized method
> }
> }
> {noformat}
> And the thread that is holding that (synchronized) lock on IndexTracker is 
> also waiting to get a write lock here:
> {noformat}
> "oak-lucene-992" #21559 daemon prio=1 os_prio=0 tid=0x7ed0280ad000 
> nid=0x1be8 waiting on condition [0x7fb96c352000]
>java.lang.Thread.State: WAITING (parking)
>   at sun.misc.Unsafe.park(Native Method)
>   - parking to wait for  <0x7fbedad77210> (a 
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
>   at 
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexNodeManager.close(IndexNodeManager.java:174)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.close(IndexTracker.java:104)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:114)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   void close() throws IOException {
> lock.writeLock().lock(); <<== waiting here
> try {
> checkState(!closed);
> closed = true;
> } finally {
> lock.writeLock().unlock();
> }
> {noformat}
> It looks like a read lock is not released. The places where a read lock is 
> acquired:
> {noformat}
> IndexNode acquire() {
> lock.readLock().lock();
>   (released if the method returns null or throws an exception)
> private void release() {
> lock.readLock().unlock();
> }
> {noformat}
> acquire() is called in acquireIndexNode:
> {noformat}
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null; <<== 
> here
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path);
> }
> }
> private synchronized IndexNode findIndexNode(String path) {
> // Retry the lookup from acquireIndexNode now that we're
> 

[jira] [Commented] (OAK-9184) Very slow, potential endless loop in LucenePropertyIndex.loadDocs()

2020-08-27 Thread Thomas Mueller (Jira)


[ 
https://issues.apache.org/jira/browse/OAK-9184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17185676#comment-17185676
 ] 

Thomas Mueller commented on OAK-9184:
-

* Logs a warning after 30 seconds.
 * If repeated more than once, and after 3 minutes, an error is logged (with 
stack trace) and the loop stops.
 * Configurable over system properties.
 * No test case, but I tested it manually using a breakpoint.

> Very slow, potential endless loop in LucenePropertyIndex.loadDocs()
> ---
>
> Key: OAK-9184
> URL: https://issues.apache.org/jira/browse/OAK-9184
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Affects Versions: 1.22.4, 1.32.0, 1.8.23
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> We found one case of a very slow, possibly endless loop in this method. 
> {noformat}
> java.lang.Thread.State: RUNNABLE at 
> org.apache.lucene.search.TopScoreDocCollector$InOrderPagingScoreDocCollector.collect(TopScoreDocCollector.java:85)
>  at org.apache.lucene.search.Scorer.score(Scorer.java:65) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:491) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:448) at 
> org.apache.lucene.search.IndexSearcher.searchAfter(IndexSearcher.java:243) at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.loadDocs(LucenePropertyIndex.java:434)
>  at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.computeNext(LucenePropertyIndex.java:353)
> {noformat}
> Background: Many threads are waiting to lock here:
> {noformat}
>   - waiting to lock <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.acquireIndexNode(IndexTracker.java:202)
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null;
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path); <<= synchronized method
> }
> }
> {noformat}
> And the thread that is holding that (synchronized) lock on IndexTracker is 
> also waiting to get a write lock here:
> {noformat}
> "oak-lucene-992" #21559 daemon prio=1 os_prio=0 tid=0x7ed0280ad000 
> nid=0x1be8 waiting on condition [0x7fb96c352000]
>java.lang.Thread.State: WAITING (parking)
>   at sun.misc.Unsafe.park(Native Method)
>   - parking to wait for  <0x7fbedad77210> (a 
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
>   at 
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexNodeManager.close(IndexNodeManager.java:174)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.close(IndexTracker.java:104)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:114)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   void close() throws IOException {
> lock.writeLock().lock(); <<== waiting here
> try {
> checkState(!closed);
> closed = true;
> } finally {
> lock.writeLock().unlock();
> }
> {noformat}
> It looks like a read lock is not released. The places where a read lock is 
> acquired:
> {noformat}
> IndexNode acquire() {
> lock.readLock().lock();
>   (released if the method returns null or throws an exception)
> private void release() {
> lock.readLock().unlock();
> }
> {noformat}
> acquire() is called in acquireIndexNode:
> {noformat}
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null; <<== 
> here
> if (indexNode != null) {
> return indexNode;
> } else {
> return 

[jira] [Commented] (OAK-9184) Very slow, potential endless loop in LucenePropertyIndex.loadDocs()

2020-08-27 Thread Thomas Mueller (Jira)


[ 
https://issues.apache.org/jira/browse/OAK-9184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17185673#comment-17185673
 ] 

Thomas Mueller commented on OAK-9184:
-

[https://github.com/oak-indexing/jackrabbit-oak/pull/274]

> Very slow, potential endless loop in LucenePropertyIndex.loadDocs()
> ---
>
> Key: OAK-9184
> URL: https://issues.apache.org/jira/browse/OAK-9184
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Affects Versions: 1.22.4, 1.32.0, 1.8.23
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> We found one case of a very slow, possibly endless loop in this method. 
> {noformat}
> java.lang.Thread.State: RUNNABLE at 
> org.apache.lucene.search.TopScoreDocCollector$InOrderPagingScoreDocCollector.collect(TopScoreDocCollector.java:85)
>  at org.apache.lucene.search.Scorer.score(Scorer.java:65) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:491) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:448) at 
> org.apache.lucene.search.IndexSearcher.searchAfter(IndexSearcher.java:243) at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.loadDocs(LucenePropertyIndex.java:434)
>  at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.computeNext(LucenePropertyIndex.java:353)
> {noformat}
> Background: Many threads are waiting to lock here:
> {noformat}
>   - waiting to lock <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.acquireIndexNode(IndexTracker.java:202)
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null;
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path); <<= synchronized method
> }
> }
> {noformat}
> And the thread that is holding that (synchronized) lock on IndexTracker is 
> also waiting to get a write lock here:
> {noformat}
> "oak-lucene-992" #21559 daemon prio=1 os_prio=0 tid=0x7ed0280ad000 
> nid=0x1be8 waiting on condition [0x7fb96c352000]
>java.lang.Thread.State: WAITING (parking)
>   at sun.misc.Unsafe.park(Native Method)
>   - parking to wait for  <0x7fbedad77210> (a 
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
>   at 
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexNodeManager.close(IndexNodeManager.java:174)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.close(IndexTracker.java:104)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:114)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   void close() throws IOException {
> lock.writeLock().lock(); <<== waiting here
> try {
> checkState(!closed);
> closed = true;
> } finally {
> lock.writeLock().unlock();
> }
> {noformat}
> It looks like a read lock is not released. The places where a read lock is 
> acquired:
> {noformat}
> IndexNode acquire() {
> lock.readLock().lock();
>   (released if the method returns null or throws an exception)
> private void release() {
> lock.readLock().unlock();
> }
> {noformat}
> acquire() is called in acquireIndexNode:
> {noformat}
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null; <<== 
> here
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path);
> }
> }
> private synchronized IndexNode findIndexNode(String path) {
> // Retry the lookup from acquireIndexNode now that we're
> // 

[jira] [Commented] (OAK-9184) Very slow, potential endless loop in LucenePropertyIndex.loadDocs()

2020-08-25 Thread Thomas Mueller (Jira)


[ 
https://issues.apache.org/jira/browse/OAK-9184?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel=17183860#comment-17183860
 ] 

Thomas Mueller commented on OAK-9184:
-

I want to ensure this loop stops after a configurable time, by default after 2 
minutes. That is to ensure very large indexes, combined with slow queries, can 
not cause issues.

> Very slow, potential endless loop in LucenePropertyIndex.loadDocs()
> ---
>
> Key: OAK-9184
> URL: https://issues.apache.org/jira/browse/OAK-9184
> Project: Jackrabbit Oak
>  Issue Type: Improvement
>  Components: lucene
>Affects Versions: 1.22.4, 1.32.0, 1.8.23
>Reporter: Thomas Mueller
>Assignee: Thomas Mueller
>Priority: Major
>
> We found one case of a very slow, possibly endless loop in this method. 
> {noformat}
> java.lang.Thread.State: RUNNABLE at 
> org.apache.lucene.search.TopScoreDocCollector$InOrderPagingScoreDocCollector.collect(TopScoreDocCollector.java:85)
>  at org.apache.lucene.search.Scorer.score(Scorer.java:65) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:621) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:491) at 
> org.apache.lucene.search.IndexSearcher.search(IndexSearcher.java:448) at 
> org.apache.lucene.search.IndexSearcher.searchAfter(IndexSearcher.java:243) at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.loadDocs(LucenePropertyIndex.java:434)
>  at 
> org.apache.jackrabbit.oak.plugins.index.lucene.LucenePropertyIndex$1.computeNext(LucenePropertyIndex.java:353)
> {noformat}
> Background: Many threads are waiting to lock here:
> {noformat}
>   - waiting to lock <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.acquireIndexNode(IndexTracker.java:202)
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null;
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path); <<= synchronized method
> }
> }
> {noformat}
> And the thread that is holding that (synchronized) lock on IndexTracker is 
> also waiting to get a write lock here:
> {noformat}
> "oak-lucene-992" #21559 daemon prio=1 os_prio=0 tid=0x7ed0280ad000 
> nid=0x1be8 waiting on condition [0x7fb96c352000]
>java.lang.Thread.State: WAITING (parking)
>   at sun.misc.Unsafe.park(Native Method)
>   - parking to wait for  <0x7fbedad77210> (a 
> java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
>   at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
>   at 
> java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
>   at 
> java.util.concurrent.locks.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexNodeManager.close(IndexNodeManager.java:174)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.close(IndexTracker.java:104)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   at 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker.update(IndexTracker.java:114)
>   - locked <0x7fbd804a9448> (a 
> org.apache.jackrabbit.oak.plugins.index.lucene.IndexTracker)
>   void close() throws IOException {
> lock.writeLock().lock(); <<== waiting here
> try {
> checkState(!closed);
> closed = true;
> } finally {
> lock.writeLock().unlock();
> }
> {noformat}
> It looks like a read lock is not released. The places where a read lock is 
> acquired:
> {noformat}
> IndexNode acquire() {
> lock.readLock().lock();
>   (released if the method returns null or throws an exception)
> private void release() {
> lock.readLock().unlock();
> }
> {noformat}
> acquire() is called in acquireIndexNode:
> {noformat}
> public IndexNode acquireIndexNode(String path) {
> IndexNodeManager index = indices.get(path);
> IndexNode indexNode = index != null ? index.acquire() : null; <<== 
> here
> if (indexNode != null) {
> return indexNode;
> } else {
> return findIndexNode(path);
> }
> }
> private synchronized IndexNode