Uploaded image for project: 'TinkerPop'
  1. TinkerPop
  2. TINKERPOP-2588

Opening a new session is extremely slow

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Not A Bug
    • 3.4.11
    • None
    • groovy, server
    • None

    Description

      When moving from sessionless mode to using sessions in requests (example request):

       

      {"requestId":"02a58ee3-e4d3-11eb-bd29-04d4c4eaf347","op":"eval","processor":"session","args":{"bindings":{},"evaluationTimeout":120000,"gremlin":"g.V().limit(1).id()","language":"gremlin-groovy","rebindings":{},"session":"50052633-079b-4500-bc29-a3eacb1f0dba"}}
      

      It doesn't really matter what the query is, the first query, which opens the session and transaction is extremely slow (~1.2s).

      From the stack trace this seems to be related to groovy script initialization:

      "gremlin-server-worker-1" #93 prio=5 os_prio=0 tid=0x00007fe5f0006800 nid=0x179 runnable [0x00007fe6059f3000]
         java.lang.Thread.State: RUNNABLE
      	at java.util.zip.ZipFile.freeEntry(Native Method)
      	at java.util.zip.ZipFile.access$1000(ZipFile.java:60)
      	at java.util.zip.ZipFile$ZipEntryIterator.next(ZipFile.java:540)
      	- locked <0x00000006c02394e0> (a java.util.jar.JarFile)
      	at java.util.zip.ZipFile$ZipEntryIterator.nextElement(ZipFile.java:514)
      	at java.util.zip.ZipFile$ZipEntryIterator.nextElement(ZipFile.java:495)
      	at java.util.jar.JarFile$JarEntryIterator.next(JarFile.java:257)
      	at java.util.jar.JarFile$JarEntryIterator.nextElement(JarFile.java:266)
      	at java.util.jar.JarFile$JarEntryIterator.nextElement(JarFile.java:247)
      	at sun.misc.URLClassPath$JarLoader.validIndex(URLClassPath.java:1017)
      	at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:1150)
      	at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:1062)
      	at sun.misc.URLClassPath.getResource(URLClassPath.java:249)
      	at java.net.URLClassLoader$1.run(URLClassLoader.java:366)
      	at java.net.URLClassLoader$1.run(URLClassLoader.java:363)
      	at java.security.AccessController.doPrivileged(Native Method)
      	at java.net.URLClassLoader.findClass(URLClassLoader.java:362)
      	at java.lang.ClassLoader.loadClass(ClassLoader.java:418)
      	- locked <0x00000006c1ee5c20> (a java.lang.Object)
      	at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:352)
      	at java.lang.ClassLoader.loadClass(ClassLoader.java:405)
      	- locked <0x00000007aca0a140> (a org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyClassLoader)
      	at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:762)
      	at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:637)
      	at org.codehaus.groovy.control.ClassNodeResolver.findByClassLoading(ClassNodeResolver.java:209)
      	at org.codehaus.groovy.control.ClassNodeResolver.tryAsLoaderClassOrScript(ClassNodeResolver.java:198)
      	at org.codehaus.groovy.control.ClassNodeResolver.findClassNode(ClassNodeResolver.java:169)
      	at org.codehaus.groovy.control.ClassNodeResolver.resolveName(ClassNodeResolver.java:125)
      	at org.codehaus.groovy.control.ResolveVisitor.resolveToOuter(ResolveVisitor.java:856)
      	at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:467)
      	at org.codehaus.groovy.control.ResolveVisitor.resolveFromStaticInnerClasses(ResolveVisitor.java:570)
      	at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:466)
      	at org.codehaus.groovy.control.ResolveVisitor.resolveFromStaticInnerClasses(ResolveVisitor.java:570)
      	at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:466)
      	at org.codehaus.groovy.control.ResolveVisitor.resolveFromStaticInnerClasses(ResolveVisitor.java:570)
      	at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:466)
      	at org.codehaus.groovy.control.ResolveVisitor.resolveFromStaticInnerClasses(ResolveVisitor.java:570)
      	at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:466)
      	at org.codehaus.groovy.control.ResolveVisitor.visitClass(ResolveVisitor.java:1421)
      	at org.codehaus.groovy.control.ResolveVisitor.startResolving(ResolveVisitor.java:230)
      	at org.codehaus.groovy.control.CompilationUnit$13.call(CompilationUnit.java:705)
      	at org.codehaus.groovy.control.CompilationUnit.applyToSourceUnits(CompilationUnit.java:965)
      	at org.codehaus.groovy.control.CompilationUnit.doPhaseOperation(CompilationUnit.java:647)
      	at org.codehaus.groovy.control.CompilationUnit.compile(CompilationUnit.java:596)
      	at groovy.lang.GroovyClassLoader.doParseClass(GroovyClassLoader.java:390)
      	at groovy.lang.GroovyClassLoader.access$300(GroovyClassLoader.java:89)
      	at groovy.lang.GroovyClassLoader$5.provide(GroovyClassLoader.java:330)
      	at groovy.lang.GroovyClassLoader$5.provide(GroovyClassLoader.java:327)
      	at org.codehaus.groovy.runtime.memoize.ConcurrentCommonCache.getAndPut(ConcurrentCommonCache.java:147)
      	at groovy.lang.GroovyClassLoader.parseClass(GroovyClassLoader.java:325)
      	at groovy.lang.GroovyClassLoader.parseClass(GroovyClassLoader.java:309)
      	at groovy.lang.GroovyClassLoader.parseClass(GroovyClassLoader.java:251)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine$GroovyCacheLoader.lambda$load$0(GremlinGroovyScriptEngine.java:819)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine$GroovyCacheLoader$$Lambda$205/522819391.get(Unknown Source)
      	at java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1604)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine$GroovyCacheLoader$$Lambda$206/2128176660.execute(Unknown Source)
      	at java.util.concurrent.CompletableFuture.asyncSupplyStage(CompletableFuture.java:1618)
      	at java.util.concurrent.CompletableFuture.supplyAsync(CompletableFuture.java:1843)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine$GroovyCacheLoader.load(GremlinGroovyScriptEngine.java:817)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine$GroovyCacheLoader.load(GremlinGroovyScriptEngine.java:812)
      	at com.github.benmanes.caffeine.cache.BoundedLocalCache$BoundedLocalLoadingCache.lambda$new$0(BoundedLocalCache.java:3117)
      	at com.github.benmanes.caffeine.cache.BoundedLocalCache$BoundedLocalLoadingCache$$Lambda$172/669669646.apply(Unknown Source)
      	at com.github.benmanes.caffeine.cache.LocalCache.lambda$statsAware$0(LocalCache.java:144)
      	at com.github.benmanes.caffeine.cache.LocalCache$$Lambda$203/911906439.apply(Unknown Source)
      	at com.github.benmanes.caffeine.cache.BoundedLocalCache.lambda$doComputeIfAbsent$16(BoundedLocalCache.java:1968)
      	at com.github.benmanes.caffeine.cache.BoundedLocalCache$$Lambda$204/1935679399.apply(Unknown Source)
      	at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853)
      	- locked <0x00000007aca0a8b8> (a java.util.concurrent.ConcurrentHashMap$ReservationNode)
      	at com.github.benmanes.caffeine.cache.BoundedLocalCache.doComputeIfAbsent(BoundedLocalCache.java:1966)
      	at com.github.benmanes.caffeine.cache.BoundedLocalCache.computeIfAbsent(BoundedLocalCache.java:1949)
      	at com.github.benmanes.caffeine.cache.LocalCache.computeIfAbsent(LocalCache.java:113)
      	at com.github.benmanes.caffeine.cache.LocalLoadingCache.get(LocalLoadingCache.java:67)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine.getScriptClass(GremlinGroovyScriptEngine.java:567)
      	at org.apache.tinkerpop.gremlin.groovy.jsr223.GremlinGroovyScriptEngine.eval(GremlinGroovyScriptEngine.java:374)
      	at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
      	at org.apache.tinkerpop.gremlin.jsr223.DefaultGremlinScriptEngineManager.lambda$createGremlinScriptEngine$16(DefaultGremlinScriptEngineManager.java:460)
      	at org.apache.tinkerpop.gremlin.jsr223.DefaultGremlinScriptEngineManager$$Lambda$202/1673908654.accept(Unknown Source)
      	at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
      	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
      	at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1384)
      	at java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:647)
      	at java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:272)
      	at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1384)
      	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
      	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:472)
      	at java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:150)
      	at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:173)
      	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
      	at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
      	at org.apache.tinkerpop.gremlin.jsr223.DefaultGremlinScriptEngineManager.createGremlinScriptEngine(DefaultGremlinScriptEngineManager.java:450)
      	at org.apache.tinkerpop.gremlin.jsr223.DefaultGremlinScriptEngineManager.getEngineByName(DefaultGremlinScriptEngineManager.java:219)
      	at org.apache.tinkerpop.gremlin.jsr223.CachedGremlinScriptEngineManager.lambda$getEngineByName$0(CachedGremlinScriptEngineManager.java:57)
      	at org.apache.tinkerpop.gremlin.jsr223.CachedGremlinScriptEngineManager$$Lambda$144/332268337.apply(Unknown Source)
      	at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1660)
      	- locked <0x00000007aca0abf8> (a java.util.concurrent.ConcurrentHashMap$ReservationNode)
      	at org.apache.tinkerpop.gremlin.jsr223.CachedGremlinScriptEngineManager.getEngineByName(CachedGremlinScriptEngineManager.java:57)
      	at org.apache.tinkerpop.gremlin.server.op.session.Session.registerMetrics(Session.java:258)
      	at org.apache.tinkerpop.gremlin.server.op.session.Session$$Lambda$295/1510600006.accept(Unknown Source)
      	at java.util.LinkedHashMap$LinkedKeySet.forEach(LinkedHashMap.java:559)
      	at org.apache.tinkerpop.gremlin.server.op.session.Session.<init>(Session.java:113)
      	at org.apache.tinkerpop.gremlin.server.op.session.SessionOpProcessor.lambda$getSession$2(SessionOpProcessor.java:208)
      	at org.apache.tinkerpop.gremlin.server.op.session.SessionOpProcessor$$Lambda$291/934345685.apply(Unknown Source)
      	at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1660)
      	- locked <0x00000007aca0ad00> (a java.util.concurrent.ConcurrentHashMap$ReservationNode)
      	at org.apache.tinkerpop.gremlin.server.op.session.SessionOpProcessor.getSession(SessionOpProcessor.java:208)
      	at org.apache.tinkerpop.gremlin.server.op.session.SessionOpProcessor.evalOp(SessionOpProcessor.java:179)
      	at org.apache.tinkerpop.gremlin.server.op.session.SessionOpProcessor$$Lambda$290/1574293989.accept(Unknown Source)
      	at org.apache.tinkerpop.gremlin.server.handler.OpExecutorHandler.channelRead0(OpExecutorHandler.java:67)
      	at org.apache.tinkerpop.gremlin.server.handler.OpExecutorHandler.channelRead0(OpExecutorHandler.java:43)
      	at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:99)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
      	at io.netty.handler.codec.http.websocketx.Utf8FrameValidator.channelRead(Utf8FrameValidator.java:82)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.http.websocketx.WebSocketServerProtocolHandler$1.channelRead(WebSocketServerProtocolHandler.java:283)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:321)
      	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:295)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
      	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
      	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
      	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
      	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
      	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
      	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
      	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
      	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
      	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
      	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
      	at java.lang.Thread.run(Thread.java:748)
      

      Following requests, with the same session id are significantly faster.

      This basically renders session to be unusable, unless you are trying to perform very long-running sessions. 

       

      Attachments

        Activity

          People

            Unassigned Unassigned
            mamoos1 Roy Reznik
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: