Logstash: slow startup times with plenty of existing entropy

[jaychris]

This is running the logstash-6.1.1 container on CoreOS.

Startup times are very slow even with plenty of available entropy:

bash-4.2$ cat /proc/sys/kernel/random/entropy_avail
2305

bash-4.2$ time logstash --help
Usage:
    bin/logstash [OPTIONS]
...
real    2m28.603s
user    0m59.627s
sys 0m3.621s

[jarpy]

Interesting (and also annoying, I'm sure).

Would you mind trying with haveged running, just to fully eliminate the entropy hypothesis?

[jarpy]

You might also see something interesting if you strace the process, though you'll also see a _lot_ of noise.

eg.

docker run --rm -it -u root --cap-add SYS_PTRACE docker.elastic.co/logstash/logstash:6.1.1 /bin/bash -c 'yum install -y strace && strace -f logstash --help'

[jarpy]

Closing on inactivity, but please post if you found anything interesting.

Thanks.

[kesor]

@jarpy I also have a very similar problem, and did the strace like you mentioned.

Using Mac OS X 10.13.4 with Docker for Mac 18.03.1-ce-mac65 that has engine 18.03.1-ce

Starting the container with:

docker run --cap-add SYS_PTRACE --user root -ti --rm docker.elastic.co/logstash/logstash:6.2.4 /bin/bash

haveged is running in another -d container, so entropy seems okay.

$ cat /proc/sys/kernel/random/entropy_avail
2900

Command used to run logstash:

time strace -r -t -T -f -o strace-logstash.log bin/logstash --help

Results in a consistent ~ 1m25s until the help output is displayed and process exits -

real    1m24.288s
user    0m37.000s
sys     0m4.880s

This is on a 3.5ghz intel core i7 16gb latest generation MacBook Pro.

Very similar delays happen with configtest, logstash-plugin remove and just running logstash and waiting for it to start "working" by anxiously glaring at its logfile.

Output from strace was copied out using docker cp and uploaded to a gist here - https://gist.github.com/kesor/e5b2f0fcea43fb4913bc0007cd48bd84

[jarpy]

I think whatever is happening here is quite deep in the internals of Logstash/JRuby and the issue might benefit from a once-over by an expert in Logstash internals.

Do you have someone who would be interested in taking a look at this, @monicasarbu?

[jgough]

I think I'm getting the same behaviour on docker.elastic.co/logstash/logstash:6.3.1

I'm trying to upgrade our logstash docker container from Logstash 5 to 6.
Our old Logstash 5 loads quickly and processes quickly, but Logstash 6 takes maybe up to 5 minutes to load, then is about 1/10th of the processing speed once it gets going.

I followed @kesor's commands above and got a time of 22s to run --help.

Again, I've got plenty of entropy with haveged running in another container:

# cat /proc/sys/kernel/random/entropy_avail
2413

[jarpy]

@acchen97, @tbragin, can you suggest a Logstash expert who might be interested in taking a look at this (rather subtle) problem?

[acchen97]

/cc @jsvd @tsg

[tbragin]

@kesor @jgough Are you running the Logstash docker image with all default settings, or are you enabling things like monitoring, security, etc..?

[tsg]

@robbavey promised to have a look at this issue. Thanks Rob :)

[kesor]

@tbragin just defaults. nothing special at all.

[robbavey]

@kesor I don't appear to get the same slowdown on a Mac running MacOS10.13.6 with the same version of Docker. The output from running stracestats from my strace output is broadly similar to the results that you pasted in your gist.

Could you possibly send the full strace output from your test and attach it to this issue? Unfortunately, the output from your gist appears to have been truncated.

[kesor]

@robbavey the strace output is full in the gist. I uploaded the whole file as-is without truncating anything. Try the direct link? https://gist.githubusercontent.com/kesor/e5b2f0fcea43fb4913bc0007cd48bd84/raw/92f04dbdb10a9bc0bdf97fe7793d7dbd47e85833/strace-logstash.log

[robbavey]

@kesor I tried the direct link and still get what appears to be a truncated file - the last line reads:

143   1528283291.803555 futex(0x7

Is that expected?

(I also tried cloning the gist, as suggested in the API docs for truncated content, but that gave me the same content as the direct link)

[kesor]

I created the same experiment, this time with logstash:6.3.1. The results are similar, hopefully the strace file is intact this time. This is the gist - https://gist.github.com/kesor/8171a1eba0c527d750b113e8c59d5ea9

[robbavey]

@kesor - that looks much better - thanks!

[frankfoti]

Any update here? we are stumped:
time strace -r -t -T -f -o strace-logstash.log /usr/share/logstash/bin/logstash --help

real 2m3.787s
user 3m13.772s
sys 0m32.056s

[robbavey]

@frankfoti Could you also post the results of your strace to a gist, or directly to this issue?

I should be able to get back to this issue shortly

[frankfoti]

strace-logstash.zip

[frankfoti]

Any update? Thanks

[deevodavis71]

Same slow startup on Docker for Mac version 18.06.1-ce and image "docker.elastic.co/logstash/logstash:6.4.3". On starting the container it takes over 45 seconds for anything at all to apperar in "docker logs" for the container, and once some output is available it takes a further 30 seconds to complete the load of logstash. Entropy is > 3200.