Velocity
  1. Velocity
  2. VELOCITY-562

Hanging in jj_scan_token (while holding lock for getResouce)

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Cannot Reproduce
    • Affects Version/s: 1.5
    • Fix Version/s: None
    • Component/s: None
    • Labels:
      None
    • Environment:
      Integreated in Tomcat on Ubuntu Linux
      JDK version: 1.5.0_08-b03

      Description

      We are having trouble with deadlocks in Velocity after updating from 1.3 to 1.5

      The thread holding the lock allways it at org.apache.velocity.runtime.parser.Parser.jj_scan_token(Parser.java:3259)
      although the frames below that differ between restarts. It is not possible to use Eclipse to step over that line. It simply hangs.

      3259 is this line: "if (jj_la == 0 && jj_scanpos == jj_lastpos) throw jj_ls;"

      Here is an example stacktrace:

      Full thread dump Java HotSpot(TM) Client VM (1.5.0_08-b03 mixed mode):

      "DataExchange" daemon prio=1 tid=0x08b2df10 nid=0x2824 waiting for monitor entry [0x8545a000..0x8545b130]
      at org.apache.velocity.runtime.resource.ResourceManagerImpl.getResource(ResourceManagerImpl.java:287)

      • waiting to lock <0x91140270> (a org.apache.velocity.runtime.resource.ResourceManagerImpl)
        at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:1102)
        at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:1077)
        at org.apache.velocity.runtime.RuntimeSingleton.getTemplate(RuntimeSingleton.java:303)
        at org.apache.velocity.app.Velocity.getTemplate(Velocity.java:503)
        at de.his.servlet.util.ServletUtil.parseWithVelocity(ServletUtil.java:735)
        [...]

      "http-8080-Processor23" daemon prio=1 tid=0x08220cc8 nid=0x2803 runnable [0x858e2000..0x858e3db0]
      at org.apache.velocity.runtime.parser.Parser.jj_scan_token(Parser.java:3259)
      at org.apache.velocity.runtime.parser.Parser.jj_3R_56(Parser.java:3089)
      at org.apache.velocity.runtime.parser.Parser.jj_3R_29(Parser.java:2696)
      at org.apache.velocity.runtime.parser.Parser.jj_3_8(Parser.java:2530)
      at org.apache.velocity.runtime.parser.Parser.jj_3_7(Parser.java:2574)
      at org.apache.velocity.runtime.parser.Parser.jj_2_7(Parser.java:2483)
      at org.apache.velocity.runtime.parser.Parser.Reference(Parser.java:1240)
      at org.apache.velocity.runtime.parser.Parser.PrimaryExpression(Parser.java:2391)
      at org.apache.velocity.runtime.parser.Parser.UnaryExpression(Parser.java:2366)
      at org.apache.velocity.runtime.parser.Parser.MultiplicativeExpression(Parser.java:2215)
      at org.apache.velocity.runtime.parser.Parser.AdditiveExpression(Parser.java:2139)
      at org.apache.velocity.runtime.parser.Parser.RelationalExpression(Parser.java:2007)
      at org.apache.velocity.runtime.parser.Parser.EqualityExpression(Parser.java:1931)
      at org.apache.velocity.runtime.parser.Parser.ConditionalAndExpression(Parser.java:1891)
      at org.apache.velocity.runtime.parser.Parser.ConditionalOrExpression(Parser.java:1851)
      at org.apache.velocity.runtime.parser.Parser.Expression(Parser.java:1798)
      at org.apache.velocity.runtime.parser.Parser.SetDirective(Parser.java:1730)
      at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:310)
      at org.apache.velocity.runtime.parser.Parser.IfStatement(Parser.java:1453)
      at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:293)
      at org.apache.velocity.runtime.parser.Parser.IfStatement(Parser.java:1453)
      at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:293)
      at org.apache.velocity.runtime.parser.Parser.IfStatement(Parser.java:1453)
      at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:293)
      at org.apache.velocity.runtime.parser.Parser.IfStatement(Parser.java:1453)
      at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:293)
      at org.apache.velocity.runtime.parser.Parser.ElseStatement(Parser.java:1564)
      at org.apache.velocity.runtime.parser.Parser.IfStatement(Parser.java:1495)
      at org.apache.velocity.runtime.parser.Parser.Statement(Parser.java:293)
      at org.apache.velocity.runtime.parser.Parser.process(Parser.java:258)
      at org.apache.velocity.runtime.parser.Parser.parse(Parser.java:105)
      at org.apache.velocity.runtime.RuntimeInstance.parse(RuntimeInstance.java:1042)
      at org.apache.velocity.runtime.RuntimeInstance.parse(RuntimeInstance.java:972)
      at org.apache.velocity.Template.process(Template.java:120)
      at org.apache.velocity.runtime.resource.ResourceManagerImpl.loadResource(ResourceManagerImpl.java:415)
      at org.apache.velocity.runtime.resource.ResourceManagerImpl.getResource(ResourceManagerImpl.java:335)

      • locked <0x91140270> (a org.apache.velocity.runtime.resource.ResourceManagerImpl)
        at org.apache.velocity.runtime.RuntimeInstance.getTemplate(RuntimeInstance.java:1102)
        at org.apache.velocity.runtime.directive.Parse.render(Parse.java:177)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.directive.Foreach.render(Foreach.java:448)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.runtime.directive.Parse.render(Parse.java:224)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.runtime.directive.Parse.render(Parse.java:224)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:107)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.runtime.directive.Parse.render(Parse.java:224)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.directive.Foreach.render(Foreach.java:448)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.directive.Foreach.render(Foreach.java:448)
        at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:170)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:88)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:107)
        at org.apache.velocity.runtime.parser.node.ASTBlock.render(ASTBlock.java:74)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.runtime.parser.node.ASTIfStatement.render(ASTIfStatement.java:107)
        at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:318)
        at org.apache.velocity.Template.merge(Template.java:254)
        at de.his.servlet.util.ServletUtil.parseWithVelocity(ServletUtil.java:736)
        at de.his.servlet.util.ServletUtil.sendResponseWithVelocity(ServletUtil.java:684)
        at de.his.servlet.HISServletModuleImpl.handleRequest(HISServletModuleImpl.java:637)
        at de.his.servlet.RequestDispatcherServlet.invoke(RequestDispatcherServlet.java:908)
        at de.his.servlet.RequestDispatcherServlet.handleRequest(RequestDispatcherServlet.java:843)
        at de.his.servlet.RequestDispatcherServlet.doGet(RequestDispatcherServlet.java:1060)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:689)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
        at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:868)
        at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:663)
        at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
        at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
        at java.lang.Thread.run(Thread.java:595)

        Activity

        Hide
        Will Glass-Husain added a comment -

        This is really very strange. Hard to debug generated code such as that in Parser.java too.

        Are you sharing either the Template object or the Context between the two threads?

        Show
        Will Glass-Husain added a comment - This is really very strange. Hard to debug generated code such as that in Parser.java too. Are you sharing either the Template object or the Context between the two threads?
        Hide
        Will Glass-Husain added a comment - - edited

        Also – is that the stack trace for all threads?

        I understand why the first thread is hanging. It's waiting for ResourceManagerImpl.getResource to be free (it's a synchronized method) – it's in use while the template is parsing. But I don't understand why the Parser is hanging. Could it be hitting an OutOfMemory or garbage collection issue?

        WILL

        Show
        Will Glass-Husain added a comment - - edited Also – is that the stack trace for all threads? I understand why the first thread is hanging. It's waiting for ResourceManagerImpl.getResource to be free (it's a synchronized method) – it's in use while the template is parsing. But I don't understand why the Parser is hanging. Could it be hitting an OutOfMemory or garbage collection issue? WILL
        Hide
        nhb added a comment - - edited

        They are using different templates and different context objects. There is, however, one property object in the context of thread "http-8080-Processor23" that is modified by thread "DataExchange" before and after the invocation of Velocity there. It is not accessed by Velocity in that thread and it is not in this context. So i don't think that this could be a problem.

        Threre is no OutOfMemoryError. But the "DataExchange" thread is working with huge amounts of data. I wrote a NotificationListener using the MemoryMXBean. It got notified that the heap will be running out of space soon, shortly before the other thread starts parsing.

        Thanks for that tip.

        Show
        nhb added a comment - - edited They are using different templates and different context objects. There is, however, one property object in the context of thread "http-8080-Processor23" that is modified by thread "DataExchange" before and after the invocation of Velocity there. It is not accessed by Velocity in that thread and it is not in this context. So i don't think that this could be a problem. Threre is no OutOfMemoryError. But the "DataExchange" thread is working with huge amounts of data. I wrote a NotificationListener using the MemoryMXBean. It got notified that the heap will be running out of space soon, shortly before the other thread starts parsing. Thanks for that tip.
        Hide
        Will Glass-Husain added a comment -

        This is always tough with these type of issues, but can you create a simple example that replicates the problem?

        Show
        Will Glass-Husain added a comment - This is always tough with these type of issues, but can you create a simple example that replicates the problem?
        Hide
        nhb added a comment -

        Although the problem was nearly 100% reproduceable last week, I was unable to reproduce it in the last two days. I even checked out the old version of our project from CVS but the problem does not occure anymore.

        Hopping that this won't happen in production --> resolution: cannot reproduce

        Show
        nhb added a comment - Although the problem was nearly 100% reproduceable last week, I was unable to reproduce it in the last two days. I even checked out the old version of our project from CVS but the problem does not occure anymore. Hopping that this won't happen in production --> resolution: cannot reproduce
        Hide
        Will Glass-Husain added a comment -

        I'm thinking... memory constraint? (i.e. garbage collection pause).

        Show
        Will Glass-Husain added a comment - I'm thinking... memory constraint? (i.e. garbage collection pause).

          People

          • Assignee:
            Unassigned
            Reporter:
            nhb
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development