Closed vladak closed 4 months ago
Repeated the measurements using the same setup but with statsd metrics collection enabled. Also, I disabled Tomcat to avoid suggester rebuild interfering with the indexing (in terms of CPU load).
before (2 days 06:08:44):
after (1 day 20:08:07):
Now, there is something about the gaps of CPU usage in the second indexing phase, and this should certainly be investigated, however given it's overwhelmingly better that the previous solution makes this easy win.
I ran the index from scratch once again, this time watching the average load with a Python program. When the average load for the last minute dropped below 10, it grabbed jstack
of the indexer process and saved it to a file. In that case, there was only one big CPU usage depression in the graph. The corresponding jstack revealed that there are 48 OpenGrok-index-worker
threads (the number matches the --threads
indexer argument value) in RUNNABLE state, all sharing the same stack:
"OpenGrok-index-worker-9363" #9363 prio=5 os_prio=64 cpu=29296657.62ms elapsed=66415.23s tid=0x000000002aa4d000 nid=0x255d runnable [0x00007ff30e5a0000]
java.lang.Thread.State: RUNNABLE
at java.io.FileInputStream.readBytes(java.base@11.0.7-internal/Native Method)
at java.io.FileInputStream.read(java.base@11.0.7-internal/FileInputStream.java:279)
at java.lang.ProcessImpl$DeferredCloseInputStream.read(java.base@11.0.7-internal/ProcessImpl.java:805)
at java.io.BufferedInputStream.read1(java.base@11.0.7-internal/BufferedInputStream.java:290)
at java.io.BufferedInputStream.read(java.base@11.0.7-internal/BufferedInputStream.java:351)
- locked <0x00007fff2ff7dad0> (a java.io.BufferedInputStream)
at java.io.BufferedInputStream.fill(java.base@11.0.7-internal/BufferedInputStream.java:252)
at java.io.BufferedInputStream.read1(java.base@11.0.7-internal/BufferedInputStream.java:292)
at java.io.BufferedInputStream.read(java.base@11.0.7-internal/BufferedInputStream.java:351)
- locked <0x00007fff2ff8d980> (a java.io.BufferedInputStream)
at com.sun.org.apache.xerces.internal.impl.XMLEntityManager$RewindableInputStream.read(java.xml@11.0.7-internal/XMLEntityManager.java:3064)
at com.sun.org.apache.xerces.internal.impl.io.UTF8Reader.read(java.xml@11.0.7-internal/UTF8Reader.java:303)
at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.load(java.xml@11.0.7-internal/XMLEntityScanner.java:1904)
at com.sun.org.apache.xerces.internal.impl.XMLEntityScanner.scanContent(java.xml@11.0.7-internal/XMLEntityScanner.java:1032)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl$FragmentContentDriver.next(java.xml@11.0.7-internal/XMLDocumentFragmentScannerImpl.java:2744)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentScannerImpl.next(java.xml@11.0.7-internal/XMLDocumentScannerImpl.java:605)
at com.sun.org.apache.xerces.internal.impl.XMLDocumentFragmentScannerImpl.scanDocument(java.xml@11.0.7-internal/XMLDocumentFragmentScannerImpl.java:534)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(java.xml@11.0.7-internal/XML11Configuration.java:888)
at com.sun.org.apache.xerces.internal.parsers.XML11Configuration.parse(java.xml@11.0.7-internal/XML11Configuration.java:824)
at com.sun.org.apache.xerces.internal.parsers.XMLParser.parse(java.xml@11.0.7-internal/XMLParser.java:141)
at com.sun.org.apache.xerces.internal.parsers.AbstractSAXParser.parse(java.xml@11.0.7-internal/AbstractSAXParser.java:1216)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl$JAXPSAXParser.parse(java.xml@11.0.7-internal/SAXParserImpl.java:635)
at com.sun.org.apache.xerces.internal.jaxp.SAXParserImpl.parse(java.xml@11.0.7-internal/SAXParserImpl.java:324)
at javax.xml.parsers.SAXParser.parse(java.xml@11.0.7-internal/SAXParser.java:197)
at org.opengrok.indexer.history.SubversionAnnotationParser.processStream(SubversionAnnotationParser.java:87)
at org.opengrok.indexer.util.Executor.exec(Executor.java:229)
at org.opengrok.indexer.history.SubversionRepository.annotate(SubversionRepository.java:408)
at org.opengrok.indexer.history.HistoryGuru.getAnnotationFromRepository(HistoryGuru.java:292)
at org.opengrok.indexer.history.HistoryGuru.createAnnotationCache(HistoryGuru.java:1167)
at org.opengrok.indexer.index.IndexDatabase.createAnnotationCache(IndexDatabase.java:1307)
at org.opengrok.indexer.index.IndexDatabase.addFile(IndexDatabase.java:1286)
at org.opengrok.indexer.index.IndexDatabase.lambda$indexParallel$9(IndexDatabase.java:1920)
at org.opengrok.indexer.index.IndexDatabase$$Lambda$1030/0x00007ff311d90168.call(Unknown Source)
at java.util.concurrent.FutureTask.run(java.base@11.0.7-internal/FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.7-internal/ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.7-internal/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.7-internal/Thread.java:834)
Basically, at the point the tasks being processed were all pertaining to a single project that consisted of a Subversion repository. The annotation cache was enabled and such processing is more I/O than CPU bound for Subversion, hence the decrease.
While it would be nicer if the graph was smoother, e.g. by somehow mixing the jobs from various projects more evenly, I don't see it as a blocker for integration, esp. considering that annotation cache is disabled by default.
This change replaces the
ForkJoinPool
used for distributingaddFile()
tasks in the 2nd phase of indexer processing with fixed thread pool. In my case:-J=-Xmx48g -J=-server
using--renamedHistory 'on' -r dirbased -G -m '256' --threads 48 --historyThreads 48 --historyFileThreads 32
and annotation cache enabled for all projectsit shaves some 8+ hours from the total indexing time:
before:
after:
The distribution of the tasks is not as uniform - more often than not a single project occupies the fixed thread pool (while always using it to its full capacity unlike the
ForkJoin
), however the sub-optimal scheduling is gone. Also, I don't like the hazy promise of customForkJoinPool
to be used forparallelStream()
processing.