JDK-8076161 : Runtime stub for throw_null_pointer_exception always constructs log messages
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 9
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2015-03-27
  • Updated: 2016-04-04
  • Resolved: 2015-06-10
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b72Fixed
Related Reports
Relates :  
Description
If you compare the costs of implicit null checks vs explicit checks, like this:

    @CompilerControl(CompilerControl.Mode.DONT_INLINE)
    public int do_Implicit(MyObject o) {
        return o.x;
    }

    @CompilerControl(CompilerControl.Mode.DONT_INLINE)
    public int do_Explicit(MyObject o) {
        if (o == null) {
            throw new NullPointerException("Boo");
        }
        return o.x;
    }

Then you will notice the implicit null checks are 4-5x more costly:
  testExplicit: 1551.416 ��  67.577  us/op
  testImplicit: 8177.205 �� 631.399  us/op

Profiling testImplicit yields:

Call Tree: FUNCTIONS.   Complete view.   Threshold: 1%   Sort by: metric.   Metric: Attributed Total CPU Time
+-  11.058   (100%)    <Total>
  +-  6.304   (57%)    RuntimeStub - throw_null_pointer_exception Runtime1 stub
  |  +-  6.264   (57%)    Runtime1::throw_null_pointer_exception(JavaThread*)
  |    +-  3.863   (35%)    SharedRuntime::throw_and_post_jvmti_exception(JavaThread*,Handle)
  |    |  +-  3.843   (35%)    Exceptions::_throw(Thread*,const char*,int,Handle,const char*)
  |    |    +-  3.032   (27%)    oopDesc::print_value_string()
  |    |    |  +-  3.022   (27%)    InstanceKlass::oop_print_value_on(oopDesc*,outputStream*)
  |    |    |    +-  2.942   (27%)    Symbol::print_value_on(outputStream*)const
  |    |    |    |  +-  2.912   (26%)    outputStream::print(const char*,...)
  |    |    |    |    +-  2.212   (20%)    outputStream::do_vsnprintf(char*,unsigned long,const char*,__va_list_tag*,bool,unsigned long&)
  |    |    |    |    |  +-  1.861   (17%)    vsnprintf
  |    |    |    |    |  |  +-  1.131   (10%)    vfprintf
  |    |    |    |    |  |  |  +-  0.150   (1%)    _IO_default_xsputn
  |    |    |    |    |  |  |  +-  0.080   (1%)    strchrnul

This happens because the log message is constructed always, regardless of LogEvents setting that is allegedly supposed to filter these:

void Exceptions::_throw(Thread* thread, const char* file, int line, Handle h_exception, const char* message) {
 ...
  // vm log
  Events::log_exception(thread, "Exception <%s%s%s> (" INTPTR_FORMAT ") thrown at [%s, line %d]",
                        h_exception->print_value_string(), message ? ": " : "", message ? message : "",
                        (address)h_exception(), file, line);
}

inline void Events::log_exception(Thread* thread, const char* format, ...) {
  if (LogEvents) {
    va_list ap;
    va_start(ap, format);
    _exceptions->logv(thread, format, ap);
    va_end(ap);
  }
}

Notice "print_value_string" call in the "log_exception" arguments.
Comments
A full fix should probably evaluate other places where LogEvents is supposed to act as a "don't do anything" check.
27-03-2015

Benchmark: http://cr.openjdk.java.net/~shade/8076161/ImplicitNullChecks.java Executable JAR: http://cr.openjdk.java.net/~shade/8076161/benchmarks.jar
27-03-2015