3

Environment:

  1. Linux 4.x
  2. async-profiler 1.6 (https://github.com/jvm-profiling-tools/async-profiler)
  3. OpenJDK8

Application-Code:

Domain-Socket communication via SocketInputStream

Action:

run app with async profiler: -d 60 -e alloc -f /tmp/alloc.svg

Problem:

unexpected String allocation from SocketInputStream#socketRead0

(cyan: TLAB alloc)

enter image description here JDK-Code for socketRead and socketRead0

private int socketRead(FileDescriptor fd,
                       byte b[], int off, int len,
                       int timeout)
    throws IOException {
    return socketRead0(fd, b, off, len, timeout);
}

private native int socketRead0(FileDescriptor fd,
                               byte b[], int off, int len,
                               int timeout)

native Socket-Impl:

  • jdk/src/solaris/native/java/net/SocketInputStream.c

Assumption:

String is probably allocated in the java-heap via JNI somewhere in following code, because there is a SocketTimeoutException in the StackTrace right beside the string allocation

Java_java_net_SocketInputStream_socketRead0(JNIEnv *env, jobject this,
                                            jobject fdObj, jbyteArray data,
                                            jint off, jint len, jint timeout)
{
    [...]
    if (timeout) {
        nread = NET_ReadWithTimeout(env, fd, bufP, len, timeout);
        if ((*env)->ExceptionCheck(env)) {
            if (bufP != BUF) {
                free(bufP);
            }
            return nread;
        }
    } else {
        nread = NET_Read(fd, bufP, len);
    }
    [...]
}

static int NET_ReadWithTimeout(JNIEnv *env, int fd, char *bufP, int len, long timeout) {
    int result = 0;
    long prevtime = NET_GetCurrentTime(), newtime;
    while (timeout > 0) {
        result = NET_TimeoutWithCurrentTime(fd, timeout, prevtime);
        if (result <= 0) {
            if (result == 0) {
                JNU_ThrowByName(env, "java/net/SocketTimeoutException", "Read timed out");
            } else if (result == -1) {
                if (errno == EBADF) {
                    JNU_ThrowByName(env, "java/net/SocketException", "Socket closed");
                } else if (errno == ENOMEM) {
                    JNU_ThrowOutOfMemoryError(env, "NET_Timeout native heap allocation failed");
                } else {
                    JNU_ThrowByNameWithMessageAndLastError
                            (env, "java/net/SocketException", "select/poll failed");
                }
            }
            return -1;
        }
        result = NET_NonBlockingRead(fd, bufP, len);
        if (result == -1 && ((errno == EAGAIN) || (errno == EWOULDBLOCK))) {
            newtime = NET_GetCurrentTime();
            timeout -= newtime - prevtime;
            if (timeout > 0) {
                prevtime = newtime;
            }
        } else {
            break;
        }
    }
    return result;
}

I searched the C-code and did not find any jString allocations, therfore I am kind of ideas.

Anyone an idea where the String allocation might happen?

apangin
  • 92,924
  • 10
  • 193
  • 247
Sergej Isbrecht
  • 3,842
  • 18
  • 27

1 Answers1

4

Your assumption is right. SocketTimeoutException in the profile tells that the method allocates an exception object, and this exception object has a String message that also needs to be allocated.

I've just committed a change to async-profiler that adds --cstack option for recording C stack along with Java stack in allocation profiling mode. It proves that java.lang.String is indeed allocated from JNI ThrowNew function:

async-profiler

apangin
  • 92,924
  • 10
  • 193
  • 247
  • I built async-profiler from master and as a matter of fact I do see the same behavior with --cstack as you described in your example. Thank you for your contribution. – Sergej Isbrecht Jan 07 '20 at 12:30