Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8076161

Runtime stub for throw_null_pointer_exception always constructs log messages

XMLWordPrintable

    • Icon: Enhancement Enhancement
    • Resolution: Fixed
    • Icon: P3 P3
    • 9
    • 9
    • hotspot
    • None
    • b72

        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.

              mockner Max Ockner (Inactive)
              shade Aleksey Shipilev
              Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

                Created:
                Updated:
                Resolved: