Optimization that can be done to increase Opengrok's performance

[Leo-Adlakha]

Hi, I have approximately 1600 repositories in my Opengrok setup, and having high delays in viewing search results, and viewing a file after searching.

Searching in all repos - 1.2mins
Searching in approx 8 repos - 5s ( common use case )
Viewing file from search results - 6-8s ( this definitely needs to be improved )

Are there some ways we can enhance the speed even further. The above speeds are taken when the cache is warmed up from the previous searches, I restart the instance everyday to have the new indexes for the setup. The current setup has

CPUs - 8
Memory - 64GB

I am not sure what can be done to increase this speeds. One hack I use to have above speeds is to make random calls to opengrok APIs to warm up the cache after restarting the instance. Please suggest any other improvements that can be done. Thanks!

[vladak]

I can offer some remarks and insights, however most of the work you will have to do yourself (or hire a consultant skilled enough to tackle the problem).

There quite a few "details" that you omitted like OpenGrok version, relevant settings (i.e. how the indexer is run), deployment information, relevant operating system details and settings, some information about the overall load (both CPU and I/O) of the system over time, at least some information about the I/O backend and about the CPUs, etc.

When searching in multiple projects at once, the search in individual projects happens in parallel. I think that the project for which the search is slowest will determine the overall search time. In general, assuming the I/O backend (by which I mean both memory and disk and anything in between) allows it, the more CPUs are thrown at the problem, the quicker the search will complete (most probably only up to some degree).

As for the warm-up, this will only make sense if the amount of memory is enough for the working set. Usually, the Lucene index files will be mapped into memory so will be subject to OS level caching. If the working set, which really is any data the webapp might need (index files, xrefs, history cache data, suggester data, ...) is significantly bigger than the amount of available memory, some cache trashing will follow, meaning the cache warm-up might offer very limited help, if any.
If you run the indexer on the same machine, this will become more complicated as the indexer will essentially wipe out some of the caches. Also, the indexer usually needs some non-trivial amount of memory to operate, so it will apply some pressure on the physical memory; as a result the OS might then reduce some file system caches etc.

Tackling the "Viewing file from search results" time might be good starting point. The webapp offers some metrics, if the webapp log level is increased enough (FINEST), they will also show up in the webapp logs.

[Leo-Adlakha]

Hi @vladak , thanks for the reply! I am adding some more information regarding the setup here -

There quite a few "details" that you omitted like OpenGrok version, relevant settings (i.e. how the indexer is run), deployment information, relevant operating system details and settings, some information about the overall load (both CPU and I/O) of the system over time, at least some information about the I/O backend and about the CPUs, etc.

Opengrok Version - 1.7.38
Relevant settings - Indexer is run as cron job daily on a seperate host using the below command.

java \
    -Djava.util.logging.config.file=$1/opengrok/etc/logging.properties -Xmx128g -Xms32g -server \
    -jar $1/opengrok/dist/lib/opengrok.jar --progress -m 4096 -T 64 -v \
    -c $1/ctags/bin/ctags \
    -s $1/opengrok/src -d $1/opengrok/data -H -S -G -P \
    -R $1/opengrok/etc/readonly-configuration.xml \
    -W $1/opengrok/etc/configuration.xml -U https://opengrok-qa.xyz.com:443

Deployment information - The webapp is deployed on tomcat v10, on a seperate host. Some options I use to start the webapp are

#!/bin/bash

# Export variables needed for the instance to run
export CATALINA_BASE=<__TOMCAT_HOME__>
export CATALINA_HOME=<__TOMCAT_HOME__>
export JAVA_OPTS="-Xms64g -Xmx128g -server -XX:MetaspaceSize=256M -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=<path-to-log-dir>"
export CATALINA_OPTS="-Dcertificate.file=<certificate-for-SSL> -Dsdportenv.http=<port_http> -Dsdportenv.https=<port_https>"
export JGSS_OPTS="<some options related to Kerberos Authentication>"
export KRB5RCACHETYPE=none

# Run the startup script
<__TOMCAT_HOME__>/tomcat/bin/catalina.sh run

Operating System Details -
OS - RHEL7
CPUs available in the server - 56 ( I allocated 8 CPUs for my webapp process, I think 8(min) is used to allocate me a server from the grid )
Memory available - 1.48TB ( I allocated 64G of memory )

When the server is allocated, it confirms that CPU is not overloaded, else it automatically shifts the service to some other server. So, CPU load is not that high now, but will be in the near future. So, not sure, if this could lead to more bad performance. Some more info from cat /proc/meminfo for the server

MemTotal:       1584470860 kB
MemFree:        1224783780 kB
MemAvailable:   1378081064 kB
Buffers:           31632 kB
Cached:         195213712 kB
SwapCached:          408 kB

I/O stats -

$ iostat
01/03/2023      _x86_64_        (56 CPU)

Device:            tps    kB_read/s    kB_wrtn/s    kB_read    kB_wrtn
nvme0n1          44.80        13.89       930.85   29016404 1944225840
dm-0              1.41         2.35         3.30    4910008    6886360
dm-1             45.56        11.52       926.87   24064788 1935896276
dm-2             45.56        11.52       926.87   24061456 1935896276
dm-3             51.32        11.52     21061.75   24059552 43990575604
dm-4              0.00         0.00         0.00       3332          0

$ iostat -c
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
          64.24    0.02    8.84    0.14    0.00   26.76

As for the warm-up, this will only make sense if the amount of memory is enough for the working set. Usually, the Lucene index files will be mapped into memory so will be subject to OS level caching. If the working set, which really is any data the webapp might need (index files, xrefs, history cache data, suggester data, ...) is significantly bigger than the amount of available memory, some cache trashing will follow, meaning the cache warm-up might offer very limited help, if any.

I don't think this could be the case in my setup. Warming up the cache, really does help in my case, and reduces the time, but still would need this to be more better.

Tackling the "Viewing file from search results" time might be good starting point. The webapp offers some metrics, if the webapp log level is increased enough (FINEST), they will also show up in the webapp logs.

Ok, will try turning this on. By the way if this shows the localhost_access_logs that are generated by tomcat, then I have already seen those where a lot of time is taken for retrieving the file from the indexes, which shouldn't be the case.

Adding some more info about my setup -

After indexing I restart the tomcat process to update the indexes, as I have Kerberos authentication which does not work with a token, hence I can't pass it to the indexing script which will notify the app, so a restart is required. If I can eliminate this, this would not require warming of cache and would be faster after restart as well.

Please do let me know any more info you might require to suggest any improvements in the performance.

Thanks,
Leo

[Leo-Adlakha]

I am also attaching the metrics, if this helps in debugging the performance issues.

# HELP authorization_sessions_invalidated_total  
# TYPE authorization_sessions_invalidated_total counter
authorization_sessions_invalidated_total 0.0
# HELP jvm_threads_states_threads The current number of threads having NEW state
# TYPE jvm_threads_states_threads gauge
jvm_threads_states_threads{state="runnable",} 8.0
jvm_threads_states_threads{state="blocked",} 0.0
jvm_threads_states_threads{state="waiting",} 24.0
jvm_threads_states_threads{state="timed-waiting",} 3.0
jvm_threads_states_threads{state="new",} 0.0
jvm_threads_states_threads{state="terminated",} 0.0
# HELP jvm_memory_committed_bytes The amount of memory in bytes that is committed for the Java virtual machine to use
# TYPE jvm_memory_committed_bytes gauge
jvm_memory_committed_bytes{area="nonheap",id="CodeHeap 'profiled nmethods'",} 1.5138816E7
jvm_memory_committed_bytes{area="heap",id="G1 Survivor Space",} 6.7108864E7
jvm_memory_committed_bytes{area="heap",id="G1 Old Gen",} 6.509559808E10
jvm_memory_committed_bytes{area="nonheap",id="Metaspace",} 5.8458112E7
jvm_memory_committed_bytes{area="nonheap",id="CodeHeap 'non-nmethods'",} 2555904.0
jvm_memory_committed_bytes{area="heap",id="G1 Eden Space",} 3.556769792E9
jvm_memory_committed_bytes{area="nonheap",id="CodeHeap 'non-profiled nmethods'",} 6094848.0
# HELP system_cpu_count The number of processors available to the Java virtual machine
# TYPE system_cpu_count gauge
system_cpu_count 8.0
# HELP system_cpu_usage The "recent cpu usage" of the system the application is running in
# TYPE system_cpu_usage gauge
system_cpu_usage 0.4137606012303606
# HELP jvm_gc_live_data_size_bytes Size of long-lived heap memory pool after reclamation
# TYPE jvm_gc_live_data_size_bytes gauge
jvm_gc_live_data_size_bytes 0.0
# HELP authorization_stack_reload_total  
# TYPE authorization_stack_reload_total counter
authorization_stack_reload_total 1.0
# HELP requests_latency_seconds  
# TYPE requests_latency_seconds summary
requests_latency_seconds_count{category="metrics",code="200",} 1.0
requests_latency_seconds_sum{category="metrics",code="200",} 0.082017
requests_latency_seconds_count{category="root",code="200",} 1.0
requests_latency_seconds_sum{category="root",code="200",} 1.695417
requests_latency_seconds_count{category="unknown",code="404",} 1.0
requests_latency_seconds_sum{category="unknown",code="404",} 0.003741
# HELP requests_latency_seconds_max  
# TYPE requests_latency_seconds_max gauge
requests_latency_seconds_max{category="metrics",code="200",} 0.082017
requests_latency_seconds_max{category="root",code="200",} 0.0
requests_latency_seconds_max{category="unknown",code="404",} 0.003741
# HELP authorization_cache_total authorization cache hits
# TYPE authorization_cache_total counter
authorization_cache_total{what="misses",} 3662.0
authorization_cache_total{what="hits",} 7326.0
# HELP jvm_gc_pause_seconds Time spent in GC pause
# TYPE jvm_gc_pause_seconds summary
jvm_gc_pause_seconds_count{action="end of minor GC",cause="G1 Evacuation Pause",} 2.0
jvm_gc_pause_seconds_sum{action="end of minor GC",cause="G1 Evacuation Pause",} 0.049
# HELP jvm_gc_pause_seconds_max Time spent in GC pause
# TYPE jvm_gc_pause_seconds_max gauge
jvm_gc_pause_seconds_max{action="end of minor GC",cause="G1 Evacuation Pause",} 0.0
# HELP process_cpu_usage The "recent cpu usage" for the Java Virtual Machine process
# TYPE process_cpu_usage gauge
process_cpu_usage 1.361531702218354E-4
# HELP requests_max  
# TYPE requests_max gauge
requests_max 1.0
# HELP requests  
# TYPE requests summary
requests_count 4.0
requests_sum 4.0
# HELP jvm_gc_max_data_size_bytes Max size of long-lived heap memory pool
# TYPE jvm_gc_max_data_size_bytes gauge
jvm_gc_max_data_size_bytes 1.37438953472E11
# HELP webapp_startup_latency_seconds web application startup latency
# TYPE webapp_startup_latency_seconds summary
webapp_startup_latency_seconds_count 1.0
webapp_startup_latency_seconds_sum 34.586835
# HELP webapp_startup_latency_seconds_max web application startup latency
# TYPE webapp_startup_latency_seconds_max gauge
webapp_startup_latency_seconds_max 0.0
# HELP system_load_average_1m The sum of the number of runnable entities queued to available processors and the number of runnable entities running on the available processors averaged over a period of time
# TYPE system_load_average_1m gauge
system_load_average_1m 28.54
# HELP jvm_memory_max_bytes The maximum amount of memory in bytes that can be used for memory management
# TYPE jvm_memory_max_bytes gauge
jvm_memory_max_bytes{area="nonheap",id="CodeHeap 'profiled nmethods'",} 1.22908672E8
jvm_memory_max_bytes{area="heap",id="G1 Survivor Space",} -1.0
jvm_memory_max_bytes{area="heap",id="G1 Old Gen",} 1.37438953472E11
jvm_memory_max_bytes{area="nonheap",id="Metaspace",} -1.0
jvm_memory_max_bytes{area="nonheap",id="CodeHeap 'non-nmethods'",} 5836800.0
jvm_memory_max_bytes{area="heap",id="G1 Eden Space",} -1.0
jvm_memory_max_bytes{area="nonheap",id="CodeHeap 'non-profiled nmethods'",} 1.22912768E8
# HELP jvm_threads_peak_threads The peak live thread count since the Java virtual machine started or peak was reset
# TYPE jvm_threads_peak_threads gauge
jvm_threads_peak_threads 190.0
# HELP jvm_memory_used_bytes The amount of used memory
# TYPE jvm_memory_used_bytes gauge
jvm_memory_used_bytes{area="nonheap",id="CodeHeap 'profiled nmethods'",} 1.3589504E7
jvm_memory_used_bytes{area="heap",id="G1 Survivor Space",} 6.7108864E7
jvm_memory_used_bytes{area="heap",id="G1 Old Gen",} 0.0
jvm_memory_used_bytes{area="nonheap",id="Metaspace",} 5.6884032E7
jvm_memory_used_bytes{area="nonheap",id="CodeHeap 'non-nmethods'",} 1260416.0
jvm_memory_used_bytes{area="heap",id="G1 Eden Space",} 1.879048192E9
jvm_memory_used_bytes{area="nonheap",id="CodeHeap 'non-profiled nmethods'",} 5568384.0
# HELP jvm_buffer_count_buffers An estimate of the number of buffers in the pool
# TYPE jvm_buffer_count_buffers gauge
jvm_buffer_count_buffers{id="mapped",} 0.0
jvm_buffer_count_buffers{id="direct",} 11.0
# HELP jvm_classes_unloaded_classes_total The total number of classes unloaded since the Java virtual machine has started execution
# TYPE jvm_classes_unloaded_classes_total counter
jvm_classes_unloaded_classes_total 0.0
# HELP cache_annotation_file_get_total file annotation cache hits
# TYPE cache_annotation_file_get_total counter
cache_annotation_file_get_total{what="miss",} 0.0
cache_annotation_file_get_total{what="hits",} 0.0
# HELP jvm_gc_memory_allocated_bytes_total Incremented for an increase in the size of the (young) heap memory pool after one GC to before the next
# TYPE jvm_gc_memory_allocated_bytes_total counter
jvm_gc_memory_allocated_bytes_total 6.811549696E9
# HELP cache_history_file_get_total file history cache hits
# TYPE cache_history_file_get_total counter
cache_history_file_get_total{what="miss",} 0.0
cache_history_file_get_total{what="hits",} 0.0
# HELP jvm_buffer_total_capacity_bytes An estimate of the total capacity of the buffers in this pool
# TYPE jvm_buffer_total_capacity_bytes gauge
jvm_buffer_total_capacity_bytes{id="mapped",} 0.0
jvm_buffer_total_capacity_bytes{id="direct",} 162553.0
# HELP jvm_threads_live_threads The current number of live threads including both daemon and non-daemon threads
# TYPE jvm_threads_live_threads gauge
jvm_threads_live_threads 35.0
# HELP authorization_latency_seconds_max authorization latency
# TYPE authorization_latency_seconds_max gauge
authorization_latency_seconds_max{outcome="negative",} 0.0
authorization_latency_seconds_max{outcome="positive",} 0.0
# HELP authorization_latency_seconds authorization latency
# TYPE authorization_latency_seconds summary
authorization_latency_seconds_count{outcome="negative",} 352.0
authorization_latency_seconds_sum{outcome="negative",} 1.762721
authorization_latency_seconds_count{outcome="positive",} 3310.0
authorization_latency_seconds_sum{outcome="positive",} 0.205411
# HELP history_repositories_invalidate_seconds  
# TYPE history_repositories_invalidate_seconds summary
history_repositories_invalidate_seconds_count 1.0
history_repositories_invalidate_seconds_sum 17.318888
# HELP history_repositories_invalidate_seconds_max  
# TYPE history_repositories_invalidate_seconds_max gauge
history_repositories_invalidate_seconds_max 0.0
# HELP jvm_threads_daemon_threads The current number of live daemon threads
# TYPE jvm_threads_daemon_threads gauge
jvm_threads_daemon_threads 31.0
# HELP jvm_buffer_memory_used_bytes An estimate of the memory that the Java virtual machine is using for this buffer pool
# TYPE jvm_buffer_memory_used_bytes gauge
jvm_buffer_memory_used_bytes{id="mapped",} 0.0
jvm_buffer_memory_used_bytes{id="direct",} 162553.0
# HELP jvm_classes_loaded_classes The number of classes that are currently loaded in the Java virtual machine
# TYPE jvm_classes_loaded_classes gauge
jvm_classes_loaded_classes 9241.0
# HELP jvm_gc_memory_promoted_bytes_total Count of positive increases in the size of the old generation memory pool before GC to after GC
# TYPE jvm_gc_memory_promoted_bytes_total counter
jvm_gc_memory_promoted_bytes_total 0.0

[vladak]

The metrics in the Prometheus format exported by the webapp usually make sense only when observed over period of time, e.g. recorded into a time-series database and presented in some sort of UI like Grafana so that one can drill down into certain periods of time. And also possibly being alerted upon when certain thresholds are exceeded (say based on some latency percentile). Such a one time snapshot does not usually help. More over the snapshot above looks like to be gathered from a webapp that has been running for a short time and/or has not received much traffic yet - the requests_count metric is just 4, which means the webapp received just 4 requests in total.

Looking at the metrics makes me think about doing a step back. Specifically, ask a question: what makes you think the high latencies are within the webapp itself and not some other layers ? Say in the network and/or the client and/or whatever authentication is in place. What work was done to isolate the increased latencies to the web app ?

[Leo-Adlakha]

Hey @vladak , its taking really long to open a file in my instance. I don't think that just fetching a file after searching should take such a long time ( 7-9 sec ), even for small files.

I have observed another thing in Chrome inspector that two calls are being made for viewing any file, I am attaching the snippet of the two calls and timings.

Is this something new added to Opengrok which redirects the request and adds the revision to the request, it takes a lot of time due to this, is there a reason behind this ? Can we remove this ?

Thanks,
Leo

[Leo-Adlakha]

Hi @vladak,

I see this log in my webapp logs - which might seem like causing the delay -

WARNING: file '/opengrok/src/repo1/greadlew' is newer than '/opengrok/data/xref/repo1/gradlew.gz'
Jan 20, 2023 4:57:37 AM org.opengrok.web.PageConfig checkFileInner

How is this happening even if my Opengrok setup is indexing everyday ?

Thanks,
Leo

[vladak]

Firstly, make sure you are not assuming. What are the related latencies reported in the Tomcat logs and/or the Prometheus metrics and also in the browser ? OpenGrok 1.7.42 provides latency reporting for xref generation (The "xref.write.latency" metric + related log message at the FINEST level).

Also, even if there was increased latency related to the on-the-fly xref generation due to the stale xref file, that would explain only the long latency of the second request made by the browser. The long latency of the first request (the one that redirects to the URL with the embedded revision ID) would remain still unexplained.

As for why this happens, you'd need to see the sync + indexer logs. You'd probably need to run the indexer with elevated log level to see the necessary amount of detail (FINEST) required to track this down. It certainly depends on how the file in question was updated. For example, if the file is located in directory of a repository that allows for history based traversal by the indexer, however the file is not part of the repository (i.e. does not have history), the indexer will not pick it up unless forced to use the directory traversal method.

Lastly, it might be interesting to traverse the directory tree for that project and find out how many stale xrefs are out there and see what is special about them, however then you may be running into a rabbit hole of chasing the wrong thing.

[Leo-Adlakha]

Ok, I'll try to switch to v1.7.42 and check xref latencies. Just curious, I hope

2023-01-20 02:45:39.253-0500 WARNING t56 IndexDatabase.markProjectIndexed: Could not notify the webapp that project project1:indexed=true,history=true was indexed: InboundJaxrsResponse{context=ClientResponse{method=PUT, uri=https://opengrok-qa.com:443/api/v1/projects/project1/indexed, status=401, reason=Unauthorized}}

the above doesn't lead to any issues. I update the configuration by restarting the webapp after re indexing.

[vladak]

Do you actually run the indexer on a separate machine/VM ? If not, using localhost-based URL will fix that. Otherwise, consider using API token for the indexer. I don't think restarting the webapp after reindex would cause long standing big latencies, with the obvious blip during the restart.

[Leo-Adlakha]

Yes, I run the indexer on a separate machine. I can't pass an API token because I am using Kerberos authentication for the tomcat server. Its fine if this doesn't lead to big latencies in opening up the files.