OpenGrok at latest version shows sluggishness when open page from repository with large history

[mmmarq]

I have an open source git indexed by openGrok, but when I try to open any file under this repository, it takes longer than 1 and a half minute to display the page. I think it tries to collect some additions info from history what make it very slow to show the final page.
I have checked and xref file is already generated (with a newer date than git workspace).

Code base is available at https://android.googlesource.com/platform/frameworks/base/ and have more than 688k commits on its history.

I'm migrating from an old openGrok version (1.0.0) to 1.7.31. The issue cannot be reproduced at older version (I know the gap is huge) even running on a oldest server configuration.

It there any way to disable any remote checking and just display "xref" file content?

Some additional information:

• Sample file:

ls -la src_base/frameworks/base/services/core/java/com/android/server/wm/WindowList.java
-rw-r--r-- 1 sse postfix 1058 May 12 11:39 src_base/frameworks/base/services/core/java/com/android/server/wm/WindowList.java
ls -la data/xref/src_base/frameworks/base/services/core/java/com/android/server/wm/WindowList.java*
-rw-r--r-- 1 sse postfix 1774 May 16 18:40 data/xref/src_base/frameworks/base/services/core/java/com/android/server/wm/WindowList.java.gz

• System Configuration

OpenGrok 1.7.31
OpenJDK 12.0.2-x64
Ubuntu 18.04
Ram 62G
Tomcat 10.0.12
Git 2.20.4

• Client side:
  Chrome & Firefox

• tomcat bin/setenv.sh content:

JAVA_OPTS="$JAVA_OPTS -server -Djava.security.auth.login.config==$CATALINA_BASE/conf/jaas.config -Dorg.opengrok.indexer.history.git=/bin/git"
# Set defauld PID file
CATALINA_PID="$CATALINA_BASE/tomcat.pid"
# OpenGrok memory boost to cover all-project searches
JAVA_OPTS="$JAVA_OPTS -Xmx32g"
export JAVA_OPTS

• tomcat conf/server.xml connector set to:

    <Connector port="8080" protocol="HTTP/1.1"
               connectionTimeout="20000"
               redirectPort="8443"
               maxThreads="1024" />

• All project under opengrok config file set with:

org.opengrok.indexer.configuration.Configuration$RemoteSCM = OFF
mergeCommitsEnabled = false
suggesterConfig = false

For other projects that have smaller history, the issue can not be noticeable.

Thanks in advance

[vladak]

When file contents are displayed, this either happens for some historical revision of given file or the current revision. In the latter case the webapp determines the latest revision first and then redirects to URL that contains the revision (e.g. https://example.com/source/xref/FreeBSD-current-src/kerberos5/Makefile?r=4c3e79ce). This is done so that links embedded in wikis/CMS/bug trackers remain valid (as long as the webapp is still around, the history is not rewritten etc.), which is especially handy if the link also contains line anchor. There is no way how this behavior can be disabled.

The described behavior usually happens if there is old index and the history cache is stale. This is because the webapp will try to lookup the latest revision of given file in the index first; if not found there, it will fall back to the history cache. If the history cache for given file is stale (i.e. the historycache file's last modification time is smaller than the last modification time of the source file; the timestamp of the xref file does not matter at this point), the SCM in question is used to lookup this information. This is likely the cause of the extra latency. This does not not manifest on the old version probably because this behavior was introduced later.

You did not say how the migration from the old version was done, however it seems the documents in the index do not contain the date information. Reindexing from scratch will likely fix the issue.

[vladak]

That said, it should be investigated why the latest revision retrieval for given repository takes so long. Git repository implementation in OpenGrok uses custom getLatestRevision() implementation that overrides the generic one in the Repository class. It basically retrieves the history of given file limited to one changeset. Same for Mercurial. Maybe there is more efficient way how to get the revision.

[vladak]

Also, the code that performs the last revision lookup should be augmented with log statements and perhaps also export latency data so it can be collected using the monitoring tools.

[vladak]

For the record, to get the last history entry for given file in the above linked Android repository, with a hacked OpenGrok (had to remove code that resolves paths relative to source root so that I can run the code from a test), it takes 5 seconds when calling GitRepository#getLastHistoryEntry() directly on my laptop with Intel Core i7 and built-in SSD. The first run of the test was much longer however I cannot say whether this was due to the file-system caches not being warmed up or because I was running the test with debugger attached (or both).

[mmmarq]

Hello @vladak, thanks for you reply
Regarding migration, new openGrok version was deployed in a new server, so all data was indexed from scratch.

You also said that "If the history cache for given file is stale (...), the SCM in question is used to lookup this information". I have "--history" enabled on index command. Should I use diff flag for history refresh? The index command I`m running is:

${OPENGROK_PATH}/opengrok-tools/bin/opengrok-indexer --java ${JAVA_HOME}/bin/java \
--java_opts=-server --java_opts=-Xmx16g --java_opts=-Xms16g --java_opts=-Dorg.opengrok.indexer.history.git=${GIT_PATH} \
--jar ${OPENGROK_PATH}/lib/opengrok.jar -- --ctags ${SSE_TOOLS_PATH}/ctags/ctags --dataRoot ${INDEX_PATH} \
-i d:'.repo' -i d:'*.git'  -i d:'.git' --history --projects --progress --optimize off --remote off --memory 1000 \
--historyThreads 50 --historyFileThreads 50 --source ${SRC_CODE_PATH}"

[vladak]

The only potentially suspicious thing in the indexer command is --remote off although for Git this should not mean anything. Is there anything out of interest either in the indexer logs (meaning from the initial index) or the web app (from around the time the long request happens) ?

[vladak]

Oh, the indexer is missing the -S option for scanning the repositories. When you run the indexer like this, it will say:

INFO: Generating history cache for all repositories ...
Jun 01, 2022 4:36:29 PM org.opengrok.indexer.history.HistoryGuru createCacheReal
INFO: Creating historycache for 0 repositories
Jun 01, 2022 4:36:29 PM org.opengrok.indexer.util.Statistics logIt
INFO: Done history cache for all repositories (took 3 ms)
Jun 01, 2022 4:36:29 PM org.opengrok.indexer.index.Indexer prepareIndexer
INFO: Done generating history cache

which means there will be no history cache and also no history in the index.

[mmmarq]

Hello @vladak,

My bad, this option is set in a diff script line after previous command with some more options:

INDEX_CMD="${INDEX_CMD} --search --depth 50 --writeConfig ${SRC_CODE_PATH}/../etc/src_configuration_raw.xml"

Regarding parameter --remote off, I added it when I was looking for a way to bypass the issue.
I can try to remote it and run index command again if you think it could help. Do you think I should run a clean index?

Thanks

[vladak]

yep, you will have to reindex from scratch.

[mmmarq]

I can try, but it will take a while. I probably will let it running through the weekend

thanks you very much for your attention

[mmmarq]

Hello @vladak,

After some configuration review I'm able to properly index my code. I ran a full index test in a small code base (only frameworks/base) and historycache folder content was fully generated, what make sluggishness gone. It was not happen when I was trying index my entire code base. I took a closer look at my index log (some gigas) and I found some unspotted "Java heap space" failures. I think it was related to the number of history thread + "--memory" parameters values. I have removed history thread number and also decreased "--memory" parameter to a lower number. I also have increased Java max mem to 24g.
Other think that get my attention is the number of "SEVERE: CTag reader cycle was interrupted!" messages. It aways comes after a java.io.IOException:

WARNING: CTags parsing problem:
java.io.IOException: Stream closed
	at java.base/java.io.BufferedInputStream.getBufIfOpen(BufferedInputStream.java:176)
	at java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:342)
	at java.base/sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
	at java.base/sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
	at java.base/sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
	at java.base/java.io.InputStreamReader.read(InputStreamReader.java:185)
	at java.base/java.io.BufferedReader.fill(BufferedReader.java:161)
	at java.base/java.io.BufferedReader.readLine(BufferedReader.java:326)
	at java.base/java.io.BufferedReader.readLine(BufferedReader.java:392)
	at org.opengrok.indexer.analysis.Ctags.readTags(Ctags.java:628)
	at org.opengrok.indexer.analysis.Ctags.lambda$doCtags$2(Ctags.java:536)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:835)

Jun 04, 2022 3:11:28 AM org.opengrok.indexer.analysis.Ctags readTags
SEVERE: CTag reader cycle was interrupted!

he logs that shows these messages has no "Java heap space" error. I'm running Universal Ctags:

ctags/ctags --version
Universal Ctags 5.9.0(3873e705), Copyright (C) 2015-2022 Universal Ctags Team
Universal Ctags is derived from Exuberant Ctags.
Exuberant Ctags 5.8, Copyright (C) 1996-2009 Darren Hiebert
  Compiled: May 11 2022, 19:58:39
  URL: https://ctags.io/
  Optional compiled features: +wildcards, +regex, +gnulib_regex, +iconv, +option-directory, +packcc, +optscript

If you have any guesses it will be welcome.

Thanks you very much for your attention once again :-)

[vladak]

The Ctags related warnings should be fairly innocuous. Usually it signals a problem in Ctags - it could be that one of the ctags processes choked on the input data. The indexer will normally retry the same file. If this persists for given set of files (where maximum number of retries for a file was reached, which means the file will not be properly indexed), it might be worth investigating.