Async-profiler: v1.6 - SIGSEGV on libasyncProfiler.so ElfParser::parseFile

[nobeh]

I am trying to run async-profiler from a host Linux on a docker container running a Java application:

Host:

$ uname -a
Linux nobeh13 5.0.0-29-generic #31-Ubuntu SMP Thu Sep 12 13:05:32 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

$ perf version
perf version 5.0.21

Example Dockerfile:

FROM ubuntu:18.04

SHELL [ "/bin/bash", "-c" ]

RUN \
    apt-get update && \
    apt-get install -y openjdk-8-jdk-headless && \
    apt-get clean && \
    rm -rf /var/lib/apt/lists/* /tmp/* /var/tmp/*

RUN \
    groupadd --gid 1000 bnobakht && \
    useradd --uid 1000 --gid 1000 --shell /bin/bash bnobakht && \
    chown -R bnobakht:root /opt && \
    mkdir /app && \
    chown -R bnobakht:root /app

ENV APP_ROOT /app

COPY ./highcpu/target/highcpu.jar ${APP_ROOT}/highcpu.jar
COPY ./run-highcpu.sh ${APP_ROOT}
COPY ./run.sh ${APP_ROOT}
COPY ./profile.sh ${APP_ROOT}

USER bnobakht
WORKDIR ${APP_ROOT}
CMD [ "./run-highcpu.sh" ]

For the docker container, I've tried docker base images openjdk:8-jdk, ubuntu:19.04 and ubuntu:18.04 (just to rule out potential issue on perf_event_open versions).

The following is how async-profiler is run from the host:

$ docker top $(docker ps | grep highcpu |cut -d ' ' -f 1)
$ sudo /opt/async-profiler/profiler.sh -d 10 -e cpu -o collapsed -f ./perf.txt JPID

and how the docker container is run:

$ docker run -it --rm --security-opt=seccomp:unconfined --volume $(pwd)/perf:/perf:rw --volume /opt/async-profiler:/opt/async-profiler:rw

The following is the header of the core dump:

# JRE version: OpenJDK Runtime Environment (8.0_222-b10) (build 1.8.0_222-8u222-b10-1ubuntu1~18.04.1-b10)
# Java VM: OpenJDK 64-Bit Server VM (25.222-b10 mixed mode linux-amd64 compressed oops)
# Problematic frame:
# C  [libasyncProfiler.so+0x1d0c3]  ElfParser::parseFile(NativeCodeCache*, char const*, char const*, bool)+0x83

The hs_err log is attached.

What am I missing or could this be a bug though not sure in which layer?

highcpu-error-29-2019-09-27_21-56-26.log

[apangin]

I've committed the fix, please check it if works.

It looks strange though, that in your case a file could be successfully opened, but could not be mmap'ed. Have you edited hs_err.log? It misses mapped file names, and the problem seems to be caused by one of those files.

[knittl]

I also encountered that bug. I can confirm that it works again with the fix. Interestingly enough, this has worked with v1.5 in the past for me, but now does not work with v1.5 either (admittedly, I did an OS upgrade from Ubuntu 19.04 to 19.10 inbetween).

With commit 78a83a31b2e3d22df6fff5653cd17e53d40d84d2, I can attach to my Java application running inside a docker container again (async-profiler is also fully contained in the container, using itimer mode).

I'm using the openjdk:11 docker image. Is there any additional information which I could provide?

[apangin]

@knittl Right, the bug existed since the beginning, but it looks like some recent OS changes actually triggered it.

I've created debug branch where the profiler prints an error on JVM's stderr whenever the problem happens - can you please try it and tell what the error is?

[knittl]

This line is printed 26 times in the target VM, when I try to attach the profiler (application and profiler both in same Docker image and running in the same container):

Failed to parse / of length -1: Cannot allocate memory

Async-profiler started with ./profiler.sh -d 1 -e itimer 1

---

More information:

root@61c3b07362da:/renderer-1.0-SNAPSHOT/bin# java  -version
openjdk version "11.0.4" 2019-07-16
OpenJDK Runtime Environment 18.9 (build 11.0.4+11)
OpenJDK 64-Bit Server VM 18.9 (build 11.0.4+11, mixed mode)
root@61c3b07362da:/renderer-1.0-SNAPSHOT/bin# uname -a
Linux 61c3b07362da 5.3.0-13-generic #14-Ubuntu SMP Tue Sep 24 02:46:08 UTC 2019 x86_64 GNU/Linux

Docker image: openjdk:11

[apangin]

@knittl Thank you for the details.
In hs_err.log provided by @nobeh there are also many lines with just "/" path in the memory map instead of the shared library names. What is also common in both cases is a docker container and Linux 5.x kernel. So, I guess this might be some "security feature" of a newer kernel. Will try to reproduce the problem on my side.

[knittl]

Right, it does not happen when attaching to a regular process outside of docker.

In case it helps, here is my docker version:

$ docker version
Client:
 Version:   17.12.0-ce
 API version:   1.35
 Go version:    go1.9.2
 Git commit:    c97c6d6
 Built: Wed Dec 27 20:10:45 2017
 OS/Arch:   linux/amd64

Server:
 Engine:
  Version:  17.12.0-ce
  API version:  1.35 (minimum version 1.12)
  Go version:   go1.9.2
  Git commit:   c97c6d6
  Built:    Wed Dec 27 20:09:19 2017
  OS/Arch:  linux/amd64
  Experimental: false

[apangin]

I found the problem, it appears to be Ubuntu/Linux bug:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1843018

The above link suggests the workaround to downgrade kernel to 5.0.0-25-generic.

I added the diagnostic message in async-profiler and the paragraph in README, so let me close the issue. Hopefully the bug will be resolved on Linux side soon, as it affects many other projects, too.

[nobeh]

I confirm that with a master branch build, it also started to work for me and I could generate a collapsed output with the following warning messages:

Could not parse symbols due to the OS bug
WARNING: Install JVM debug symbols to improve profile accuracy

The second is because I did not install -dbg package for JDK yet.

Thanks @apangin for the fix and @knittl for more details on why this is happening.