This Bugzilla instance is a read-only archive of historic NetBeans bug reports. To report a bug in NetBeans please follow the project's instructions for reporting issues.

Bug 268310 - Excessive InapplicableMethodException causes slowness in bg-scan during initial load.
Summary: Excessive InapplicableMethodException causes slowness in bg-scan during initi...
Status: NEW
Alias: None
Product: java
Classification: Unclassified
Component: Compiler (show other bugs)
Version: Dev
Hardware: PC Windows 7
: P3 normal (vote)
Assignee: Dusan Balek
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-10-02 18:14 UTC by NukemBy
Modified: 2016-10-02 18:37 UTC (History)
0 users

See Also:
Issue Type: DEFECT
Exception Reporter:


Attachments
profiler screen-shot (473.61 KB, image/jpeg)
2016-10-02 18:14 UTC, NukemBy
Details

Note You need to log in before you can comment on or make changes to this bug.
Description NukemBy 2016-10-02 18:14:35 UTC
Created attachment 162306 [details]
profiler screen-shot

While self-profiling NetBeans to check what so lengthy is happening in background scan I see that top hot point is filling stack trace for `com.sun.tools.javac.comp.Resolve$InapplicableMethodException` (see attached screen shot).

While capturing one of such exceptions I see that it occurs for class, whose information resides in cache
      sourcefile
         ClassReader$SourceFileObject
         SourceFileObject[RequestProcessor.java]	
      classfile
         FileObjects$FileBase
         file:/C:/.../workspace/cache/index/s765/java/15/classes/org/openide/util/RequestProcessor.sig	

It looks like one of bad practices - 'throwing exception to implement flow control' - is used here, therefore InapplicableMethodException is thrown frequently enough to become a performance bottleneck, where expensive operation of collecting stack trace is just a 'supplementary' unused CPU load.

Looking into code (resides in separate repository - http://hg.netbeans.org/main/nb-javac)
    nb-javac\src\jdk.compiler\share\classes\com\sun\tools\javac\comp\Resolve.java

Flow-control via throwing/capturing exceptions

    Symbol selectBest(...) {
        ...
        try {
            types.noWarnings.clear();
            Type mt = rawInstantiate(env, site, sym, null, argtypes, typeargtypes,
                               allowBoxing, useVarargs, types.noWarnings);
            currentResolutionContext.addApplicableCandidate(sym, mt);
        } catch (InapplicableMethodException ex) {
            currentResolutionContext.addInapplicableCandidate(sym, ex.getDiagnostic());
            switch (bestSoFar.kind) {
                case ABSENT_MTH:
                    return new InapplicableSymbolError(currentResolutionContext);
                case WRONG_MTH:
                    bestSoFar = new InapplicableSymbolsError(currentResolutionContext);
                default:
                    return bestSoFar;
            }
        }
        if (!isAccessible(env, site, sym)) {
            return (bestSoFar.kind == ABSENT_MTH)
                ? new AccessError(env, site, sym)
                : bestSoFar;
        }
        return (bestSoFar.kind.isResolutionError() && bestSoFar.kind != AMBIGUOUS)
            ? sym
            : mostSpecific(argtypes, sym, bestSoFar, env, site, useVarargs);
    }

Implementation, whose actual behaviour contradicts provided javadoc (exception is thrown instead of returning null):

        /** Try to instantiate the type of a method so that it fits
         *  given type arguments and argument types. If successful, return
         *  the method's instantiated type, else return null.
         *  ...
         */
        Type rawInstantiate(...) throws Infer.InferenceException {
            ...

            DeferredAttr.DeferredAttrContext dc = currentResolutionContext.deferredAttrContext(m, infer.emptyContext, resultInfo, warn);
 - here --> currentResolutionContext.methodCheck.argumentsAcceptable(env, dc,
                                    argtypes, mt.getParameterTypes(), warn);
            dc.complete();
            return mt;
        }

Source of exception: 
        
    abstract class AbstractMethodCheck implements MethodCheck {
        @Override
        public void argumentsAcceptable(... List<Type> argtypes, List<Type> formals ...) {
            ...
            Type varargsFormal = useVarargs ? formals.last() : null;

            if (varargsFormal == null &&
                    argtypes.size() != formals.size()) {
                reportMC(env.tree, MethodCheckDiag.ARITY_MISMATCH, inferenceContext); // not enough args
            }
    ...
        protected void reportMC(DiagnosticPosition pos, MethodCheckDiag diag, InferenceContext inferenceContext, Object... args) {
            boolean inferDiag = inferenceContext != infer.emptyContext;
            InapplicableMethodException ex = inferDiag ?
                    infer.inferenceException : new InapplicableMethodException(diags);
            if (inferDiag && (!diag.inferKey.equals(diag.basicKey))) {
                Object[] args2 = new Object[args.length + 1];
                System.arraycopy(args, 0, args2, 1, args.length);
                args2[0] = inferenceContext.inferenceVars();
                args = args2;
            }
            String key = inferDiag ? diag.inferKey : diag.basicKey;
            throw ex.setMessage(diags.create(DiagnosticType.FRAGMENT, log.currentSource(), pos, key, args));
        }
        
Exception in that particular case was thrown for attempt to instantiate type via parameterless constructor having list of actual arguments as [java.lang.String] plus valid constructor was already found:

    findMethodInScope()
        site=org.openide.util.RequestProcessor
        name="<init>"
        argTypes=[java.lang.String]
        typeargtypes=[]
        bestSoFar = (com.sun.tools.javac.code.Symbol$MethodSymbol) RequestProcessor(java.lang.String)

I think it will not be a problem to reproduce, but just for reference - stack trace at the moment of exception is thrown

    http://hg.netbeans.org/main/nb-javac/rev/2611fd2fbbbb
    http://hg.netbeans.org/main @ 10cc566d91aa2f7f31fc5b6d3949909d25e57b83

"pool-5-thread-2"
	at com.sun.tools.javac.comp.Resolve$AbstractMethodCheck.reportMC(Resolve.java:785)
	at com.sun.tools.javac.comp.Resolve$AbstractMethodCheck.argumentsAcceptable(Resolve.java:741)
	at com.sun.tools.javac.comp.Resolve$4.argumentsAcceptable(Resolve.java:850)
	at com.sun.tools.javac.comp.Resolve.rawInstantiate(Resolve.java:590)
	at com.sun.tools.javac.comp.Resolve.selectBest(Resolve.java:1475)
	at com.sun.tools.javac.comp.Resolve.findMethodInScope(Resolve.java:1656)
	at com.sun.tools.javac.comp.Resolve.findMethod(Resolve.java:1725)
	at com.sun.tools.javac.comp.Resolve.findMethod(Resolve.java:1699)
	at com.sun.tools.javac.comp.Resolve.findConstructor(Resolve.java:2538)
	at com.sun.tools.javac.comp.Resolve$11.doLookup(Resolve.java:2507)
	at com.sun.tools.javac.comp.Resolve$BasicLookupHelper.lookup(Resolve.java:3016)
	at com.sun.tools.javac.comp.Resolve.lookupMethod(Resolve.java:3266)
	at com.sun.tools.javac.comp.Resolve.resolveConstructor(Resolve.java:2504)
	at com.sun.tools.javac.comp.Resolve.resolveConstructor(Resolve.java:2495)
	at com.sun.tools.javac.comp.Attr.visitNewClass(Attr.java:2225)
	at com.sun.tools.javac.tree.JCTree$JCNewClass.accept(JCTree.java:1659)
	at com.sun.tools.javac.comp.Attr$ResultInfo.attr(Attr.java:496)
	at com.sun.tools.javac.comp.Attr.attribTree(Attr.java:637)
	at com.sun.tools.javac.comp.Attr.attribExpr(Attr.java:676)
	at com.sun.tools.javac.comp.Attr.visitVarDef(Attr.java:1165)
	at com.sun.tools.javac.tree.JCTree$JCVariableDecl.accept(JCTree.java:926)
	at com.sun.tools.javac.comp.Attr$ResultInfo.attr(Attr.java:496)
	at com.sun.tools.javac.comp.Attr.attribTree(Attr.java:637)
	at com.sun.tools.javac.comp.Attr.attribStat(Attr.java:707)
	at com.sun.tools.javac.comp.Attr.attribClassBody(Attr.java:4688)
	at com.sun.tools.javac.comp.Attr.attribClass(Attr.java:4587)
	at com.sun.tools.javac.comp.Attr.attribClass(Attr.java:4515)
	at com.sun.tools.javac.comp.Attr.attrib(Attr.java:4490)
	at com.sun.tools.javac.main.JavaCompiler.attribute(JavaCompiler.java:1295)
	at com.sun.tools.javac.main.JavaCompiler.attribute(JavaCompiler.java:1268)
	at com.sun.tools.javac.api.JavacTaskImpl.analyze(JavacTaskImpl.java:470)
	at com.sun.tools.javac.api.JavacTaskImpl$3.call(JavacTaskImpl.java:446)
	at com.sun.tools.javac.api.JavacTaskImpl$3.call(JavacTaskImpl.java:443)
	at com.sun.tools.javac.api.JavacTaskImpl.handleExceptions(JavacTaskImpl.java:139)
	at com.sun.tools.javac.api.JavacTaskImpl.analyze(JavacTaskImpl.java:443)
	at org.netbeans.modules.java.source.parsing.JavacParser.moveToPhase(JavacParser.java:641)
	at org.netbeans.modules.java.source.parsing.CompilationInfoImpl.toPhase(CompilationInfoImpl.java:382)
	at org.netbeans.api.java.source.CompilationController.toPhase(CompilationController.java:109)
	at org.netbeans.api.java.source.ui.ElementOpen$4.run(ElementOpen.java:305)
	at org.netbeans.api.java.source.ui.ElementOpen$4.run(ElementOpen.java:299)
	at org.netbeans.api.java.source.JavaSource$MultiTask.run(JavaSource.java:486)
	at org.netbeans.modules.parsing.impl.TaskProcessor.callUserTask(TaskProcessor.java:609)
	at org.netbeans.modules.parsing.api.ParserManager$UserTaskAction.run(ParserManager.java:153)
	at org.netbeans.modules.parsing.api.ParserManager$UserTaskAction.run(ParserManager.java:137)
	at org.netbeans.modules.parsing.impl.TaskProcessor$2.call(TaskProcessor.java:204)
	at org.netbeans.modules.parsing.impl.TaskProcessor$2.call(TaskProcessor.java:201)
	at org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager.priorityIO(FileChangedManager.java:176)
	at org.netbeans.modules.masterfs.providers.ProvidedExtensions.priorityIO(ProvidedExtensions.java:360)
	at org.netbeans.modules.parsing.nb.DataObjectEnvFactory.runPriorityIO(DataObjectEnvFactory.java:141)
	at org.netbeans.modules.parsing.impl.Utilities.runPriorityIO(Utilities.java:88)
	at org.netbeans.modules.parsing.impl.TaskProcessor.runUserTask(TaskProcessor.java:201)
	at org.netbeans.modules.parsing.api.ParserManager.parse(ParserManager.java:104)
	at org.netbeans.api.java.source.JavaSource.runUserActionTaskImpl(JavaSource.java:436)
	at org.netbeans.api.java.source.JavaSource.runUserActionTask(JavaSource.java:407)
	at org.netbeans.api.java.source.ui.ElementOpen.getOffset(ElementOpen.java:345)
	at org.netbeans.api.java.source.ui.ElementOpen.getOpenInfo(ElementOpen.java:245)
	at org.netbeans.api.java.source.ui.ElementOpen.getOpenInfo(ElementOpen.java:238)
	at org.netbeans.api.java.source.ui.ElementOpen.open(ElementOpen.java:116)
	at org.netbeans.api.java.source.ui.ElementOpen.open(ElementOpen.java:111)
	at org.netbeans.api.java.source.ui.ElementOpen.open(ElementOpen.java:143)
	at org.netbeans.modules.profiler.nbimpl.providers.GoToJavaSourceProvider$GotoSourceRunnable$1.run(GoToJavaSourceProvider.java:126)
	at org.netbeans.modules.profiler.nbimpl.providers.GoToJavaSourceProvider$GotoSourceRunnable$1.run(GoToJavaSourceProvider.java:116)
	at org.netbeans.api.java.source.JavaSource$MultiTask.run(JavaSource.java:486)
	at org.netbeans.modules.parsing.impl.TaskProcessor.callUserTask(TaskProcessor.java:609)
	at org.netbeans.modules.parsing.api.ParserManager$UserTaskAction.run(ParserManager.java:153)
	at org.netbeans.modules.parsing.api.ParserManager$UserTaskAction.run(ParserManager.java:137)
	at org.netbeans.modules.parsing.impl.TaskProcessor$2.call(TaskProcessor.java:204)
	at org.netbeans.modules.parsing.impl.TaskProcessor$2.call(TaskProcessor.java:201)
	at org.netbeans.modules.masterfs.filebasedfs.utils.FileChangedManager.priorityIO(FileChangedManager.java:176)
	at org.netbeans.modules.masterfs.providers.ProvidedExtensions.priorityIO(ProvidedExtensions.java:360)
	at org.netbeans.modules.parsing.nb.DataObjectEnvFactory.runPriorityIO(DataObjectEnvFactory.java:141)
	at org.netbeans.modules.parsing.impl.Utilities.runPriorityIO(Utilities.java:88)
	at org.netbeans.modules.parsing.impl.TaskProcessor.runUserTask(TaskProcessor.java:201)
	at org.netbeans.modules.parsing.api.ParserManager.parse(ParserManager.java:104)
	at org.netbeans.api.java.source.JavaSource.runUserActionTaskImpl(JavaSource.java:436)
	at org.netbeans.api.java.source.JavaSource.runUserActionTask(JavaSource.java:407)
	at org.netbeans.modules.profiler.nbimpl.javac.ParsingUtils.invokeScanSensitiveTask(ParsingUtils.java:70)
	at org.netbeans.modules.profiler.nbimpl.providers.GoToJavaSourceProvider$GotoSourceRunnable.run(GoToJavaSourceProvider.java:151)
	at org.netbeans.modules.profiler.nbimpl.providers.GoToJavaSourceProvider$1.doInBackground(GoToJavaSourceProvider.java:186)
	at org.netbeans.lib.profiler.ui.SwingWorker$2.run(SwingWorker.java:159)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:745)
Comment 1 NukemBy 2016-10-02 18:37:41 UTC
Small addendum - provided stack trace actually occurs during attempt to open Source from self profiler via context menu (takes 10-15 seconds to execute), that happened while I've clicked action in self-profile report for bg-scan. Most probably that same root cause is reason for slowness in both cases.