Why does the count of calls of a recursive method

Question

This question already has an answer here:

• Why is the max recursion depth I can reach non-deterministic? 4 answers

A simple class for demonstration purposes:

public class Main {

    private static int counter = 0;

    public static void main(String[] args) {
        try {
            f();
        } catch (StackOverflowError e) {
            System.out.println(counter);
        }
    }

    private static void f() {
        counter++;
        f();
    }
}

I executed the above program 5 times, the results are:

22025
22117
15234
21993
21430

Why are the results different each time?

I tried setting the max stack size (for example -Xss256k). The results were then a bit more consistent but again not equal each time.

Java version:

java version "1.8.0_72"
Java(TM) SE Runtime Environment (build 1.8.0_72-b15)
Java HotSpot(TM) 64-Bit Server VM (build 25.72-b15, mixed mode)

EDIT

When JIT is disabled (-Djava.compiler=NONE) I always get the same number (11907).

This makes sense as JIT optimizations are probably affecting the size of stack frames and the work done by JIT definitely has to vary between the executions.

Nevertheless, I think it would be beneficial if this theory is confirmed with references to some documentation about the topic and/or concrete examples of work done by JIT in this specific example that leads to frame size changes.

Answer 1

The observed variance is caused by background JIT compilation.

This is how the process looks like:

1. Method f() starts execution in interpreter.
2. After a number of invocations (around 250) the method is scheduled for compilation.
3. The compiler thread works in parallel to the application thread. Meanwhile the method continues execution in interpreter.
4. As soon as the compiler thread finishes compilation, the method entry point is replaced, so the next call to f() will invoke the compiled version of the method.

There is basically a race between applcation thread and JIT compiler thread. Interpreter may perform different number of calls before the compiled version of the method is ready. At the end there is a mix of interpreted and compiled frames.

No wonder that compiled frame layout differs from interpreted one. Compiled frames are usually smaller; they don't need to store all the execution context on the stack (method reference, constant pool reference, profiler data, all arguments, expression variables etc.)

Futhermore, there is even more race possibilities with Tiered Compilation (default since JDK 8). There can be a combination of 3 types of frames: interpreter, C1 and C2 (see below).

---

Let's have some fun experiments to support the theory.

1. Pure interpreted mode. No JIT compilation.
   No races => stable results.

   $ java -Xint Main
   11895
   11895
   11895
   

2. Disable background compilation. JIT is ON, but is synchronized with the application thread.
   No races again, but the number of calls is now higher due to compiled frames.

   $ java -XX:-BackgroundCompilation Main
   23462
   23462
   23462
   

3. Compile everything with C1 before execution. Unlike previous case there will be no interpreted frames on the stack, so the number will be a bit higher.

   $ java -Xcomp -XX:TieredStopAtLevel=1 Main
   23720
   23720
   23720
   

4. Now compile everything with C2 before execution. This will produce the most optimized code with the smallest frame. The number of calls will be the highest.

   $ java -Xcomp -XX:-TieredCompilation Main
   59300
   59300
   59300
   

   Since the default stack size is 1M, this should mean the frame now is only 16 bytes long. Is it?

   $ java -Xcomp -XX:-TieredCompilation -XX:CompileCommand=print,Main.f Main
   
     0x00000000025ab460: mov    %eax,-0x6000(%rsp)    ; StackOverflow check
     0x00000000025ab467: push   %rbp                  ; frame link
     0x00000000025ab468: sub    $0x10,%rsp            
     0x00000000025ab46c: movabs $0xd7726ef0,%r10      ; r10 = Main.class
     0x00000000025ab476: addl   $0x2,0x68(%r10)       ; Main.counter += 2
     0x00000000025ab47b: callq  0x00000000023c6620    ; invokestatic f()
     0x00000000025ab480: add    $0x10,%rsp
     0x00000000025ab484: pop    %rbp                  ; pop frame
     0x00000000025ab485: test   %eax,-0x23bb48b(%rip) ; safepoint poll
     0x00000000025ab48b: retq
   

   In fact, the frame here is 32 bytes, but JIT has inlined one level of recursion.

5. Finally, let's look at the mixed stack trace. In order to get it, we'll crash JVM on StackOverflowError (option available in debug builds).

   $ java -XX:AbortVMOnException=java.lang.StackOverflowError Main
   

   The crash dump hs_err_pid.log contains the detailed stack trace where we can find interpreted frames at the bottom, C1 frames in the middle and lastly C2 frames on the top.

   Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
   J 164 C2 Main.f()V (12 bytes) @ 0x00007f21251a5958 [0x00007f21251a5900+0x0000000000000058]
   J 164 C2 Main.f()V (12 bytes) @ 0x00007f21251a5920 [0x00007f21251a5900+0x0000000000000020]
     // ... repeated 19787 times ...
   J 164 C2 Main.f()V (12 bytes) @ 0x00007f21251a5920 [0x00007f21251a5900+0x0000000000000020]
   J 163 C1 Main.f()V (12 bytes) @ 0x00007f211dca50ec [0x00007f211dca5040+0x00000000000000ac]
   J 163 C1 Main.f()V (12 bytes) @ 0x00007f211dca50ec [0x00007f211dca5040+0x00000000000000ac]
     // ... repeated 1866 times ...
   J 163 C1 Main.f()V (12 bytes) @ 0x00007f211dca50ec [0x00007f211dca5040+0x00000000000000ac]
   j  Main.f()V+8
   j  Main.f()V+8
     // ... repeated 1839 times ...
   j  Main.f()V+8
   j  Main.main([Ljava/lang/String;)V+0
   v  ~StubRoutines::call_stub
   

Answer 2

The exact functioning of Java stack undocumented, but it totally depends on the memory allocated to that thread.

Just try using the Thread constructor with stacksize and see if it gets constant. I have not tried it it, so please share the results.

Answer 3

First of all, the following has not been researched. I have not "deep dived" the OpenJDK source code to validate any of the following, and I don't have access to any inside knowledge.

I tried to validate your results by running your test on my machine:

$ java -version
openjdk version "1.8.0_71"
OpenJDK Runtime Environment (build 1.8.0_71-b15)
OpenJDK 64-Bit Server VM (build 25.71-b15, mixed mode)

I get the "count" varying over a range of ~250. (Not as much as you are seeing)

First some background. A thread stack in a typical Java implementation is a contiguous region of memory that is allocated before the thread is started, and that is never grown or moved. A stack overflow happens when the JVM tries to create a stack frame to make a method call, and the frame goes beyond the limits of the memory region. The test could be done by testing the SP explicitly, but my understanding is that it is normally implemented using a clever trick with the memory page settings.

When a stack region is allocated, the JVM makes a syscall to tell the OS to mark a "red zone" page at the end of the stack region read-only or non-accessible. When a thread makes a call that overflows the stack, it accesses memory in the "red zone" which triggers a memory fault. The OS tells the JVM via a "signal", and the JVM's signal handler maps it to a StackOverflowError that is "thrown" on the thread's stack.

So here are a couple of possible explanations for the variability:

• The granularity of hardware-based memory protection is the page boundary. So if the thread stack has been allocated using malloc, the start of the region is not going to be page aligned. Therefore the distance from the start of the stack frame to the first word of the "red zone" (which >is< page aligned) is going to be variable.

• The "main" stack is potentially special, because that region may be used while the JVM is bootstrapping. That might lead to some "stuff" being left on the stack from before main was called. (This is not convincing ... and I'm not convinced.)

Having said this, the "large" variability that you are seeing is baffling. Page sizes are too small to explain a difference of ~7000 in the counts.

UPDATE

When JIT is disabled (-Djava.compiler=NONE) I always get the same number (11907).

Interesting. Among other things, that could cause stack limit checking to be done differently.

This makes sense as JIT optimizations are probably affecting the size of stack frames and the work done by JIT definitely has to vary between the executions.

Plausible. The size of the stackframe could well be different after the f() method has been JIT compiled. Assuming f() was JIT compiled at some point you stack will have a mixture of "old" and "new" frames. If the JIT compilation occurred at different points, then the ratio will be different ... and hence the count will be different when you hit the limit.

Nevertheless, I think it would be beneficial if this theory is confirmed with references to some documentation about the topic and/or concrete examples of work done by JIT in this specific example that leads to frame size changes.

Little chance of that, I'm afraid ... unless you are prepared to PAY someone to do a few days research for you.

1) No such (public) reference documentation exists, AFAIK. At least, I've never been able to find a definitive source for this kind of thing ... apart from deep diving the source code.

2) Looking at the JIT compiled code tells you nothing of how the bytecode interpreter handled things before the code was JIT compiled. So you won't be able to see if the frame size has changed.