-XX:+TieredCompilation destroys tracebacks #1025

Closed
ivan opened this Issue Feb 22, 2013 · 9 comments

Comments

2 participants

ivan commented Feb 22, 2013

leiningen specifies a default :jvm-opts of ["-XX:+TieredCompilation"], but unfortunately -XX:+TieredCompilation destroys traceback information (at least in Clojure), probably due to JIT bugs:

user> (inc nil) (pst)
NullPointerException   clojure.lang.Numbers.ops (Numbers.java:942)
NullPointerException 
    clojure.lang.Numbers.ops (Numbers.java:942)
    clojure.lang.Numbers.inc (Numbers.java:110)
    user/eval2992 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
    clojure.main/repl/fn--6610/fn--6611 (main.clj:271)
    clojure.main/repl/fn--6610 (main.clj:271)
    clojure.main/repl (main.clj:269)
    clojure.tools.nrepl.middleware.interruptible-eval/evaluate/fn--2767 (interruptible_eval.clj:56)
nil
user> (inc nil) (pst)
NullPointerException   clojure.lang.Numbers.ops (Numbers.java:942)
NullPointerException 
    clojure.lang.Numbers.ops (Numbers.java:942)
    clojure.lang.Numbers.inc (Numbers.java:110)
    user/eval2996 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
    clojure.main/repl/fn--6610/fn--6611 (main.clj:271)
    clojure.main/repl/fn--6610 (main.clj:271)
    clojure.main/repl (main.clj:269)
    clojure.tools.nrepl.middleware.interruptible-eval/evaluate/fn--2767 (interruptible_eval.clj:56)
nil
user> (inc nil) (pst)
NullPointerException   clojure.lang.Numbers.ops (Numbers.java:942)
NullPointerException 
    clojure.lang.Numbers.ops (Numbers.java:942)
    clojure.lang.Numbers.inc (Numbers.java:110)
    user/eval3000 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
    clojure.main/repl/fn--6610/fn--6611 (main.clj:271)
    clojure.main/repl/fn--6610 (main.clj:271)
    clojure.main/repl (main.clj:269)
    clojure.tools.nrepl.middleware.interruptible-eval/evaluate/fn--2767 (interruptible_eval.clj:56)
nil
user> (inc nil) (pst)
NullPointerException   [trace missing]
NullPointerException 
nil
user> (inc nil) (pst)
NullPointerException   [trace missing]
NullPointerException 
nil
user> (inc nil) (pst)
NullPointerException   [trace missing]
NullPointerException 
nil
user> (re-seq #"" nil) (pst)
NullPointerException   java.util.regex.Matcher.getTextLength (Matcher.java:1234)
NullPointerException 
    java.util.regex.Matcher.getTextLength (Matcher.java:1234)
    java.util.regex.Matcher.reset (Matcher.java:308)
    java.util.regex.Matcher.<init> (Matcher.java:228)
    java.util.regex.Pattern.matcher (Pattern.java:1088)
    clojure.core/re-matcher (core.clj:4386)
    clojure.core/re-seq (core.clj:4411)
    user/eval3016 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
nil
user> (re-seq #"" nil) (pst)
NullPointerException   java.util.regex.Matcher.getTextLength (Matcher.java:1234)
NullPointerException 
    java.util.regex.Matcher.getTextLength (Matcher.java:1234)
    java.util.regex.Matcher.reset (Matcher.java:308)
    java.util.regex.Matcher.<init> (Matcher.java:228)
    java.util.regex.Pattern.matcher (Pattern.java:1088)
    clojure.core/re-matcher (core.clj:4386)
    clojure.core/re-seq (core.clj:4411)
    user/eval3020 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
nil
user> (re-seq #"" nil) (pst)
NullPointerException   java.util.regex.Matcher.getTextLength (Matcher.java:1234)
NullPointerException 
    java.util.regex.Matcher.getTextLength (Matcher.java:1234)
    java.util.regex.Matcher.reset (Matcher.java:308)
    java.util.regex.Matcher.<init> (Matcher.java:228)
    java.util.regex.Pattern.matcher (Pattern.java:1088)
    clojure.core/re-matcher (core.clj:4386)
    clojure.core/re-seq (core.clj:4411)
    user/eval3024 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
nil
user> (re-seq #"" nil) (pst)
NullPointerException   java.util.regex.Matcher.getTextLength (Matcher.java:1234)
NullPointerException 
    java.util.regex.Matcher.getTextLength (Matcher.java:1234)
    java.util.regex.Matcher.reset (Matcher.java:308)
    java.util.regex.Matcher.<init> (Matcher.java:228)
    java.util.regex.Pattern.matcher (Pattern.java:1088)
    clojure.core/re-matcher (core.clj:4386)
    clojure.core/re-seq (core.clj:4411)
    user/eval3028 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
nil
user> (re-seq #"" nil) (pst)
NullPointerException   java.util.regex.Matcher.getTextLength (Matcher.java:1234)
NullPointerException 
    java.util.regex.Matcher.getTextLength (Matcher.java:1234)
    java.util.regex.Matcher.reset (Matcher.java:308)
    java.util.regex.Matcher.<init> (Matcher.java:228)
    java.util.regex.Pattern.matcher (Pattern.java:1088)
    clojure.core/re-matcher (core.clj:4386)
    clojure.core/re-seq (core.clj:4411)
    user/eval3032 (NO_SOURCE_FILE:1)
    clojure.lang.Compiler.eval (Compiler.java:6619)
    clojure.lang.Compiler.eval (Compiler.java:6582)
    clojure.core/eval (core.clj:2852)
    clojure.main/repl/read-eval-print--6601/fn--6604 (main.clj:253)
    clojure.main/repl/read-eval-print--6601 (main.clj:253)
nil
user> (re-seq #"" nil) (pst)
NullPointerException   [trace missing]
NullPointerException 
nil
user> (re-seq #"" nil) (pst)
NullPointerException   [trace missing]
NullPointerException 
nil
user> (re-seq #"" nil) (pst)
NullPointerException   [trace missing]
NullPointerException 
nil

I tested with

OpenJDK Runtime Environment (IcedTea7 2.3.6) (7u13-2.3.6-0ubuntu0.12.10.1)
OpenJDK 64-Bit Server VM (build 23.7-b01, mixed mode)

on 64-bit Ubuntu 12.10

and

java version "1.7.0_13"
Java(TM) SE Runtime Environment (build 1.7.0_13-b20)
Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode)

on 64-bit Windows 7

Owner

technomancy commented Feb 22, 2013

Thanks for tracking down the root cause. It looks like placing a limit on tiered compilation still lets us get the benefits of increased startup speed without triggering the bug. I didn't want to do this at first since it results in degraded performance in the long term, but typically boot is more important.

@technomancy technomancy added a commit that referenced this issue Feb 22, 2013

@technomancy technomancy Moving Tiered Compilation to the dev profile.
Ensures the fix to #1025 doesn't affect production usage of Leiningen.
57ea876

ivan commented Feb 24, 2013

Bug filed with Oracle at bugs.sun.com; internal review ID is 2456988

I reproduced it on Ubuntu, Windows 7, Mountain Lion, and with Java 8 Build b77 as well.

-XX:TieredStopAtLevel=3 is also enough to avoid triggering the bug.

Owner

technomancy commented Feb 26, 2013

For those seeing this problem in Leiningen 2.0.0, this will fix things:

:jvm-opts ["-XX:+TieredCompilation" "-XX:TieredStopAtLevel=1"]

Though you may want to put it in the :dev profile if you don't want it to affect production use.

ivan commented May 2, 2013

If I ever get a reply from Oracle (not looking likely), I'll post the bug ID here

ivan commented Dec 2, 2013

The original JVM issue is still unfixed in Java 8 Build b117

ivan commented Mar 21, 2014

Oracle Java 8 (build 1.8.0-b132) has turned on TieredCompilation by default, and still has this bug.

ivan commented Mar 21, 2014

This is not an OpenJDK or Clojure bug, but rather a HotSpot optimization that throws preallocated exceptions without a stack trace for hot throws. It's implemented here: http://hg.openjdk.java.net/jdk7u/jdk7u/hotspot/file/tip/src/share/vm/opto/graphKit.cpp#l548

This particular optimization can make stack traces disappear for NullPointerException, ArithmeticException, ArrayIndexOutOfBoundsException, ArrayStoreException, and ClassCastException.

Contrary to my earlier comments, they go missing even when tiered compilation is off, or when the max tier level is 3 (or even 1). Note that with some settings, it may take a lot longer for the throw to become hot and the stack trace to go missing.

To turn this optimization off and always see stack traces, start java with -XX:-OmitStackTraceInFastThrow.

The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag: -XX:-OmitStackTraceInFastThrow.

http://www.oracle.com/technetwork/java/javase/relnotes-139183.html

Owner

technomancy commented Mar 21, 2014

Thanks for taking the time to look into this. While this optimization probably makes sense in production, it's definitely not what you want during development, so I've added the flag to the default jvm-opts.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment