scala / scala-dev

Scala 2 team issues. Not for user-facing bugs or directly actionable user-facing improvements. For build/test/infra and for longer-term planning and idea tracking. Our bug tracker is at https://github.com/scala/bug/issues
Apache License 2.0
130 stars 14 forks source link

investigate: error events in jfr recording #239

Open lrytz opened 8 years ago

lrytz commented 8 years ago

I run the compiler with a flight recorder dump:

scalac -J-XX:+UnlockCommercialFeatures -J-XX:+FlightRecorder -J-XX:StartFlightRecording=dumponexit=true,settings=profile,filename=out.jfr

Opening the file in JMC, in the Events-Log tab, there's 483 events like this one. Seems to be NoSuchMethodErrors thrown by LambdaMetaFactory.

Name    Value   Identifier  Content Type    Relational Key
Start Time  10/5/16 11:55:27.185 AM (startTime) timestamp   
End Time    10/5/16 11:55:27.185 AM (endTime)   timestamp   
Duration    0 s (duration)  timespan    
Class   java.lang.NoSuchMethodError thrownClass class   
Message java.lang.Object.$anonfun$addSyntheticMethods$31(Lscala/tools/nsc/typechecker/SyntheticMethods;Lscala/tools/nsc/typechecker/MethodSynthesis$ClassMethodSynthesis;)Lscala/reflect/internal/Trees$Tree;   message text    
Event Thread    main    (thread)    thread  
    Error.<init>(String) line: 71           
    LinkageError.<init>(String) line: 55            
    IncompatibleClassChangeError.<init>(String) line: 55            
    NoSuchMethodError.<init>(String) line: 58           
    MethodHandleNatives.resolve(MemberName, Class)          
    MemberName$Factory.resolve(byte, MemberName, Class) line: 977           
    MemberName$Factory.resolveOrNull(byte, MemberName, Class) line: 1017            
    DirectMethodHandle.<init>(MethodType, LambdaForm, MemberName) line: 59          
    DirectMethodHandle.make(byte, Class, MemberName) line: 84           
    MethodHandles$Lookup.getDirectMethodCommon(byte, Class, MemberName, boolean, boolean, Class) line: 1656         
    MethodHandles$Lookup.getDirectMethodNoSecurityManager(byte, Class, MemberName, Class) line: 1613            
    MethodHandles$Lookup.getDirectMethodForConstant(byte, Class, MemberName) line: 1798         
    MethodHandles$Lookup.linkMethodHandleConstant(byte, Class, String, Object) line: 1747           
    MethodHandleNatives.linkMethodHandleConstant(Class, int, Class, String, Object) line: 477           
    SyntheticMethods.caseObjectMethods$1(MethodSynthesis$ClassMethodSynthesis, int, BooleanRef) line: 297           
    SyntheticMethods.synthesize$1(Contexts$Context, MethodSynthesis$ClassMethodSynthesis, int, BooleanRef) line: 319            
    SyntheticMethods.caseTemplateBody$1(Trees$Template, Contexts$Context, MethodSynthesis$ClassMethodSynthesis, int, BooleanRef) line: 392          
    SyntheticMethods.$anonfun$addSyntheticMethods$47(SyntheticMethods, Trees$Template, Contexts$Context, MethodSynthesis$ClassMethodSynthesis, int, BooleanRef, List) line: 396         
    SymbolTable.deriveTemplate(Trees$Tree, Function1) line: 16          
    SyntheticMethods.addSyntheticMethods(Trees$Template, Symbols$Symbol, Contexts$Context) line: 395            
    SyntheticMethods.addSyntheticMethods$(SyntheticMethods, Trees$Template, Symbols$Symbol, Contexts$Context) line: 65          
    Global$$anon$1.addSyntheticMethods(Trees$Template, Symbols$Symbol, Contexts$Context) line: 424          
    Typers$Typer.finishMethodSynthesis(Trees$Template, Symbols$Symbol, Contexts$Context) line: 1874         
    Typers$Typer.typedModuleDef(Trees$ModuleDef) line: 1855         
...
retronym commented 8 years ago

Seems like this shows up from this "corner case" check in DirectMethodHandle for public lambda target methods in interfaces.

        if (member.getDeclaringClass().isInterface() &&
                member.isMethod() && !member.isAbstract()) {
            // Check for corner case: invokeinterface of Object method
            MemberName m = new MemberName(Object.class, member.getName(), member.getMethodType(), member.getReferenceKind());
            m = MemberName.getFactory().resolveOrNull(m.getReferenceKind(), m, null);
            if (m != null && m.isPublic()) {
                assert(member.getReferenceKind() == m.getReferenceKind());  // else this.form is wrong
                member = m;
            }
        }

resolveOrNull internally uses exceptions as control flow. 😭

An equivalent javac lambda would be backed by a private method and would not go through this check.

retronym commented 8 years ago

Seem liks the JDK could be changed to skip that code path for static references (such as our lambda refs) as there are no non-private static methods in Object.

retronym commented 8 years ago

https://bugs.openjdk.java.net/browse/JDK-8161588

retronym commented 8 years ago

Withdrawing this as clearing exceptions actually doesn't seem to get rid of overhead(!), making this change moot. The overhead for my use case is small but annoying.

http://mail.openjdk.java.net/pipermail/core-libs-dev/2016-August/042770.html

👎

retronym commented 8 years ago

I guess we'll need to apply Claes' patches to the JDK and see if we can measure a performance improvement.

retronym commented 8 years ago

/cc @cl4es

cl4es commented 8 years ago

Seems like I should make another attempt at fixing this. Which version of the JDK are you targetting?

lrytz commented 8 years ago

Scala 2.12 requires JDK 8. I was using 1.8.0_102 on macOS sierra.

cl4es commented 8 years ago

Ok, I'll see what I can do.

retronym commented 8 years ago

Thanks! The motivating difference in our use case is that it is more common to have lambdas in interfaces, because we're now compiling Scala traits directly to interfaces+default methods, and lots of existing Scala code uses lambdas in traits.

cl4es commented 8 years ago

Got it.

It'd be nice if you could get some data on how much this actually matters performance-wise in your case, e.g., for startup. I think fixing it for JDK 9 can be motivated on a purely hygenic note, but backports may need extra motivation.

retronym commented 8 years ago

Will do.

Relatedly, the calling code looks wrong (or at least not clearly right) to me:

    private DirectMethodHandle(MethodType mtype, LambdaForm form, MemberName member) {
        super(mtype, form);
        if (!member.isResolved())  throw new InternalError();

        if (member.getDeclaringClass().isInterface() &&
                member.isMethod() && !member.isAbstract()) {
            // Check for corner case: invokeinterface of Object method
            MemberName m = new MemberName(Object.class, member.getName(), member.getMethodType(), member.getReferenceKind());
            m = MemberName.getFactory().resolveOrNull(m.getReferenceKind(), m, null);
            if (m != null && m.isPublic()) {
                assert(member.getReferenceKind() == m.getReferenceKind());  // else this.form is wrong
                member = m;
            }
        }

        this.member = member;
    }

I can't quite break this, but I think it is only correct because there are no public static methods in Object.

Here's what I tried:


public class Test {
    interface Thunk { void apply(); }
    public interface I {
        // private statics require Java 9
        private static void registerNatives() { System.out.println("I::registerNatives");}
        private static void foo() { System.out.println("I::foo");}

        default Thunk registerNativesThunk() {
            // Linking this constant gets most of the way into the "Check for corner case: invokeinterface of Object method"
            // code path in DirectMethodHandle, but does not rebind to Object::registerNatives as it
            // is non-public.
            return I::registerNatives;
        }
        default Thunk fooThunk() {
            // The same code path would incorrectly (?) rebind a static reference to I::foo
            // to a hypothetical new static method Object:foo.
            return I::foo;
        }
    }
    static class C implements I {}
    public static void main(String[] args) {
        new C().fooThunk().apply();
        new C().registerNativesThunk().apply();
    }
}
retronym commented 8 years ago

Note to self: we can probably approximate the benchmarking by turning off stack traces in throwables with:

⚡ (java -XX:+PrintFlagsInitial 2>&1) | grep StackTraceInThrowable
     bool StackTraceInThrowable                     = true                                {product}

Based on the numbers in:

https://shipilev.net/blog/2014/exceptional-performance/#_lil_exception_is_born

And assuming that the 483 events reported in JFR mean that 483 errors were thrown (and it isn't a sampled value), my back of the envelope calculations lead me to believe that we're only talking something in the order of 20 milliseconds of overhead, which would be within noise in our benchmarks.

cl4es commented 8 years ago

Error events are not sampled (java.lang.Error is instrumented to trigger the events on creation).

I'd guess the overhead is small, too, and mostly happen during startup. It's an unnecessary distraction and would be good to get it cleaned up, though.

lrytz commented 8 years ago

I also observed some java.lang.NoSuchFieldErrors (in addition to NoSuchMethodError) in a MethodHandles$Lookup.linkMethodHandleConstant(byte, Class, String, Object) stack trace, also during lambda initialization.

dwijnand commented 4 years ago

Keep open?