Logstash: bin/logstash-plugin install on Docker is slow

[ph]

On a docker image the bin/logstash-plugin install <offline_pack> takes a really long time, 7-8 minutes, to start downloading the remote pack.

I am not sure what is causing this yet, since on a regular ubuntu vm the call completes in a few seconds.

Reported by @jarpy and he provided a docker image to reproduce it.

[ph]

@jarpy I remember that you run the command with the DEBUG=1 option, did you try to remove it to see if its faster?

[ph]

As a reference this is the result on a test vm.

ph@logstash-dev:~/tmp/logstash-5.2.0$ time LOGSTASH_PACK_URL="https://staging.elastic.co/5.2.0-6ee3d9ba/downloads/logstash-plugins" bin/logstash-plugin install x-pack
Downloading file: https://staging.elastic.co/5.2.0-6ee3d9ba/downloads/logstash-plugins/x-pack/x-pack-5.2.0.zip
Downloading [=============================================================] 100%
Installing file: /tmp/studtmp-5177a7c6871f002964ed6f932f5e5fc1262dbd9e5ce8ec582124cd89660f/x-pack-5.2.0.zip
Install successful

real    0m11.091s
user    0m13.128s
sys 0m0.532s

and with DEBUG=1

real    0m11.299s
user    0m13.772s
sys 0m0.412s

[ph]

seems to be a non issue.. closing :)

[guyisra]

@ph Why was this a non issue?
Installing a plugin in docker takes several minutes..

[jarpy]

Indeed. It seems this is still reproducible.

See here for a 7 minute plugin install, and read on for some strace output of the Java process.

The linked issue is quite old, but I can also reproduce with the latest image:

$ time docker run --rm -it docker.elastic.co/logstash/logstash:5.5.0 logstash-plugin install logstash-input-mysql
Validating logstash-input-mysql
Installing logstash-input-mysql
Installation successful

real    6m57.053s
user    0m0.078s
sys     0m0.031s

[jarpy]

Here is a shell snippet to reproduce the issue. It builds a simple Logstash image from scratch to avoid any complications from the official image.

cat > Dockerfile <<EOF
FROM openjdk:8-jre
RUN curl -Lo - https://artifacts.elastic.co/downloads/logstash/logstash-5.5.0.tar.gz | \
    tar zxf - -C /usr/share && \
    mv /usr/share/logstash-5.5.0 /usr/share/logstash
CMD /usr/share/logstash/bin/logstash-plugin install logstash-input-mysql
EOF

docker build -t logstash-plugin-install .
time docker run --rm -it logstash-plugin-install

Edit: 4m15s on my system.

[jarpy]

Still reproducible with 6.0.0-beta1-e80e42d8

@dliappis, could you try my repro to see if I'm crazy?

cat > Dockerfile <<EOF
FROM openjdk:8-jre
RUN curl -Lo - https://staging.elastic.co/6.0.0-beta1-e80e42d8/downloads/logstash/logstash-6.0.0-beta1.tar.gz | \
    tar zxf - -C /usr/share && \
    mv /usr/share/logstash-6.0.0-beta1 /usr/share/logstash
CMD /usr/share/logstash/bin/logstash-plugin install logstash-input-mysql
EOF

docker build -t logstash-plugin-install .
time docker run --rm -it logstash-plugin-install

[danwhitacre]

@jarpy I have run into the same issue. Building a docker image from docker.elastic.co/logstash/logstash:5.5.1, and trying to install a local gem. I haven't run any benchmarks, but it easily takes 5-7 minutes to install.

[danwhitacre]

I tried adding haveged as well to manage my entropy, and that didn't seem to kick the problem either. This has been suggested to fix the problem before.

[jarpy]

@suyograo: Do you have someone who would like to take a look at this? Thanks.

[danwhitacre]

my dockerfile for reference

# logstash base docker image
FROM docker.elastic.co/logstash/logstash:5.5.1

# entropy
RUN yum -y install wget
RUN wget http://dl.fedoraproject.org/pub/epel/7/x86_64/h/haveged-1.9.1-1.el7.x86_64.rpm
RUN rpm -Uvh haveged-1.9.1-1.el7.x86_64.rpm
RUN yum install haveged
RUN chkconfig haveged on

# copy the plugin gem
COPY logstash-filter-custom-?.?.?.gem /usr/share/logstash/

# install plugins
RUN /usr/share/logstash/bin/logstash-plugin install /usr/share/logstash/logstash-filter-custom-?.?.?.gem

# copy config files
RUN rm -f /usr/share/logstash/pipeline/logstash.conf
COPY config/ /usr/share/logstash/config/
COPY pipeline/ /usr/share/logstash/pipeline/

[jarpy]

I also had no luck with haveged.

The strace output is the most interesting thing I've seen so far. It spends vast amounts of time doing this:

pid     1] futex(0x7fd69226a9d0, FUTEX_WAIT, 31, NULL <unfinished ...>
[pid    47] futex(0x7f552b39b9d0, FUTEX_WAIT, 64, NULL

[danwhitacre]

@jarpy What was the strace that you ran? If the logstash plugin install process is multithreaded you will see a lot of hangs like that when the parent process is waiting for child process to complete.

[dliappis]

@jarpy So sorry for the late answer to your question.

I also get similar behavior (on 17.05.0-ce using devicemapper and LVM thinpool). Not as slow as what you guys have noticed, but at 1m58s you don't call it snappy either:

$ time docker run --rm -it logstash-plugin-install
Validating logstash-input-mysql
Installing logstash-input-mysql
Installation successful

real    1m57.958s
user    0m0.018s
sys 0m0.009s

[danwhitacre]

Yea, this is what I am getting currently.

real    6m30.947s
user    0m0.033s
sys 0m0.028s

Pretty unacceptable, so I am trying to look into as well. Unfortunately, I don't have much experience with this kind of stuff.

[guyisra]

Turning on DEBUG env var it seems that when installing a single specific plugin it also (re)installs all other plugins. So if the gemfile is changed, installing a plugin will update all gems.

[danwhitacre]

@guyisra I mean I don't think I have the DEBUG env var on. I am running with the default docker image, and I posted my Dockerfile above.

[dliappis]

Thanks for the tip @guyisra!

Indeed. I used the following:

cat >Dockerfile <<EOF
FROM openjdk:8-jre
RUN curl -Lo - https://artifacts.elastic.co/downloads/logstash/logstash-6.0.0-beta1.tar.gz |     tar zxf - -C /usr/share &&     mv /usr/share/logstash-6.0.0-beta1 /usr/share/logstash
RUN apt-get update && apt-get install -y htop iotop sysstat procps
EOF

docker build -t logstash-plugin-install .

and then ran:

docker run --rm -e 'DEBUG=true' --name logstash-plugin-install logstash-plugin-install bash -c '/usr/share/logstash/bin/logstash-plugin install logstash-input-mysql'

This shows lots of bundle stuff going on:

...
Bundle complete! 110 Gemfile dependencies, 195 gems now installed.
Gems in the group development were not installed.
Bundled gems are installed into .usr/share/logstash/vendor/bundle.
Installation successful

and using docker stats logstash-plugin-install we can see there are some pretty heavy CPU stuff going on, as well as a total bandwidth consumption of around 62MB, so depending on your cpu and network speed all the downloads may take some time plus build time needed by gem/bundler.

[danwhitacre]

So seeing some better times when running the install as part of my travis ci builds (~3-4 minute range). Wondering if this is a docker or host OS problem.

my local environment
docker version: Version 17.06.0-ce-mac19 (18663)
host os: OS X El Capitan 10.11

[ph]

Installing plugins is a bit and this is due for the JRUBY/Java startup
time, under docker it could be slower due to constraints on the containers.

On Sat, Aug 19, 2017 at 12:06 AM Dan Whitacre [e-mail]
wrote:

So seeing some better times when running the install as part of my travis
ci builds (~3-4 minute range). Wondering if this is a docker or host OS
problem.

my local environment
docker version: Version 17.06.0-ce-mac19 (18663)
host os: OS X El Capitan 10.11

—
You are receiving this because you were assigned.
Reply to this email directly, view it on GitHub
https://github.com/elastic/logstash/issues/6600#issuecomment-323498573,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AAACgD_61vRfvg171exQ4UAaL98_TA3Gks5sZl84gaJpZM4Lv0PP
.

>

ph

[danwhitacre]

hm so I just downloaded a fresh install of logstash 5.5.1 (not the docker image). On initial install of my plugin it took almost 2 minutes.

real    1m51.130s
user    0m49.065s
sys 0m2.791s

Uninstalled the plugin and reran and we're back down to a reasonable number.

real    0m20.360s
user    0m34.134s
sys 0m1.390s

was able to reproduce this and got similar results the second time.

[danwhitacre]

I can probably assume in the docker container, this would be a "fresh" logstash each time I go to build. So if its taking almost 2 minutes on my host normally, then in a docker container I could see it taking 4 or 5 minutes.

[danwhitacre]

I removed the entropy stuff from the docker file.. so this is what I have now.

# logstash base docker image
FROM docker.elastic.co/logstash/logstash:5.5.1

# copy the plugin gem
COPY logstash-filter-custom-?.?.?.gem /usr/share/logstash/

# install plugins
RUN /usr/share/logstash/bin/logstash-plugin install /usr/share/logstash/logstash-filter-custom-?.?.?.gem

# copy config files
RUN rm -f /usr/share/logstash/pipeline/logstash.conf
COPY config/ /usr/share/logstash/config/
COPY pipeline/ /usr/share/logstash/pipeline/

this is taking about 4 and a half minutes.

real    4m27.148s
user    0m0.034s
sys 0m0.029s

[purplesrl]

+1 on 6.0

If I install it from inside docker, it takes 1 minute

If I install it from the Dockerfile during the build process it takes 10+mins

[ebuildy]

Still very slow with Docker image docker.elastic.co/logstash/logstash-oss:6.2.4, any clue to improve it?

[cdenneen]

Any update on this issue? It's been a year since the last update.

[daggerjames]

logstash-plugin install would retrieve every gem if not in 'local' or 'development', see

If you were behind a Great Wall like me that has a huge connection issue to rubygems.org, you could manually copy a bundle config with mirrors into the folder.

...
WORKDIR /usr/share/logstash/
RUN mkdir -p .bundle
COPY /path/to/.bundle/config .bundle/config
...

and

# .bundle/config
---
BUNDLE_MIRROR__HTTPS://RUBYGEMS__ORG/: "https://gems.ruby-china.com"

Besides, locally run plugin install would be significantly quicker than inside docker, with my best guess, due to the cache inside ~/.bundle, generated by bundler. The environment inside docker is clean, so there is no cache to speed up :)