[VELOCITY-607] Runtime macro rendering very slow in Velocity 1.6-dev (679708) compared to 1.5

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Fixed
• Fix Version/s: 1.6
• Component/s: Engine
• Environment: Maven 2, JUnit, JUnitPerf, JRat, custom testbench: http://www.iki.fi/wyla/velocity/testbench
• Assignee: Unassigned
• Reporter: Jarkko Viinamäki
• Created: 25/Jul/08 09:23
• Updated: 13/Aug/08 06:32
• Resolved: 13/Aug/08 06:32

Description

The following test template (see VELOCITY-24):

1. 1. local macro, not global
      #macro(letter $char)
      This is the letter $char
      #end

#letter("A")
#letter("B")
#letter("C")
#letter("D")
#letter("E")
#letter("F")
#letter("G")
#letter("H")
#letter("I")
#letter("J")
#letter("K")
#letter("L")
#letter("M")
#letter("N")
#letter("O")
#letter("P")
#letter("Q")
#letter("R")
#letter("S")
#letter("T")
#letter("U")
#letter("V")
#letter("W")
#letter("X")
#letter("Y")
#letter("Z")

—

Works quickly and correctly with Velocity 1.5 with several concurrent threads. However, 1.6-dev is a LOT slower (even 20x).

The major performance bottlenecks seem to be:
RuntimeMacro.render (60% of time)
VelocimacroFactory.getVelocimacro (20% of time)

With several threads this test also causes Velocity to throw error(s):

org.apache.velocity.exception.MacroOverflowException: Exceed maximum 20 macro calls. Call Stack:letter->letter->letter->letter->letter
at org.apache.velocity.runtime.VelocimacroFactory.startMacroRendering(VelocimacroFactory.java:179)
at org.apache.velocity.runtime.RuntimeInstance.startMacroRendering(RuntimeInstance.java:1693)
at org.apache.velocity.runtime.directive.VelocimacroProxy.render(VelocimacroProxy.java:200)
at org.apache.velocity.runtime.directive.RuntimeMacro.render(RuntimeMacro.java:230)
at org.apache.velocity.runtime.parser.node.ASTDirective.render(ASTDirective.java:178)
at org.apache.velocity.runtime.parser.node.SimpleNode.render(SimpleNode.java:323)
at org.apache.velocity.Template.merge(Template.java:324)
at org.apache.velocity.Template.merge(Template.java:232)
at org.apache.velocity.test.load.Velocity24Test.testRendering(Velocity24Test.java:51)

This is related to VELOCITY-297 but the fix doesn't seem work with the new modified macro implementation.