search

clojure-emacs / orchard

A fertile ground for Clojure tooling
Eclipse Public License 1.0
323 stars 54 forks source link

`parser_utils/parse_java` taking a long time. #240

Closed FiV0 closed 2 months ago

FiV0 commented 2 months ago

I am seeing that some thread is taking a lot of time at orchard.java.parser_utils$parse_java.invokeStatic(parser_utils.clj:47). I don't know exactly what triggers it, but the stacktrace goes through some nrepl.middleware. I am doing profiling and the stacktrace (included at the bottom) is making up over 50% of my profiles which seems quite off. We have a bit of a weird setup with gradle and clojurephant which you can find here. This doesn't seem to happen every time I jack in, but more sporadically. Let know if I can provide more information to debug this.

Environment & Version information

Clojure version

implementation("org.clojure", "clojure", "1.11.1") and nrepl("cider", "cider-nrepl", "0.46.0")

Java version

openjdk 21.0.2 2024-01-16
OpenJDK Runtime Environment (build 21.0.2+13)
OpenJDK 64-Bit Server VM (build 21.0.2+13, mixed mode, sharing)

Operating system

Operating System: Manjaro Linux                     
Kernel: Linux 6.6.24-1-MANJARO

Stacktrace

    at com.sun.tools.javac.code.ClassFinder.fillIn(jdk.compiler@21.0.2/ClassFinder.java:402)
    at com.sun.tools.javac.code.ClassFinder.complete(jdk.compiler@21.0.2/ClassFinder.java:302)
    at com.sun.tools.javac.code.ClassFinder$$Lambda/0x0000000801897030.complete(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.code.Symbol.complete(jdk.compiler@21.0.2/Symbol.java:682)
    at com.sun.tools.javac.code.Symbol$ClassSymbol.complete(jdk.compiler@21.0.2/Symbol.java:1418)
    at com.sun.tools.javac.code.ClassFinder.loadClass(jdk.compiler@21.0.2/ClassFinder.java:446)
    at com.sun.tools.javac.comp.Resolve.loadClass(jdk.compiler@21.0.2/Resolve.java:2068)
    at com.sun.tools.javac.comp.Resolve.findIdentInPackageInternal(jdk.compiler@21.0.2/Resolve.java:2465)
    at com.sun.tools.javac.comp.Resolve.findIdentInPackage(jdk.compiler@21.0.2/Resolve.java:2453)
    at com.sun.tools.javac.comp.Attr.selectSym(jdk.compiler@21.0.2/Attr.java:4547)
    at com.sun.tools.javac.comp.Attr.visitSelect(jdk.compiler@21.0.2/Attr.java:4435)
    at com.sun.tools.javac.tree.JCTree$JCFieldAccess.accept(jdk.compiler@21.0.2/JCTree.java:2581)
    at com.sun.tools.javac.comp.Attr.attribTree(jdk.compiler@21.0.2/Attr.java:662)
    at com.sun.tools.javac.comp.Attr.visitSelect(jdk.compiler@21.0.2/Attr.java:4400)
    at com.sun.tools.javac.tree.JCTree$JCFieldAccess.accept(jdk.compiler@21.0.2/JCTree.java:2581)
    at com.sun.tools.javac.comp.Attr.attribTree(jdk.compiler@21.0.2/Attr.java:662)
    at com.sun.tools.javac.comp.Attr.visitSelect(jdk.compiler@21.0.2/Attr.java:4400)
    at com.sun.tools.javac.tree.JCTree$JCFieldAccess.accept(jdk.compiler@21.0.2/JCTree.java:2581)
    at com.sun.tools.javac.comp.Attr.attribTree(jdk.compiler@21.0.2/Attr.java:662)
    at com.sun.tools.javac.comp.Attr.attribImportQualifier(jdk.compiler@21.0.2/Attr.java:396)
    at com.sun.tools.javac.comp.TypeEnter$ImportsPhase.doImport(jdk.compiler@21.0.2/TypeEnter.java:449)
    at com.sun.tools.javac.comp.TypeEnter$ImportsPhase.resolveImports(jdk.compiler@21.0.2/TypeEnter.java:398)
    at com.sun.tools.javac.comp.TypeEnter$ImportsPhase.runPhase(jdk.compiler@21.0.2/TypeEnter.java:324)
    at com.sun.tools.javac.comp.TypeEnter$Phase.doCompleteEnvs(jdk.compiler@21.0.2/TypeEnter.java:285)
    at com.sun.tools.javac.comp.TypeEnter$Phase.completeEnvs(jdk.compiler@21.0.2/TypeEnter.java:254)
    at com.sun.tools.javac.comp.TypeEnter.complete(jdk.compiler@21.0.2/TypeEnter.java:201)
    at com.sun.tools.javac.code.Symbol.complete(jdk.compiler@21.0.2/Symbol.java:682)
    at com.sun.tools.javac.code.Symbol$ClassSymbol.complete(jdk.compiler@21.0.2/Symbol.java:1418)
    at com.sun.tools.javac.comp.Enter.complete(jdk.compiler@21.0.2/Enter.java:615)
    at com.sun.tools.javac.main.JavaCompiler.readSourceFile(jdk.compiler@21.0.2/JavaCompiler.java:853)
    at com.sun.tools.javac.main.JavaCompiler.readSourceFile(jdk.compiler@21.0.2/JavaCompiler.java:810)
    at com.sun.tools.javac.main.JavaCompiler.lambda$new$0(jdk.compiler@21.0.2/JavaCompiler.java:357)
    at com.sun.tools.javac.main.JavaCompiler$$Lambda/0x0000000801895568.complete(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.code.ClassFinder.fillIn(jdk.compiler@21.0.2/ClassFinder.java:377)
    at com.sun.tools.javac.code.ClassFinder.complete(jdk.compiler@21.0.2/ClassFinder.java:302)
    at com.sun.tools.javac.code.ClassFinder$$Lambda/0x0000000801897030.complete(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.code.Symbol.complete(jdk.compiler@21.0.2/Symbol.java:682)
    at com.sun.tools.javac.code.Symbol$ClassSymbol.complete(jdk.compiler@21.0.2/Symbol.java:1418)
    at com.sun.tools.javac.code.Symbol$ClassSymbol.flags(jdk.compiler@21.0.2/Symbol.java:1334)
    at com.sun.tools.javac.comp.Check.importAccessible(jdk.compiler@21.0.2/Check.java:4330)
    at com.sun.tools.javac.comp.TypeEnter$ImportsPhase.lambda$resolveImports$2(jdk.compiler@21.0.2/TypeEnter.java:386)
    at com.sun.tools.javac.comp.TypeEnter$ImportsPhase$$Lambda/0x00000008019a6fa8.accepts(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.code.Scope$FilterImportScope.lambda$getSymbolsByName$2(jdk.compiler@21.0.2/Scope.java:973)
    at com.sun.tools.javac.code.Scope$FilterImportScope$$Lambda/0x00000008019adcd8.test(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.util.Iterators$1.update(jdk.compiler@21.0.2/Iterators.java:100)
    at com.sun.tools.javac.util.Iterators$1.<init>(jdk.compiler@21.0.2/Iterators.java:96)
    at com.sun.tools.javac.util.Iterators.createFilterIterator(jdk.compiler@21.0.2/Iterators.java:95)
    at com.sun.tools.javac.code.Scope$FilterImportScope.lambda$getSymbolsByName$3(jdk.compiler@21.0.2/Scope.java:971)
    at com.sun.tools.javac.code.Scope$FilterImportScope$$Lambda/0x00000008019ad860.iterator(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.code.Scope$CompoundScope.lambda$getSymbolsByName$2(jdk.compiler@21.0.2/Scope.java:1098)
    at com.sun.tools.javac.code.Scope$CompoundScope$$Lambda/0x00000008019ad3c8.apply(jdk.compiler@21.0.2/Unknown Source)
    at com.sun.tools.javac.util.Iterators$CompoundIterator.hasNext(jdk.compiler@21.0.2/Iterators.java:75)
    at com.sun.tools.javac.comp.Resolve.findGlobalType(jdk.compiler@21.0.2/Resolve.java:2314)
    at com.sun.tools.javac.comp.Resolve.findType(jdk.compiler@21.0.2/Resolve.java:2401)
    at com.sun.tools.javac.comp.Resolve.findIdentInternal(jdk.compiler@21.0.2/Resolve.java:2432)
    at com.sun.tools.javac.comp.Resolve.findIdent(jdk.compiler@21.0.2/Resolve.java:2418)
    at com.sun.tools.javac.comp.Resolve.resolveIdent(jdk.compiler@21.0.2/Resolve.java:2710)
    at com.sun.tools.javac.comp.Attr.visitIdent(jdk.compiler@21.0.2/Attr.java:4323)
    at com.sun.tools.javac.tree.JCTree$JCIdent.accept(jdk.compiler@21.0.2/JCTree.java:2715)
    at com.sun.tools.javac.comp.Attr.attribTree(jdk.compiler@21.0.2/Attr.java:662)
    at com.sun.tools.javac.comp.Attr.attribType(jdk.compiler@21.0.2/Attr.java:728)
    at com.sun.tools.javac.comp.Attr.attribType(jdk.compiler@21.0.2/Attr.java:721)
    at com.sun.tools.javac.comp.MemberEnter.visitVarDef(jdk.compiler@21.0.2/MemberEnter.java:272)
    at jdk.javadoc.internal.tool.JavadocMemberEnter.visitVarDef(jdk.javadoc@21.0.2/JavadocMemberEnter.java:99)
    at com.sun.tools.javac.tree.JCTree$JCVariableDecl.accept(jdk.compiler@21.0.2/JCTree.java:1022)
    at com.sun.tools.javac.comp.MemberEnter.memberEnter(jdk.compiler@21.0.2/MemberEnter.java:170)
    at com.sun.tools.javac.comp.MemberEnter.signature(jdk.compiler@21.0.2/MemberEnter.java:118)
    at com.sun.tools.javac.comp.MemberEnter.visitMethodDef(jdk.compiler@21.0.2/MemberEnter.java:200)
    at jdk.javadoc.internal.tool.JavadocMemberEnter.visitMethodDef(jdk.javadoc@21.0.2/JavadocMemberEnter.java:67)
    at com.sun.tools.javac.tree.JCTree$JCMethodDecl.accept(jdk.compiler@21.0.2/JCTree.java:916)
    at com.sun.tools.javac.comp.MemberEnter.memberEnter(jdk.compiler@21.0.2/MemberEnter.java:170)
    at com.sun.tools.javac.comp.MemberEnter.memberEnter(jdk.compiler@21.0.2/MemberEnter.java:182)
    at com.sun.tools.javac.comp.TypeEnter$MembersPhase.finishClass(jdk.compiler@21.0.2/TypeEnter.java:1135)
    at com.sun.tools.javac.comp.TypeEnter$MembersPhase.runPhase(jdk.compiler@21.0.2/TypeEnter.java:1081)
    at com.sun.tools.javac.comp.TypeEnter$Phase.doCompleteEnvs(jdk.compiler@21.0.2/TypeEnter.java:285)
    at com.sun.tools.javac.comp.TypeEnter$AbstractMembersPhase.doCompleteEnvs(jdk.compiler@21.0.2/TypeEnter.java:962)
    at com.sun.tools.javac.comp.TypeEnter$Phase.completeEnvs(jdk.compiler@21.0.2/TypeEnter.java:254)
    at com.sun.tools.javac.comp.TypeEnter$Phase.completeEnvs(jdk.compiler@21.0.2/TypeEnter.java:269)
    at com.sun.tools.javac.comp.TypeEnter$Phase.completeEnvs(jdk.compiler@21.0.2/TypeEnter.java:269)
    at com.sun.tools.javac.comp.TypeEnter$Phase.completeEnvs(jdk.compiler@21.0.2/TypeEnter.java:269)
    at com.sun.tools.javac.comp.TypeEnter$Phase.completeEnvs(jdk.compiler@21.0.2/TypeEnter.java:269)
    at com.sun.tools.javac.comp.TypeEnter.complete(jdk.compiler@21.0.2/TypeEnter.java:201)
    at com.sun.tools.javac.code.Symbol.complete(jdk.compiler@21.0.2/Symbol.java:682)
    at com.sun.tools.javac.code.Symbol$ClassSymbol.complete(jdk.compiler@21.0.2/Symbol.java:1418)
    at com.sun.tools.javac.comp.Enter.complete(jdk.compiler@21.0.2/Enter.java:615)
    at com.sun.tools.javac.comp.Enter.main(jdk.compiler@21.0.2/Enter.java:592)
    at jdk.javadoc.internal.tool.JavadocEnter.main(jdk.javadoc@21.0.2/JavadocEnter.java:72)
    at jdk.javadoc.internal.tool.JavadocTool.getEnvironment(jdk.javadoc@21.0.2/JavadocTool.java:206)
    at jdk.javadoc.internal.tool.Start.parseAndExecute(jdk.javadoc@21.0.2/Start.java:565)
    at jdk.javadoc.internal.tool.Start.begin(jdk.javadoc@21.0.2/Start.java:398)
    at jdk.javadoc.internal.tool.Start.begin(jdk.javadoc@21.0.2/Start.java:360)
    at jdk.javadoc.internal.api.JavadocTaskImpl.call(jdk.javadoc@21.0.2/JavadocTaskImpl.java:99)
    at orchard.java.parser_utils$parse_java.invokeStatic(parser_utils.clj:47)
    at orchard.java.parser_utils$parse_java.invoke(parser_utils.clj:16)
    at orchard.java.parser$source_info.invokeStatic(parser.clj:230)
    - locked <0x000000060f2cd060> (a java.lang.Object)
    at orchard.java.parser$source_info.invoke(parser.clj:220)
    at clojure.lang.AFn.applyToHelper(AFn.java:154)
    at clojure.lang.AFn.applyTo(AFn.java:144)
    at clojure.lang.Var.applyTo(Var.java:707)
    at clojure.core$apply.invokeStatic(core.clj:667)
    at clojure.core$apply.invoke(core.clj:662)
    at orchard.java$source_info_STAR_.invokeStatic(java.clj:124)
    at orchard.java$source_info_STAR_.doInvoke(java.clj:101)
    at clojure.lang.RestFn.invoke(RestFn.java:411)
    at orchard.java$source_info.invokeStatic(java.clj:139)
    at orchard.java$source_info.invoke(java.clj:135)
    at orchard.java$class_info_STAR_.invokeStatic(java.clj:331)
    at orchard.java$class_info_STAR_.invoke(java.clj:321)
    at orchard.java$class_info.invokeStatic(java.clj:376)
    at orchard.java$class_info.invoke(java.clj:368)
    at orchard.java$member_info$fn__8755.invoke(java.clj:427)
    at orchard.java$member_info.invokeStatic(java.clj:426)
    at orchard.java$member_info.invoke(java.clj:416)
    at orchard.java$resolve_member$fn__8766.invoke(java.clj:477)
    at clojure.core$map$fn__5949.invoke(core.clj:2772)
    at clojure.lang.LazySeq.sval(LazySeq.java:44)
    - eliminated <0x0000000633a00ae8> (a clojure.lang.LazySeq)
    at clojure.lang.LazySeq.seq(LazySeq.java:53)
    - locked <0x0000000633a00ae8> (a clojure.lang.LazySeq)
    at clojure.lang.RT.seq(RT.java:535)
    at clojure.core$seq__5481.invokeStatic(core.clj:139)
    at clojure.core$filter$fn__5976.invoke(core.clj:2826)
    at clojure.lang.LazySeq.sval(LazySeq.java:44)
    - locked <0x00000006334003e8> (a clojure.lang.LazySeq)
    at clojure.lang.LazySeq.seq(LazySeq.java:60)
    - locked <0x000000061353c0d0> (a clojure.lang.LazySeq)
    at clojure.lang.RT.seq(RT.java:535)
    at clojure.lang.RT.nthFrom(RT.java:982)
    at clojure.lang.RT.nth(RT.java:940)
    at clojure.core$distinct$step__6497$fn__6498$fn__6500.invoke(core.clj:5079)
    at clojure.core$distinct$step__6497$fn__6498.invoke(core.clj:5079)
    at clojure.lang.LazySeq.sval(LazySeq.java:44)
    - eliminated <0x000000061353c108> (a clojure.lang.LazySeq)
    at clojure.lang.LazySeq.seq(LazySeq.java:53)
    - locked <0x000000061353c108> (a clojure.lang.LazySeq)
    at clojure.lang.RT.seq(RT.java:535)
    at clojure.core$seq__5481.invokeStatic(core.clj:139)
    at clojure.core$seq__5481.invoke(core.clj:139)
    at orchard.java$resolve_symbol.invokeStatic(java.clj:502)
    at orchard.java$resolve_symbol.invoke(java.clj:485)
    at orchard.info$clj_meta.invokeStatic(info.clj:78)
    at orchard.info$clj_meta.invoke(info.clj:64)
    at orchard.info$info_STAR_.invokeStatic(info.clj:163)
    at orchard.info$info_STAR_.invoke(info.clj:148)
    at cider.nrepl.middleware.info$info.invokeStatic(info.clj:122)
    at cider.nrepl.middleware.info$info.invoke(info.clj:81)
    at cider.nrepl.middleware.info$eldoc_reply.invokeStatic(info.clj:133)
    at cider.nrepl.middleware.info$eldoc_reply.invoke(info.clj:131)
    at cider.nrepl.middleware.util.error_handling$eval10763$fn__10764.invoke(error_handling.clj:160)
    at clojure.lang.MultiFn.invoke(MultiFn.java:234)
    at cider.nrepl.middleware.info$handle_info.invokeStatic(info.clj:147)
    at cider.nrepl.middleware.info$handle_info.invoke(info.clj:146)
    at clojure.lang.Var.invoke(Var.java:390)
    at cider.nrepl$wrap_info$fn__10385.invoke(nrepl.clj:287)
    at nrepl.middleware$wrap_conj_descriptor$fn__5425.invoke(middleware.clj:16)
    at nrepl.middleware.completion$wrap_completion$fn__6271.invoke(completion.clj:58)
    at nrepl.middleware$wrap_conj_descriptor$fn__5425.invoke(middleware.clj:16)
    at cider.nrepl$wrap_apropos$fn__10335.invoke(nrepl.clj:187)
    at nrepl.middleware$wrap_conj_descriptor$fn__5425.invoke(middleware.clj:16)
    at cider.nrepl$wrap_log$fn__10403.invoke(nrepl.clj:387)
    at nrepl.middleware$wrap_conj_descriptor$fn__5425.invoke(middleware.clj:16)
    at nrepl.middleware.print$wrap_print$fn__5661.invoke(print.clj:234)
    at nrepl.middleware$wrap_conj_descriptor$fn__5425.invoke(middleware.clj:16)
    at nrepl.middleware.session$session$fn__5864.invoke(session.clj:325)
    at nrepl.middleware$wrap_conj_descriptor$fn__5425.invoke(middleware.clj:16)
    at nrepl.server$default_handler$fn__6432.invoke(server.clj:141)
    at nrepl.server$handle_STAR_.invokeStatic(server.clj:24)
    at nrepl.server$handle_STAR_.invoke(server.clj:21)
    at nrepl.server$handle$fn__6400.invoke(server.clj:41)
    at clojure.core$binding_conveyor_fn$fn__5837.invoke(core.clj:2047)
    at clojure.lang.AFn.call(AFn.java:18)
    at java.util.concurrent.FutureTask.run(java.base@21.0.2/FutureTask.java:317)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21.0.2/ThreadPoolExecutor.java:1144)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@21.0.2/ThreadPoolExecutor.java:642)
    at java.lang.Thread.runWith(java.base@21.0.2/Thread.java:1596)
    at java.lang.Thread.run(java.base@21.0.2/Thread.java:1583)
vemv commented 2 months ago

Hi @FiV0, that part of the JDK that we're using is slow.

I plan to replace it with https://github.com/clojure-emacs/orchard/issues/211 over the next couple months.

Normally what's happening in your machine is that some caches are warming up. Once that is done, it should get back to normal.

Cheers - V

FiV0 commented 2 months ago

Normally what's happening in your machine is that some caches are warming up. Once that is done, it should get back to normal.

I see this behaviour not over a couple of seconds or minutes, but longer periods. You still think this is some cache warming up?

vemv commented 2 months ago

Yes

If you are using enrich-classpath, you can disable it for preventing Orchard from having access to the things that are necessary for cache building.

That also can be done in a per-project manner with .dir-locals.el

vemv commented 2 months ago

Feel free to continue the conversation.