indexer CPU usage increased by factor 5 after 1.5 to 1.7 upgrade

[der-eismann]

Describe the bug
I recently upgraded our OpenGrok instance by simply changing the tag of the Docker image from 1.5.12 to 1.7.3. Since then the duration of the periodic reindex rose from 3,5 minutes to 17 minutes. I was aware that the 1.7.0 release mentioned

This means the initial reindex after upgrading to this version will take much longer. Subsequent reindex times will be normal.

Since the subsequent reindex times aren't normal I guess this is a bug. This is how the CPU usage looks in Grafana since the upgrade:

To Reproduce
Steps to reproduce the behavior:

• Have OpenGrok 1.5.12 running on Docker
• Upgrade to OpenGrok 1.7.3 on Docker

Expected behavior
Continue normal operation

[vladak]

What kind of repositories are indexed ? How many of them ? It would be helpful if you could extract the partial times from indexer logs (entries with took and time value) so that we can see which indexing phase if affected.

This is very likely related to the conversion of Git handling to JGit.

[vladak]

Also, getting the stack traces of the indexer using jstack at the point CPU is pegged would be beneficial.

[vladak]

This is very likely related to the conversion of Git handling to JGit.

Actually, another candidate could be the XML serialization restrictions.

[der-eismann]

Sorry for not giving more information. We index 223 Git repositories with a variety of complexity. Here are some log entries:

INFO: done invalidating 1 repositories (took 316 ms)
INFO: Done historycache for /opengrok/src/repo-1 (took 67 ms)
INFO: Done history cache for all repositories (took 115 ms)
INFO: Done traversal of directory /repo-1 (took 3.626 seconds)
INFO: Done indexing of directory /repo-1 (took 2.353 seconds)
INFO: Done optimizing index for project repo-1 (took 3.770 seconds)
INFO: Done indexing data of all repositories (took 13.325 seconds)
INFO: Indexer finished (took 14.918 seconds)

INFO: done invalidating 1 repositories (took 594 ms)
INFO: Done historycache for /opengrok/src/repo-2 (took 62 ms)
INFO: Done history cache for all repositories (took 144 ms)
INFO: Done traversal of directory /repo-2 (took 1.564 seconds)
INFO: Done indexing of directory /repo-2 (took 173 ms)
INFO: Done optimizing index for project repo-2 (took 1.373 seconds)
INFO: Done indexing data of all repositories (took 5.631 seconds)
INFO: Indexer finished (took 8.21 seconds)

# Our largest repository
INFO: done invalidating 1 repositories (took 1.127 seconds)
INFO: Done historycache for /opengrok/src/repo-3 (took 0:01:02)
INFO: Done history cache for all repositories (took 0:01:02)
INFO: Done traversal of directory /repo-3 (took 17.30 seconds)
INFO: Done indexing of directory /repo-3 (took 17.522 seconds)
INFO: Done optimizing index for project repo-3 (took 10.489 seconds)
INFO: Done indexing data of all repositories (took 49.297 seconds)
INFO: Indexer finished (took 0:01:54)

For jstack I'll need to figure out how to do this first.

Also we run the Docker container with NOMIRROR=true, everything else is default.

[der-eismann]

Here's the jstack output:

2021-06-11 12:06:04
Full thread dump OpenJDK 64-Bit Server VM (11.0.11+9 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007fc7f402e6f0, length=31, elements={
0x00007fc838016000, 0x00007fc8380b3800, 0x00007fc8380b5800, 0x00007fc8380bc800,
0x00007fc8380be800, 0x00007fc8380c0800, 0x00007fc8380c3000, 0x00007fc8380c5000,
0x00007fc8380fb000, 0x00007fc838f03800, 0x00007fc7ec9fa800, 0x00007fc7ec577000,
0x00007fc7f0799000, 0x00007fc839075000, 0x00007fc838b32800, 0x00007fc838cff000,
0x00007fc838cba000, 0x00007fc838c3a000, 0x00007fc838649800, 0x00007fc838158800,
0x00007fc83815a000, 0x00007fc83815c000, 0x00007fc8385ed800, 0x00007fc8385ef800,
0x00007fc838156000, 0x00007fc8385d4800, 0x00007fc8385d6800, 0x00005614d3564800,
0x00007fc81406c000, 0x00007fc7e4004800, 0x00007fc7f405f000
}

"main" #1 prio=5 os_prio=0 cpu=11300.96ms elapsed=9194.27s tid=0x00007fc838016000 nid=0x13 runnable  [0x00007fc83e537000]
   java.lang.Thread.State: RUNNABLE
	at java.net.PlainSocketImpl.socketAccept(java.base@11.0.11/Native Method)
	at java.net.AbstractPlainSocketImpl.accept(java.base@11.0.11/AbstractPlainSocketImpl.java:458)
	at java.net.ServerSocket.implAccept(java.base@11.0.11/ServerSocket.java:565)
	at java.net.ServerSocket.accept(java.base@11.0.11/ServerSocket.java:533)
	at org.apache.catalina.core.StandardServer.await(StandardServer.java:609)
	at org.apache.catalina.startup.Catalina.await(Catalina.java:887)
	at org.apache.catalina.startup.Catalina.start(Catalina.java:833)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.11/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.11/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.11/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@11.0.11/Method.java:566)
	at org.apache.catalina.startup.Bootstrap.start(Bootstrap.java:342)
	at org.apache.catalina.startup.Bootstrap.main(Bootstrap.java:473)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=39.30ms elapsed=9194.18s tid=0x00007fc8380b3800 nid=0x1a waiting on condition  [0x00007fc820292000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.11/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@11.0.11/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.11/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=30.19ms elapsed=9194.18s tid=0x00007fc8380b5800 nid=0x1b in Object.wait()  [0x00007fc820191000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000000c5830a50> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.11/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.51ms elapsed=9194.18s tid=0x00007fc8380bc800 nid=0x1c runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=484.56ms elapsed=9194.18s tid=0x00007fc8380be800 nid=0x1d runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=69317.17ms elapsed=9194.18s tid=0x00007fc8380c0800 nid=0x1e waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #7 daemon prio=9 os_prio=0 cpu=10159.47ms elapsed=9194.18s tid=0x00007fc8380c3000 nid=0x1f waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #8 daemon prio=9 os_prio=0 cpu=215.85ms elapsed=9194.18s tid=0x00007fc8380c5000 nid=0x20 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #9 daemon prio=8 os_prio=0 cpu=7.70ms elapsed=9194.15s tid=0x00007fc8380fb000 nid=0x21 in Object.wait()  [0x00007fc8182e6000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <no object reference available>
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000000c5954c80> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@11.0.11/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)
	at jdk.internal.misc.InnocuousThread.run(java.base@11.0.11/InnocuousThread.java:134)

"expirationThread" #12 prio=5 os_prio=0 cpu=53.07ms elapsed=9185.92s tid=0x00007fc838f03800 nid=0x24 in Object.wait()  [0x00007fc7e2570000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <no object reference available>
	at java.util.TimerThread.mainLoop(java.base@11.0.11/Timer.java:553)
	- waiting to re-lock in wait() <0x00000000c6b7f210> (a java.util.TaskQueue)
	at java.util.TimerThread.run(java.base@11.0.11/Timer.java:506)

"background~resource~releaser" #15 daemon prio=5 os_prio=0 cpu=0.36ms elapsed=9184.54s tid=0x00007fc7ec9fa800 nid=0x27 waiting on condition  [0x00007fc7e186d000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c6b797c0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.ArrayBlockingQueue.take(java.base@11.0.11/ArrayBlockingQueue.java:417)
	at net.openhft.chronicle.core.io.BackgroundResourceReleaser.runReleaseResources(BackgroundResourceReleaser.java:27)
	at net.openhft.chronicle.core.io.BackgroundResourceReleaser$$Lambda$428/0x00000008403c6840.run(Unknown Source)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"chronicle-analytics-http-client" #16 daemon prio=5 os_prio=0 cpu=334.09ms elapsed=9184.49s tid=0x00007fc7ec577000 nid=0x28 waiting on condition  [0x00007fc7e176c000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c6b79ab0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"pool-1-thread-1" #21 prio=5 os_prio=0 cpu=0.20ms elapsed=9176.93s tid=0x00007fc7f0799000 nid=0x2d waiting on condition  [0x00007fc7e1f6e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c6b8c9c8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.11/AbstractQueuedSynchronizer.java:2123)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Catalina-utility-1" #22 prio=1 os_prio=0 cpu=816.36ms elapsed=9176.91s tid=0x00007fc839075000 nid=0x2e waiting on condition  [0x00007fc7e226f000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c5aa2f70> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.11/AbstractQueuedSynchronizer.java:2123)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-1" #23 daemon prio=5 os_prio=0 cpu=35112.96ms elapsed=9176.91s tid=0x00007fc838b32800 nid=0x2f waiting on condition  [0x00007fc7dee64000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-2" #24 daemon prio=5 os_prio=0 cpu=23184.35ms elapsed=9176.91s tid=0x00007fc838cff000 nid=0x30 waiting on condition  [0x00007fc7ded63000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-3" #25 daemon prio=5 os_prio=0 cpu=22058.66ms elapsed=9176.91s tid=0x00007fc838cba000 nid=0x31 waiting on condition  [0x00007fc7dec62000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-4" #26 daemon prio=5 os_prio=0 cpu=24976.87ms elapsed=9176.91s tid=0x00007fc838c3a000 nid=0x32 waiting on condition  [0x00007fc7deb61000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-5" #27 daemon prio=5 os_prio=0 cpu=22794.66ms elapsed=9176.91s tid=0x00007fc838649800 nid=0x33 waiting on condition  [0x00007fc7dea60000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-6" #28 daemon prio=5 os_prio=0 cpu=18993.74ms elapsed=9176.91s tid=0x00007fc838158800 nid=0x34 waiting on condition  [0x00007fc7de95f000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-7" #29 daemon prio=5 os_prio=0 cpu=17102.57ms elapsed=9176.91s tid=0x00007fc83815a000 nid=0x35 waiting on condition  [0x00007fc7de85e000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-8" #30 daemon prio=5 os_prio=0 cpu=35593.76ms elapsed=9176.91s tid=0x00007fc83815c000 nid=0x36 waiting on condition  [0x00007fc7de75d000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-9" #31 daemon prio=5 os_prio=0 cpu=20499.00ms elapsed=9176.91s tid=0x00007fc8385ed800 nid=0x37 waiting on condition  [0x00007fc7de65c000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-exec-10" #32 daemon prio=5 os_prio=0 cpu=35472.20ms elapsed=9176.91s tid=0x00007fc8385ef800 nid=0x38 waiting on condition  [0x00007fc7de55b000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7c6fb30> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:108)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-Poller" #33 daemon prio=5 os_prio=0 cpu=1496.24ms elapsed=9176.90s tid=0x00007fc838156000 nid=0x39 runnable  [0x00007fc7de45a000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.EPoll.wait(java.base@11.0.11/Native Method)
	at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@11.0.11/EPollSelectorImpl.java:120)
	at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@11.0.11/SelectorImpl.java:124)
	- locked <0x00000000c7c76f00> (a sun.nio.ch.Util$2)
	- locked <0x00000000c7c769c0> (a sun.nio.ch.EPollSelectorImpl)
	at sun.nio.ch.SelectorImpl.select(java.base@11.0.11/SelectorImpl.java:136)
	at org.apache.tomcat.util.net.NioEndpoint$Poller.run(NioEndpoint.java:763)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"http-nio-8080-Acceptor" #34 daemon prio=5 os_prio=0 cpu=772.91ms elapsed=9176.90s tid=0x00007fc8385d4800 nid=0x3a runnable  [0x00007fc7de359000]
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.ServerSocketChannelImpl.accept0(java.base@11.0.11/Native Method)
	at sun.nio.ch.ServerSocketChannelImpl.accept(java.base@11.0.11/ServerSocketChannelImpl.java:533)
	at sun.nio.ch.ServerSocketChannelImpl.accept(java.base@11.0.11/ServerSocketChannelImpl.java:285)
	at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:514)
	at org.apache.tomcat.util.net.NioEndpoint.serverSocketAccept(NioEndpoint.java:79)
	at org.apache.tomcat.util.net.Acceptor.run(Acceptor.java:106)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Catalina-utility-2" #35 prio=1 os_prio=0 cpu=848.84ms elapsed=9176.90s tid=0x00007fc8385d6800 nid=0x3b waiting on condition  [0x00007fc7de258000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c5aa2f70> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:1177)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"pool-3-thread-1" #57 prio=5 os_prio=0 cpu=933.70ms elapsed=9175.21s tid=0x00005614d3564800 nid=0x50 waiting on condition  [0x00007fc7ddf57000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7ddf020> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"JGit-WorkQueue" #62 daemon prio=5 os_prio=0 cpu=2.59ms elapsed=9171.95s tid=0x00007fc81406c000 nid=0x58 waiting on condition  [0x00007fc7dde56000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7f250a8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.11/AbstractQueuedSynchronizer.java:2123)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"pool-3-thread-2" #63 prio=5 os_prio=0 cpu=870.61ms elapsed=9171.75s tid=0x00007fc7e4004800 nid=0x59 waiting on condition  [0x00007fc7ddc54000]
   java.lang.Thread.State: WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x00000000c7ddf020> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(java.base@11.0.11/LockSupport.java:194)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@11.0.11/AbstractQueuedSynchronizer.java:2081)
	at java.util.concurrent.LinkedBlockingQueue.take(java.base@11.0.11/LinkedBlockingQueue.java:433)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Attach Listener" #5526 daemon prio=9 os_prio=0 cpu=0.28ms elapsed=0.09s tid=0x00007fc7f405f000 nid=0x11aca waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=0 cpu=1612.37ms elapsed=9194.19s tid=0x00007fc8380b0800 nid=0x19 runnable  

"GC Thread#0" os_prio=0 cpu=5673.15ms elapsed=9194.28s tid=0x00007fc83802d800 nid=0x14 runnable  

"GC Thread#1" os_prio=0 cpu=5552.21ms elapsed=9193.69s tid=0x00007fc808001000 nid=0x23 runnable  

"G1 Main Marker" os_prio=0 cpu=4.46ms elapsed=9194.28s tid=0x00007fc838047800 nid=0x15 runnable  

"G1 Conc#0" os_prio=0 cpu=492.95ms elapsed=9194.28s tid=0x00007fc838049800 nid=0x16 runnable  

"G1 Refine#0" os_prio=0 cpu=3.80ms elapsed=9194.27s tid=0x00007fc838083000 nid=0x17 runnable  

"G1 Young RemSet Sampling" os_prio=0 cpu=3625.24ms elapsed=9194.27s tid=0x00007fc838084800 nid=0x18 runnable  
"VM Periodic Task Thread" os_prio=0 cpu=3731.62ms elapsed=9194.14s tid=0x00007fc8380ff000 nid=0x22 waiting on condition  

JNI global refs: 38, weak refs: 45

[vladak]

I think Git bisect is in order.

[vladak]

Instead of bisecting I ran the indexer for individual releases first:

#!/bin/bash

set -e

git config --local advice.detachedHead false

git checkout -f -q master
git tag --sort="version:refname" | grep '^1\.[5-7]' | while read tag; do
	echo -n "\"$tag\" "
	git checkout -f -q "$tag"
	# Maven messes with stdin, corrupting the while cycle, so point it to the right place.
	mvn -q -DskipTests=true -Dcheckstyle.skip clean package </dev/null >/dev/null 2>&1
	rm -rf /var/opengrok/data.openssl
	/usr/bin/time -o /dev/stdout --format '%e' java -Xmx8g -classpath 'distribution/target/dist/*' -Djava.util.logging.config.file=logging.properties-SEVERE \
	    org.opengrok.indexer.index.Indexer -s /var/opengrok/src.openssl -d /var/opengrok/data.openssl -c /usr/local/bin/ctags -H -S -P \
	    2>/dev/null
	git checkout -f -q master
done

Not sure how I missed this in #3589 (comment) however there seems to be cca 3x slowdown in 1.7.4 when reindexing from scratch. The 1.7.4 release contained mainly the per partes history changes plus also some JGit finishing touches. It seems that the performance regression is caused by the former (now bisect would help to drill down). It seems that MAX_CHANGESETS set to 512 in GitRepository is too small and should be probably bumped. The OpenSSL Git repository I used for the test has some 28k changesets so it would split into 56 chunks.

In 1.7.11 some of the performance was brought back by the parallelization of history cache creation for individual files in PR #3636. That would help only if there is enough CPU cores available, though.

Anyhow, I think the regression would only be seen when reindexing from scratch or when reindexing repository with large amount of incoming changesets.

[vladak]

Experimenting with GitRepository#MAX_CHANGESETS in changeset f8dd3dc and the OpenSSL Git repository:

512	232.79
1024	202.47
2048	168.30
4096	94.73
8192	90.38
16384	86.51

This confirms that the per partes changes indeed caused the long indexing times.

Need to figure out the sweet spot for large repositories (like Linux that has more than one million of changesets) w.r.t. speed and heap. Also, the count should probably be configurable.