slow macro invocation

[Darin Kelkhoff <da...@sportingnews.com>]

hello all,

in my company's velocity setup, we have a fairly large macro library file 
(about 5 megs, 900 or so macros), set up in velocity.properties as a macro 
libarary, and it's loaded when our system initializes.  

in debugging a performance-challenged-template today, i discovered that about 
500-600 milliseconds were passing between the timestamps i recorded using the 
$context.timestamp calls in the example below (timestamp(String) is a method 
i put in my context object to log System.currentTimeMillis() to System.out):

#macro High()
   ### some code here
   $context.timestamp("before call")
   #Low()
   ### more things here
#end

#macro Low()
   $context.timestamp("inside low")
   ### lots of more code
#end

thinking that this seemed like quite a bit of time for what seemed like it 
should be a simple operation, i checked the size of macro Low.  it was about 
50KB, which made it one of the largest in our system.  fortunatly, though, it 
easily split into two pieces, as shown here:

## original macro Low:
#macro Low()
   $context.timestamp("inside low")
   #if($context.isRed)
      ### red code
   #else
      ### violet code
   #end
#end

######

## macro Low split piece 1:
#macro LowRed()
   $context.timestamp("inside low red")
   ### red code
#end

## macro Low split piece 2:
#macro LowViloet()
   $context.timestamp("inside low violet")
   ### violet code
#end

## modified macro High
#macro High()
   $context.timestamp("before call")
   #if($context.isRed)
      #LowRed()
   #else
      #LowViolet()
   #end
#end

after making this switch, each macro (LowRed and LowViolet) was about 25KB.  
now, when i ran the same set of templates (some using red, some violet), the 
average time between two timestamps was closer to 150 or 200 millis, and the 
total rendering time of the templates was down by about 300 millis as well. 


so, to make a long example a short question, does it, and if so why does it, 
take longer to invoke a larger macro than a shorter one?  i'm fairly sure 
that our macro library is not being reloaded, as that is usually about a 30 
second operation (which is another thing i'm somewhat concerned about).  i'd 
appreciate any insight or ideas on this.  i'm running 1.2rc3.

thanks,

-- 
Darin Kelkhoff  -  Programmer
darink@sportingnews.com  -  314.991.6623
The Sporting News  -  www.sportingnews.com


--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>

Re: slow macro invocation

["Geir Magnusson Jr." <ge...@optonline.net>]

On 10/28/02 10:42 PM, "Darin Kelkhoff" <da...@sportingnews.com> wrote:

> hello all,
> 
> in my company's velocity setup, we have a fairly large macro library file
> (about 5 megs, 900 or so macros), set up in velocity.properties as a macro
> libarary, and it's loaded when our system initializes.

Wow.
 
> 
> in debugging a performance-challenged-template today, i discovered that about
> 500-600 milliseconds were passing between the timestamps i recorded using the
> $context.timestamp calls in the example below (timestamp(String) is a method
> i put in my context object to log System.currentTimeMillis() to System.out):
> 
> #macro High()
>  ### some code here
>  $context.timestamp("before call")
>  #Low()
>  ### more things here
> #end
> 
> #macro Low()
>  $context.timestamp("inside low")
>  ### lots of more code
> #end
> 
> thinking that this seemed like quite a bit of time for what seemed like it
> should be a simple operation, i checked the size of macro Low.  it was about
> 50KB, which made it one of the largest in our system.  fortunatly, though, it
> easily split into two pieces, as shown here:
> 
> ## original macro Low:
> #macro Low()
>  $context.timestamp("inside low")
>  #if($context.isRed)
>     ### red code
>  #else
>     ### violet code
>  #end
> #end
> 
> ######
> 
> ## macro Low split piece 1:
> #macro LowRed()
>  $context.timestamp("inside low red")
>  ### red code
> #end
> 
> ## macro Low split piece 2:
> #macro LowViloet()
>  $context.timestamp("inside low violet")
>  ### violet code
> #end
> 
> ## modified macro High
> #macro High()
>  $context.timestamp("before call")
>  #if($context.isRed)
>     #LowRed()
>  #else
>     #LowViolet()
>  #end
> #end
> 
> after making this switch, each macro (LowRed and LowViolet) was about 25KB.
> now, when i ran the same set of templates (some using red, some violet), the
> average time between two timestamps was closer to 150 or 200 millis, and the
> total rendering time of the templates was down by about 300 millis as well.
> 
> 
> so, to make a long example a short question, does it, and if so why does it,
> take longer to invoke a larger macro than a shorter one?  i'm fairly sure
> that our macro library is not being reloaded, as that is usually about a 30
> second operation (which is another thing i'm somewhat concerned about).  i'd
> appreciate any insight or ideas on this.  i'm running 1.2rc3.

Off hand, I can't think of any reason why that would make a difference,
unless things aren't being cached.  IIRC - when a VM is used, it's 'hung' in
the right place in the syntax tree for the template, and then appears to be
a part of the template, or should be.

Are the templates being reloaded?

-- 
Geir Magnusson Jr. 
geirm@adeptra.com                                    +1-203-355-2219 (w)
Adeptra Inc.                                         +1-203-247-1713 (m)



--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>