[Templates] [% PROCESS %] is slow - more profiles

[Bradley Baetz]

I was trying to work out why some output using templates was taking much
more time than just using html directly. It turns out that a simple
template which uses PROCESS is about twice as slow as just putting the
block in directly. I ran these tests using TT 2.06, but with the patch
mentioned in the 2.06d changelog to get compiled templates working. I used
the XS stash.

I've attached the script I was using. If I use the following template:

[% FOREACH bug = bugs %]
  <tr>
    <td>
      <a href="show_bug.cgi?id=[% bug.id %]">[% bug.id %]</a>
    </td>
    <td>
      [% bug.title FILTER html %]
    </td>
  </tr>
[% END %]

then with 1000 bugs it takes about 21 seconds to process the template 100 
times (reusing the same template object)

On the other hand, if I use:

[% BLOCK row %]
  <tr>
    <td>
      <a href="show_bug.cgi?id=[% bug.id %]">[% bug.id %]</a>
    </td>
    <td>
      [% bug.title FILTER html %]
    </td>
  </tr>
[% END %]

[% FOREACH bug = bugs %]
[% PROCESS row %]
[% END %]

then it takes 43 seconds.

These numbers are repeatable to within a couple of seconds each way.

I'd expect process to have some overhead, but half the speed is a lot. The 
ratio is also roughly the same as I change the number of bugs:

500 bugs is 10 sec vs 23
2000 bugs gives 41 sec vs 90

I tried the cvs version of TT, and the ratio was slightly better, but the
times were much greater - 1000 bugs gave me 34 vs 58 (as compared to 21 vs
43).

This was an unloaded PIII-500 RH7.2 system with perl 5.6.0.

Does anyone have any ideas?

Bradley

#!/usr/bin/perl -w

my $num_bugs = 1000;
my $num_rep = 100;

use Template;
use Time::HiRes qw(gettimeofday tv_interval);

my $template = Template->new({
  COMPILE_EXT => ".ttc",
  OUTPUT => "/dev/null",
  PRE_CHOMP => 1,
  POST_CHOMP => 1,
  TRIM => 1
});

my $vars = {};

my @bugs;

foreach $n (1..$num_bugs) {
    my $bug = {};
    $bug->{'id'} = $n;
    $bug->{'title'} = "XXXXX";
    push(@bugs, $bug);
}

$vars->{'bugs'} = \@bugs;

# process one to get it compiled
$template->process("test.tmpl", $vars)
  || die $template->error();

my $start = [gettimeofday];

foreach (1..$num_rep) {
    $template->process("test.tmpl", $vars)
      || die $template->error();
}

my $end = [gettimeofday];
my $elapsed = tv_interval($start, $end);

print "Took $elapsed\n";
print "That makes " . $elapsed / $num_rep . " per run\n";