A deep, deep dive into Java debugging
Tags: debugging, java, showdev
Published: 2019-01-11 00:51:39

---
title: A deep, deep dive into Java debugging
published: true
description: Follow me down the rabbit hole... if you dare.
tags: debugging, java, showdev
---

This is the story of a Java debugging journey that started with a question I couldn't answer about Java stack traces. As a long time Java programmer, I am approached for help by developers who encounter unusual problems in the language. Diving in and ge</span>tting acquainted with all the dark corners of Java is something I really enjoy, mainly because I emerge with a better understanding of the language, and also because it equips our team with better tools to solve the everyday problems ... as well as the unusual ones.

Our trip takes us through a deeper look at Java lambdas and method references, and ends up with a quick foray into the JVM code. We'll use a couple of debugging tools and techniques to figure it all out, and learn a little about implementation details and diagnostic JVM options. <span class="inline-comment-marker valid">It's a good example of how, with the source in hand, you can demystify a general phenomenon, such as missing frames.</span>
<h2 id="ParentEpicFinalTerminalClauseFactoryandthecaseofthemissingframe-ItstartedwithaNullPointerException...">It all started with a <span style="font-family: courier;">NullPointerException</span>...</h2>
<span class="inline-comment-marker">A co-worker approac</span><span class="inline-comment-marker">hed me with the following stack trace:</span>
<pre>java.lang.NullPointerException
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.Collections$2.tryAdvance(Collections.java:4717)
	at java.util.Collections$2.forEachRemaining(Collections.java:4725)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
	at com.atlassian.jira.jql.util.ParentEpicFinalTerminalClauseFactory.getFinalTerminalQuery(ParentEpicFinalTerminalClauseFactory.java:47)</pre>
This was accompanied by another 364 less-interesting frames. What's interesting, and what brought him to me, is the code of the first frame. It's from the JDK (build <span style="font-family: courier;">1.8.0_172-b11</span>), and it is as follows:
<pre><strong>ReferencePipeline.java</strong>
public final  Stream map(Function&lt;? super P_OUT, ? extends R&gt; mapper) {
    Objects.requireNonNull(mapper);
    return new StatelessOp&lt;P_OUT, R&gt;(this, StreamShape.REFERENCE,
                                 StreamOpFlag.NOT_SORTED | StreamOpFlag.NOT_DISTINCT) {
        @Override
        Sink opWrapSink(int flags, Sink sink) {
            return new Sink.ChainedReference&lt;P_OUT, R&gt;(sink) {
                @Override
                <span style="color: #bf2600;">public void accept(P_OUT u) {</span>
                    downstream.accept(mapper.apply(u));
                }
            };
        }
    };
}
</pre>
The question at hand was, "What could be <span style="font-family: courier;">null</span> on line 193 (highlighted above in red)?"  It can't be <span style="font-family: courier;">mapper</span> because:
<ul style="padding-left: 60px;">
 	<li>It is a local, so it can't be updated from outside this code</li>
 	<li>There's a <span style="font-family: courier;">requireNonNull</span> before the usage, so it started not null, and</li>
 	<li>It is <em>effectively final</em> and used in an inner class, so it can't have changed. For full details on <em>effectively final</em> you can read the <a href="https://docs.oracle.com/javase/specs/jls/se8/html/jls-4.html#jls-4.12.4" class="external-link" rel="nofollow">Java Language Specification, version 8, section 4.12.4</a>, but TL;DR: it could be <span style="font-family: courier;">final</span> and so is treated as <span style="font-family: courier;">final</span> since the inner class reference needs it.</li>
</ul>
It can't be <span style="font-family: courier;">downstream</span>, because if you hunt down its declaration you find:
<pre><strong>Sink.java</strong>
static abstract class ChainedReference&lt;T, E_OUT&gt; implements Sink {
    protected final Sink&lt;? super E_OUT&gt; downstream;
 
    public ChainedReference(Sink&lt;? super E_OUT&gt; downstream) {
        this.downstream = Objects.requireNonNull(downstream);
    }
</pre>
As you can see:
<ul style="padding-left: 60px;">
 	<li>The field <span style="font-family: courier;">downstream</span> is final,</li>
 	<li>There's a <span style="font-family: courier;">requireNonNull</span> when it is initialized, and</li>
 	<li>There's no usage of <span style="font-family: courier;">this</span> or <span style="font-family: courier;">super</span> in the constructor, so we can't be in code executing on a partially constructed object.</li>
</ul>
My next thought was that maybe <span style="font-family: courier;">P_OUT</span> was a boxed type, like <span style="font-family: courier;">Integer</span> or <span style="font-family: courier;">Long</span>, and that to invoke <span style="font-family: courier;">mapper.apply</span>, the compiler had inserted an unboxing of <span style="font-family: courier;">u.</span><span class="inline-comment-marker">Unboxing throws a <span style="font-family: courier;">NullPointerException</span> if the reference is <span style="font-family: courier;">null</span> (detailed in <a class="external-link" href="https://docs.oracle.com/javase/specs/jls/se8/html/jls-5.html#jls-5.1.8" rel="nofollow">JLS 8, 5.1.8</a>). For example, code like <span style="font-family: courier;">int value = getValue();</span></span>

can throw an exception, if <span style="font-family: courier;">getValue()</span> is declared to return <span style="font-family: courier;">Integer</span> and actually returns <span style="font-family: courier;">null</span> because the compiler inserts a call to <span style="font-family: courier;">Integer.intValue</span> to convert the returned <span style="font-family: courier;">Integer</span> to an <span style="font-family: courier;">int</span>. However, looking at the code for <span style="font-family: courier;">getFinalTerminalQuery</span> in this case revealed that <span style="font-family: courier;">P_OUT</span> was <span style="font-family: courier;">com.atlassian.jira.issue.Issue</span>, which isn't boxed – it's the main issue interface in Jira.
<h2 id="ParentEpicFinalTerminalClauseFactoryandthecaseofthemissingframe-Where'sthenull?">Where's the <span style="font-family: courier;">null</span>?</h2>
Although these questions didn't find the source of the <span style="font-family: courier;">NullPointerException</span>, they did reveal that <span style="font-family: courier;">mapper</span> was <span style="font-family: courier;">Issue::getId</span> - that is - a <em>method reference</em> (<span class="inline-comment-marker">as per </span><a href="https://docs.oracle.com/javase/specs/jls/se8/html/jls-15.html#jls-15.13" class="external-link" rel="nofollow"><span class="inline-comment-marker">JLS 8, 15.13</span></a>), and this seemed unusual enough to be interesting and worth looking at further. At this point I was somewhat bemused, but also quite excited, because I couldn't explain what I was seeing ... which meant that I was about to learn something new! So I broke out a bit <span class="inline-comment-marker">of </span><span class="inline-comment-marker">test code</span><span class="inline-comment-marker"> by</span> boiling down the case above to the following code:
<pre><strong>Main.java</strong>
public class Main {
    static class Thing {
        Long
        getId() {
            return 163L;
        }
    }

    public static void main(String[] args) {
        Thing thing = null;
        System.out.println(
            Collections.singleton(thing).stream().map(Thing::getId).collect(toList())
        );
    }
}
</pre>
Sure enough, running this code got me a <span style="font-family: courier;">NullPointerException</span> with a stack similar enough to the above, at least at the pointy end. By the way, you can clone that repository using <span style="font-family: courier;">git clone git@bitbucket.org:atlassian/missing-frame.git</span> if you want to see it for yourself. There are some handy canned command lines in the README.

In other words, you'll get a <span style="font-family: courier;">NullPointerException</span> if you apply a valid method reference (like <span style="font-family: courier;">Thing::getId</span> in the example) to a <span style="font-family: courier;">null</span> reference.

This is not surprising. What is surprising, until you know this, is that you won't see a frame for the invocation of that function. You <em>can't</em> see a frame for <span style="font-family: courier;">getId</span> of course, because that would mean you'd be in a member function where <span style="font-family: courier;">this</span> was null, <span class="inline-comment-marker">which</span> won't happen while you're looking. This has nothing to do with the use of the <span style="font-family: courier;">Stream</span> by the way, you can get the same effect from
<pre>Thing thing = null;
Function&lt;Thing, Long&gt; function = Thing::getId;
function.apply(thing);
</pre>
<span class="inline-comment-marker">But I didn't know that at the time I was writing the test code</span>. This is one of the nice things about writing test code, you can freely edit it <span class="inline-comment-marker">and</span> play around with what exactly is causing the effect you are investigating.
<h2><span class="inline-comment-marker">But where is </span><span class="inline-comment-marker">the </span><span class="inline-comment-marker">exception thrown</span>?</h2>
In <span class="inline-comment-marker">IntelliJ, you can use </span><em><span class="inline-comment-marker">View/Show Bytecode</span></em><span class="inline-comment-marker"> on these examples to see the JVM bytecode. Other IDEs have similar functionality. You could also use <span style="font-family: courier;">javap</span> from the command line. In any case, </span>you will see something like:
<pre>INVOKEDYNAMIC apply()Ljava/util/function/Function; [
  // handle kind 0x6 : INVOKESTATIC
  java/lang/invoke/LambdaMetafactory.metafactory(Ljava/lang/invoke/MethodHandles$Lookup;Ljava/lang/String;Ljava/lang/invoke/MethodType;Ljava/lang/invoke/MethodType;Ljava/lang/invoke/MethodHandle;Ljava/lang/invoke/MethodType;)Ljava/lang/invoke/CallSite;
  // arguments:
  (Ljava/lang/Object;)Ljava/lang/Object;, 
  // handle kind 0x5 : INVOKEVIRTUAL
  com/atlassian/rgates/missingframe/Main$Thing.getId()Ljava/lang/Long;, 
  (Lcom/atlassian/rgates/missingframe/Main$Thing;)Ljava/lang/Long;
]</pre>
What is <span style="font-family: courier;">invokedynamic</span>, you say? In this case, we need to break out the <a href="https://docs.oracle.com/javase/specs/jvms/se8/html/jvms-6.html#jvms-6.5.invokedynamic">Java Virtual Machine Specification, version 8, section 6.5</a>, which tells us that some information is looked up and then resolved (as per <a href="https://docs.oracle.com/javase/specs/jvms/se8/html/jvms-5.html#jvms-5.4.3.6">JVMS 8, section 5.4.3.6</a>) to produce a <span style="font-family: courier;">MethodHandle</span> object. This is then <span style="font-family: courier;">invoke()</span>d to get a <span style="font-family: courier;">CallSite</span> which is bound to that instruction, effectively caching the costly lookup. Then, we <span style="font-family: courier;">invokeExact</span> the <span style="font-family: courier;">CallSite.target</span> to get a <span style="font-family: courier;">Function</span> object. Whoah. It's worth noting this is not what is throwing – it hasn't even looked at the <span style="font-family: courier;">null</span> reference yet, and the spec is quite clear that <em>an <span style="color: #003366;">"<span class="inline-comment-marker">invokedynamic instruction which is bound to a call site object never throws a </span><span style="font-family: courier;"><span class="inline-comment-marker">NullPointerException</span></span><span class="inline-comment-marker"> or …"</span></span></em><span class="inline-comment-marker">.</span>

<p>So what is the <span style="font-family: courier;">Function</span> we get? If you look at it in IntelliJ, for example by breakpointing the constructor of <span style="font-family: courier;">NullPointerException</span> and inspecting the <span style="font-family: courier;">mapper</span>, you see an object which claims to be a <span style="font-family: courier;">com.atlassian.rgates.missingframe.Main$$Lambda$1/6738746</span>, but you won't find that in your source. These classes are generated on the fly by the <span style="font-family: courier;">LambdaMetafactory</span> referenced in the <span style="font-family: courier;">INVOKEDYNAMIC</span> opcode. The code that writes them is in the delightfully named <span style="font-family: courier;">java.lang.invoke.InnerClassLambdaMetafactory#spinInnerClass</span>. It's worth noting they don't go through the normal <span style="font-family: courier;">ClassLoader</span> machinery, but use the wonderful <span style="font-family: courier;">sun.misc.Unsafe#defineAnonymousClass</span> to get themselves loaded.</p>

<p>Anyway, now that I was this far down, I had to keep digging. So I dumped the class spun up by <span style="font-family: courier;">spinInnerClass</span> to a file by evaluating <span style="font-family: courier;">new FileOutputStream("lambdaClass.class").write(classBytes)</span> in the debugger. This is a common trick I use when debugging – evaluating an expression which intentionally has side effects. There is some data we want to inspect – <span style="font-family: courier;">classBytes</span> in this example. To inspect it, we want to pass it off to another tool, and so we need to get it in a file. The expression has the side effect of writing <span style="font-family: courier;">classBytes</span> to the file <span style="font-family: courier;">lambdaClass.class</span>, and I can use this for further processing. Once I had the bytes from the built-on-the-fly class in a file, I could use the <span style="font-family: courier;">javap</span> utility to dump it.</p>
<pre>0: aload_1
1: checkcast     #15                 // class com/atlassian/rgates/missingframe/Main$Thing
4: invokevirtual #19                 // Method com/atlassian/rgates/missingframe/Main$Thing.getId:()Ljava/lang/Long;
7: areturn
</pre>
<span style="color: #222222;"><span style="color: #091e42;">Voila!</span> It's the <span style="font-family: courier;">invokevirtual</span> that is throwing <span style="font-family: courier;">NullPointerException</span>, as per <a href="https://docs.oracle.com/javase/specs/jvms/se8/html/jvms-6.html#jvms-6.5.invokevirtual">JVMS 8, section 6.5</a>: <em>if </em>objectref<em> is null, the </em>invokevirtual<em> instruction throws a <span style="font-family: courier;">NullPointerException</span></em>. So that's kind of what one might expect – a runtime generated wrapper which calls the function named by the method reference.</span>
<h2><span style="color: #222222;">But the frame is still missing!</span></h2>
<span style="color: #222222;">There totally should be a frame for <span style="font-family: courier;">apply</span>. In fact, if you're playing at home and have breakpointed the <span style="font-family: courier;">NullPointerException</span> constructor like me, you can see the <span style="font-family: courier;">apply</span> frame on the stack. However, if you step through the code until after the call to <span style="font-family: courier;">java.lang.Throwable#fillInStackTrace(int)</span>, you won't find the frame in the output of <span style="font-family: courier;">Throwable.getStackTrace</span>. At this point, the only place left to inspect was <span style="font-family: courier;">fillInStackTrace</span>, and of course that is <span style="font-family: courier;">native</span>. So you need to hop over to the <span class="inline-comment-marker">OpenJdk source</span>, and look at </span><span style="font-family: courier;">void java_lang_Throwable::fill_in_stack_trace(Handle throwable, methodHandle method, TRAPS)</span> in <span style="font-family: courier;">hotspot/src/share/vm/classfile/javaClasses.cpp</span>. I didn't <span class="inline-comment-marker">grok</span> the whole method, but I did skip through it enough to find:
<pre><strong>javaClasses.cpp</strong>
if (method-&gt;is_hidden()) {
  if (skip_hidden)  continue;
}</pre>
Methods can be <em>hidden</em>? <span style="color: #003366;"><span class="inline-comment-marker">TIL.</span><span class="inline-comment-marker"> </span></span>I wonder who calls <span style="font-family: courier;">set_hidden</span>? As it turns out, <span style="font-family: courier;">void ClassFileParser::MethodAnnotationCollector::apply_to(methodHandle m)</span> says:
<pre><strong>classFileParser.cpp</strong>
if (has_annotation(_method_LambdaForm_Hidden))
  m-&gt;set_hidden(true);</pre>
<span class="inline-comment-marker">A bit more digging reveals</span> that the value of <span style="font-family: courier;">_method_LambdaForm_Hidden</span> is the string <span style="font-family: courier;">Ljava/lang/invoke/LambdaForm$Hidden;</span>. To tie this back to the Java code, I again used <span style="font-family: courier;">javap</span> to decompile the class file we dumped above. This time, however, I added an extra flag to <span style="font-family: courier;">javap</span> - the <span style="font-family: courier;">-v</span> flag, which makes <span style="font-family: courier;">javap</span> verbose. In particular, this makes it dump the strings in the class constant pool - our string is at index <span style="font-family: courier;">#13</span>, and we can see the runtime annotation <span style="font-family: courier;">#13</span> is present on the <span style="font-family: courier;">apply</span> method:
<pre>#13 = Utf8               Ljava/lang/invoke/LambdaForm$Hidden;

...
public java.lang.Object apply(java.lang.Object);
...
RuntimeVisibleAnnotations:
  0: #13()
</pre>
<p class="auto-cursor-target">So, you can't see the frame because it's hidden. In fact, a bit further up in <span style="font-family: courier;">spinInnerClass</span>, it calls:</p>

<pre>mv.visitAnnotation("Ljava/lang/invoke/LambdaForm$Hidden;", true);</pre>
to add the annotation, but I missed this on the first read through. Reading this backwards to understand the flow: When generating the runtime wrappers used to invoke the method references, the generation code annotates the <span style="font-family: courier;">apply</span> method with a <span style="font-family: courier;">java.lang.invoke.LambdaForm$Hidden</span> annotation, and the JVM code (which fills in stack traces to implement the Java level <span style="color: #222222;"><span style="font-family: courier;">fillInStackTrace</span></span> function) checks for this annotation, and skips over frames for methods with this annotation.
<h2>One more thing …</h2>
The <span class="inline-comment-marker">sharp eyed will have noticed</span> that the JVM code in <span style="font-family: courier;">javaClasses.cpp</span> above has a <span style="font-family: courier;">skip_hidden</span> check also, which turns out to be set from <span style="font-family: courier;">ShowHiddenFrames</span>, which is mentioned in:
<pre>diagnostic(bool, ShowHiddenFrames, false,                                 \
        "show method handle implementation frames (usually hidden)")      \
</pre>
Reading some documentation in this file led me to <span style="font-family: courier;">java -XX:+UnlockDiagnosticVMOptions -XX:+PrintFlagsFinal</span> which shows a wealth of JVM diagnostic and internal stuff, including:
<pre>bool ShowHiddenFrames                          = false                               {diagnostic}</pre>
and thus, finally to:
<pre>:; java -XX:+UnlockDiagnosticVMOptions -XX:+ShowHiddenFrames -cp build/libs/missing-frame.jar com.atlassian.rgates.missingframe.Main
Exception in thread "main" java.lang.NullPointerException
	at com.atlassian.rgates.missingframe.Main$$Lambda$1/295530567.apply(:1000004)
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.Collections$2.tryAdvance(Collections.java:4717)
	at java.util.Collections$2.forEachRemaining(Collections.java:4725)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
	at com.atlassian.rgates.missingframe.Main.main(Main.java:17)</pre>
<p class="auto-cursor-target">There's the frame! The error is at <span style="font-family: courier;">&lt;Unknown&gt;:1000004</span> –  the JVM doesn't know the source name (hence <span style="font-family: courier;">&lt;Unknown&gt;</span>), and uses <span style="font-family: courier;">1000000 + bci</span> for line numbers if it has no line numbers, where <span style="font-family: courier;">bci</span> is the byte code index of the <span style="font-family: courier;">invokevirtual</span> we identified as the cause above.</p>

<h2 class="auto-cursor-target">And my co-worker?</h2>
I got back to my co-worker with my findings, and they responded <em><span style="color: #172b4d; text-decoration: none;">Curiosity: Satisfied</span></em>. It's nice to go beyond just "use this workaround" and instead gain a full understanding of exactly why the code is behaving in the way we observe. It's especially nice when I get to learn a few things about Java implementation details and JVM internals.