How is it possible that StringBuilder.setLength(0) invokes Arrays.fill?

Question

While investigating a performance test result I found the following stack trace reported in Java Flight Recorder's "Hot Methods":

Stack Trace                                        Sample Count Percentage(%)
-----------                                        ------------ ----------
java.util.Arrays.rangeCheck(int, int, int)                  358      2.212
   java.util.Arrays.fill(char[], int, int, char)            358      2.212
      java.lang.AbstractStringBuilder.setLength(int)        358      2.212
         java.lang.StringBuilder.setLength(int)             358      2.212
            org.apache.logging.log4j.core.async.RingBufferLogEvent.getMessageTextForWriting()
                                                            201      1.242
               org.apache.logging.log4j.core.async.RingBufferLogEvent.setMessage(Message)
                                                            201      1.242

From the stack trace, it looks like setting the StringBuilder's length results in Arrays.fill being called. However, I don't understand why this is happening because the StringBuilder's length is set to zero.

Looking at the code for Log4j's RingBufferLogEvent.getMessageTextForWriting method, it is clear the StringBuilder's length is never set to any other value than zero:

// RingBufferLogEvent.java

private StringBuilder getMessageTextForWriting() {
    if (messageText == null) {
        messageText = new StringBuilder(Constants.INITIAL_REUSABLE_MESSAGE_SIZE); // 128
    }
    messageText.setLength(0); // <-- this call. Note: new length is ALWAYS zero.
    return messageText;
}

I don't understand how this could ever result in Arrays.fill being invoked. Looking at the code for AbstractStringBuilder, Arrays.fill should only be invoked if the new length is greater than the previous number of characters used.

// AbstractStringBuilder.java

public void setLength(int newLength) {
    if (newLength < 0)
        throw new StringIndexOutOfBoundsException(newLength);
    ensureCapacityInternal(newLength);

    if (count < newLength) { // <-- how can this condition be true if newLength is zero?
        Arrays.fill(value, count, newLength, '\0');
    }

    count = newLength;
}

How could count < newLength ever be true when newLength is always zero?

---

JVM Version:

Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)

(and Log4j 2.10.0)

Answer 1

There is an issue with JFR. It collects stack traces asynchronously, i.e. not only at safepoints like many other profilers do. On one hand, this makes sampling more realistic, since there is no safepoint bias. On the other hand, HotSpot JVM is not able to walk the stack correctly at any random moment of time.

HotSpot private API AsyncGetCallTrace tries to do best to recover current stack trace from any arbitrary point where a timer signal has interrupted the application. However, some places in the code are not safe for stack walking. If AsyncGetCallTrace is called at one of those places, it may return invalid stack trace or no stack trace at all.

This is a known issue of AsyncGetCallTrace. JDK-8022893 has the examples and the analysis of the problem. It is a rather often situation that AsyncGetCallTrace (and all profilers based on it) returns inaccurate trace where some frames are mistakenly replaced by neighbour methods.