[BUG] Slow index creation on MacOS

[diachedelic]

Describe the bug
It takes ten times longer to create an index (PUT /my_index) using the MacOS build of OpenSearch than in Docker.

Attempting to create several indexes at once ends up taking several times as long as creating a single index, yet OpenSearch's process does not seem to be CPU or memory bound. There do not appear to be any errors or warnings in the log.

This is not a problem in production, but it is slowing down our automated tests in development.

To Reproduce
Steps to reproduce the behavior:

1. Install opensearch by running brew install opensearch
2. Start opensearch
3. Run time curl -XPUT localhost:9200/my_index

Output:

$ time curl -XPUT localhost:9200/my_index
{"acknowledged":true,"shards_acknowledged":true,"index":"my_index"}
real    0m2.024s

4. Now, install opensearch using docker pull opensearchproject/opensearch:latest
5. Start container with docker run -p 9200:9200 -e "discovery.type=single-node" -e "plugins.security.disabled=true" opensearchproject/opensearch:latest
6. Run time curl -XPUT localhost:9200/my_index

Output:

$ time curl -XPUT localhost:9200/my_index
{"acknowledged":true,"shards_acknowledged":true,"index":"my_index"}
real    0m0.193s

Expected behavior
I would expect the MacOS build to create indexes much faster than the Docker container, seeing as the container is running in the Docker Desktop VM.

Plugins
I used the default installation.

Host/Environment (please complete the following information):

• OpenSearch v2.3.0
• OS: MacOS 11.4 (Big Sur)
• Intel MacBook Pro

[anasalkouz]

@diachedelic is this performance degradation only limited to the index creation API ? or you are facing same issue with other APIs?

[diachedelic]

I have only noticed it with the index creation API. Populating and querying the index appear to be fast.

[diachedelic]

This might result from MacOS's excruciatingly slow implementation of the fsync system call, described at golang/go#28739 (comment).

If so, these would be the hot lines:

OpenSearch/libs/core/src/main/java/org/opensearch/core/internal/io/IOUtils.java

Line 301 in 31a360f

file.force(true);

https://github.com/openjdk/jdk/blob/master/src/java.base/macosx/native/libnio/ch/FileDispatcherImpl.c#L51

[diachedelic]

From the ElasticSearch folks:

The root cause of this is that fsync performance on modern macs is quite slow and Elasticsearch (any many other databases) use this extensively for durability purposes. There's really not a whole lot we can do here and we have the same issue with slow test execution on Macs.

I am not using a modern Mac, but it seems plausible that this also affects older Macs.

[dblock]

@diachedelic You can test it by commenting out that line. Obviously don't do this in production ;)

[diachedelic]

I'm afraid I can't get OpenSearch to build:

$ ./gradlew localDistro
Starting a Gradle Daemon, 1 incompatible Daemon could not be reused, use --status for details

FAILURE: Build failed with an exception.

* What went wrong:
Unable to start the daemon process.
This problem might be caused by incorrect configuration of the daemon.
For example, an unrecognized jvm option is used.
Please refer to the User Manual chapter on the daemon at https://docs.gradle.org/7.5.1/userguide/gradle_daemon.html
Process command line: /Library/Java/JavaVirtualMachines/jdk1.8.0_131.jdk/Contents/Home/bin/java -XX:+HeapDumpOnOutOfMemoryError -Xss2m --add-exports jdk.compiler/com.sun.tools.javac.api=ALL-UNNAMED --add-exports jdk.compiler/com.sun.tools.javac.file=ALL-UNNAMED --add-exports jdk.compiler/com.sun.tools.javac.parser=ALL-UNNAMED --add-exports jdk.compiler/com.sun.tools.javac.tree=ALL-UNNAMED --add-exports jdk.compiler/com.sun.tools.javac.util=ALL-UNNAMED -Xmx3g -Dfile.encoding=UTF-8 -Duser.country=AU -Duser.language=en -Duser.variant -cp /Users/jamesdiacono/.gradle/wrapper/dists/gradle-7.5.1-all/1ehga6e77gqps5uk2kc5kf1vc/gradle-7.5.1/lib/gradle-launcher-7.5.1.jar org.gradle.launcher.daemon.bootstrap.GradleDaemon 7.5.1
Please read the following process output to find out more:
-----------------------
Unrecognized option: --add-exports
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.

$ java -version
java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

[dblock]

You need a newer JDK, see https://github.com/opensearch-project/OpenSearch/blob/main/DEVELOPER_GUIDE.md

[Bukhtawar]

The hot paths might as well be outside IOUtils.java as well.

OpenSearch/server/src/main/java/org/opensearch/index/translog/TranslogWriter.java

Line 510 in d8e7d87

channel.force(false);

[diachedelic]

@dblock What version are you using? I am using JDK 18.

[dblock]

That would be JDK 8 in your output (1.8 is JDK8, 18 would be 18.0....).

Set JAVA_HOME accordingly, e.g.

$ export JAVA_HOME=`/usr/libexec/java_home -v 11`

$ echo $JAVA_HOME
/Library/Java/JavaVirtualMachines/temurin-11.jdk/Contents/Home

$ java --version
openjdk 11.0.13 2021-10-19
OpenJDK Runtime Environment Temurin-11.0.13+8 (build 11.0.13+8)
OpenJDK 64-Bit Server VM Temurin-11.0.13+8 (build 11.0.13+8, mixed mode)

[diachedelic]

Thank you, that was silly of me.

I commented out force(true) everywhere I could find it (in IOUtils.java, Checkpoint.java and TranslogHeader.java), but it did not improve the performance of index creation.

Edit: also TranslogWriter.java

[dblock]

Thanks @diachedelic, sounds like we'll need more profiling! @andrross or @mch2 do you have any suggestions of how to properly construct a benchmark or an existing benchmark that can be run to narrow this down?

[andrross]

@diachedelic I'd recommend using Java Flight Recorder to profile the VM running OpenSearch. Then just use a simple script calling create index in a loop, something like:

for i in $(seq 0 300) ; do curl -XPUT localhost:9200/my_index_$i ; done

The profiling data generated by Java Flight Recorder will hopefully show what is being slow.

[diachedelic]

I have had a go with the Java Flight Recorder. My benchmark was to create 10 indexes concurrently - and it took about 20 seconds! Even so, nothing jumps out at me when I view the log in JDK Mission Control. There is this:

The maximum amount of used memory was 97.1 % of the physical memory available.
The maximum amount of memory used was 15.5 GiB. This is 97.1 % of the 16 GiB of physical memory available. Having little free memory may lead to swapping, which is very expensive. To avoid this, either decrease the memory usage or increase the amount of available memory.

But it can't be right - throughout the benchmark, Activity Monitor.app showed 8GB free. The OpenSearch process never went above 23% CPU or 1.25GB memory.

I've attached the Flight Recorder data if somebody else would like to take a look.
opensearch-scrubbed.tar.gz

[diachedelic]

I also noticed this in OpenSearch's output:

[2022-11-05T11:18:13,960][WARN ][o.o.c.r.a.DiskThresholdMonitor] flood stage disk watermark [95%] exceeded

I mean, I have 13GB free disk space so it's not like OpenSearch is actually running out of space. But maybe it has something to do with it?

[andrross]

@diachedelic Can you try this again where you're below that 95% threshold? It is possible that it is related.

[diachedelic]

I reduced my disk space usage to 81% (below both the high and low watermarks) but I did not see any improvement.

[diachedelic]

Here are some benchmark results. Each run consists of creating count indexes concurrently.

MacOS build:

count 1
total 1823ms
average 1823ms

count 3
total 5867ms
average 1956ms

count 10
total 17215ms
average 1722ms

count 50
total 35412ms
average 708ms

Linux build, running inside the Docker VM:

count 1
total 419ms
average 419ms

count 3
total 838ms
average 279ms

count 10
total 1802ms
average 180ms

count 50
total 5073ms
average 101ms