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)

Merwyn

What JDK are you using? According to this code, Arrays#fill indeed shouldn't be reached. – Seldan

@Seldan I updated the question to add version info. – Merwyn

that looks impossible from the code indeed, unless that if is called before it – Lietman

What is your initial size of the StringBuilder? (Constants.INITIAL_REUSABLE_MESSAGE_SIZE) – Briscoe

Did you set a break point on if (count < newLength) { ? I mean if the condition really is true, I'd check where the values are coming from. – Briscoe

@Kayaman Yes but I sprinkled salt on my desk first so that should be fine... Thanks for the -Xnocursedjvm flag suggestion. The QA team will like that one. :-) – Merwyn

INITIAL_REUSABLE_MESSAGE_SIZE could be overridden by the log4j.initialReusableMsgSize system property. Could you check if you aren't setting it to some negative number by mistake? (wild guess, I know, but running out of ideas here - at least ideas that don't involve dark magic, that is ;-)) – Seldan

@Seldan I am confident the INITIAL_REUSABLE_MESSAGE_SIZE is not overridden with a system property and even if it was a negative number, new char[capacity] would fail in the AbstractStringBuilder constructor. – Merwyn

Looking at the AbstractStringBuilder class source, the member variable int count is never initialised to zero. It's always assumed it defaults to zero but we cannot be sure going by this reference docs.oracle.com/javase/tutorial/java/nutsandbolts/… which states "Fields that are declared but not initialized will be set to a reasonable default by the compiler. ... Relying on such default values, however, is generally considered bad programming style" I would suggest inspecting messageText.length() or the count variable once. We can never be sure.. – Bloodsucker

this might be an optimization from JIT, thus I added the jvm tag. there are some really awesome users following that tag that could shed some light here - I hope u don't mind – Lietman

@AnupChaudhari last time I checked the JLS defined explicit default values so you can rely on them even if it is not too obvious. But these defaults are there all along so unlikely to change. see docs.oracle.com/javase/specs/jls/se9/html/jls-4.html#jls-4.12.5 – Stoush

Told u some "cool" guys will help us ( I was really meaning just pangin here... ) – Lietman

It might be worth running your application with the extra jvm flags "-XX:+UnlockDiagnosticVMOptions -XX:+DebugNonSafepoints", see docs.oracle.com/javacomponents/jmc-5-5/jfr-runtime-guide/… section 1.4.1 – Marvel

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.

Nikolas

See docs.oracle.com/javacomponents/jmc-5-5/jfr-runtime-guide/…, section 1.4.1, this might help against this issue. – Marvel

@Marvel This is a different issue. – Nikolas