• Do not register here on develop.twiki.org, login with your twiki.org account.
• Use View topic Item7848 for generic doc work for TWiki-6.1.1. Use View topic Item7851 for doc work on extensions that are not part of a release. More... Close
• Anything you create or change in standard webs (Main, TWiki, Sandbox etc) will be automatically reverted on every SVN update.
Does this site look broken?. Use the LitterTray web for test cases.

Item5866: shortcircuit TWiki::_processTags shortpath for 10-30% TWiki render speed improvement

Item Form Data

AppliesTo: Component: Priority: CurrentState: WaitingFor: TargetRelease ReleasedIn
Engine   Urgent Closed   patch 4.2.1, 5.0.0

Edit Form Data

Summary:
Reported By:
Codebase:
Applies To:
Component:
Priority:
Current State:
Waiting For:
Target Release:
Released In:
 

Detail

It looks like the recursive calls to _processTags most often request to process text that does not contain =%='s

the following patch shortcircuits this

on TWiki, it reduces the calls from 422 to 85, with an improvement in speed by ~300mS on TWikiVariables, its much more dramatic.

before patch (TWikiVariables)

# spent 8.06276s (0.70676+6.64924) within TWiki::_processTags which was called 2219 times, avg 0.00332s/call: 
# 1864 times (0.24136+2.22403s) by TWiki::_processTags at line 2607 of /usr/lib/cgi-bin/TWikiRelease04x02/lib/TWiki.pm, avg 0.00132s/call 
# 355 times (0.46540+4.42521s) by TWiki::expandAllTags at line 2516 of /usr/lib/cgi-bin/TWikiRelease04x02/lib/TWiki.pm, avg 0.01378s/call
sub _processTags {

after patch (TWikiVariables)

# spent 7.11110s (0.59860+5.91390) within TWiki::_processTags which was called 537 times, avg 0.01213s/call: 
# 355 times (0.49653+3.96225s) by TWiki::expandAllTags at line 2516 of /usr/lib/cgi-bin/TWikiRelease04x02/lib/TWiki.pm, avg 0.01256s/call 
# 182 times (0.10207+1.95165s) by TWiki::_processTags at line 2607 of /usr/lib/cgi-bin/TWikiRelease04x02/lib/TWiki.pm, avg 0.01128s/call
sub _processTags {

Index: ../lib/TWiki.pm
===================================================================
--- ../lib/TWiki.pm   (revision 17256)
+++ ../lib/TWiki.pm   (working copy)
@@ -2538,6 +2538,10 @@
 
     return '' unless defined( $text );
 
+#print STDERR "===".($this->{yes}||'expandAllTags')."==============================================\n";
+#print STDERR $text."\n";
+undef $this->{yes};
+
     my $depth = shift;
 
     # my( $topic, $web, $meta ) = @_;
@@ -2595,6 +2599,12 @@
                     print STDERR ' ' x $tell--,"EXPANDED $tag -> $e\n" if TRACE_TAG_PARSER;
                     $stackTop = pop( @stack );
                     # Recursively expand tags in the expansion of $tag
+unless ($e =~ /%/) {
+    #print STDERR "nonsense _processTags($e)\n";
+    $stackTop .= $e;
+    next;
+}
+$this->{yes} = 1;
                     $stackTop .= _processTags($this, $e, $tagf, $depth-1, @_ );
                 } else { # expansion failed
                     print STDERR ' ' x $tell++,"EXPAND $tag FAILED\n" if TRACE_TAG_PARSER;

I'd like to test this a little more tomorrow before i contemplate merging it, but I recon i'd be worth tossing into 4.2.1

(i'm running the unit tests atm)

-- TWiki:Main/SvenDowideit - 02 Aug 2008

I have experimented with this a bit, and I think it's reasonable optimisation.

-- TWiki:Main.CrawfordCurrie - 02 Aug 2008

further optimisations found - don't split(/%/ unless there is a '%'

and removed the print STDERR if DEBUG calls as they seem to eat alot more time than they should.

# spent 5.11737s (0.37570+4.36596) within TWiki::_processTags which was called 537 times, avg 0.00883s/call: 
# 355 times (0.28639+2.98496s) by TWiki::expandAllTags at line 2516 of /usr/lib/cgi-bin/TWikiRelease04x02/lib/TWiki.pm, avg 0.00922s/call 
# 182 times (0.08931+1.38100s) by TWiki::_processTags at line 2607 of /usr/lib/cgi-bin/TWikiRelease04x02/lib/TWiki.pm, avg 0.00808s/call
sub _processTags {

-- SvenDowideit - 03 Aug 2008

more speed tests

commandsbefore (PurePerl)after (PurePerl)
time ./view Main.WebHome skin pattern > /dev/null 
nytprofhtml --out Main.WebHome.pattern

time ./view TWiki.WebHome skin plain > /dev/null 
nytprofhtml --out TWiki.WebHome.plain  

time ./view TWiki.WebHome skin pattern > /dev/null 
nytprofhtml --out TWiki.WebHome.pattern

time ./view TWiki.TWikiVariables skin pattern > /dev/null 
nytprofhtml --out TWiki.TWikiVariables.pattern

time ./view TWiki.TWikiVariables skin plain > /dev/null 
nytprofhtml --out TWiki.TWikiVariables.plain  

time ./view Bugs.NewItems skin plain > /dev/null 
nytprofhtml --out Bugs.NewItems.plain

time ./view Bugs.NewItems skin pattern > /dev/null 
nytprofhtml --out Bugs.NewItems.pattern
real   0m1.904s
user   0m0.924s
sys   0m0.460s
Generating report...

real   0m1.652s
user   0m0.976s
sys   0m0.316s
Generating report...

real   0m2.073s
user   0m1.092s
sys   0m0.576s
Generating report...

real   0m8.766s
user   0m4.356s
sys   0m3.112s
Generating report...

real   0m7.831s
user   0m3.392s
sys   0m2.712s
Generating report...

real   0m15.378s
user   0m7.144s
sys   0m6.224s
Generating report...

real   0m16.479s
user   0m8.025s
sys   0m6.256s
Generating report...
real   0m1.853s
user   0m1.000s
sys   0m0.364s
Generating report...

real   0m1.083s
user   0m0.552s
sys   0m0.260s
Generating report...

real   0m1.556s
user   0m0.816s
sys   0m0.532s
Generating report...

real   0m7.277s
user   0m3.520s
sys   0m2.708s
Generating report...

real   0m7.236s
user   0m3.576s
sys   0m2.456s
Generating report...

real   0m15.954s
user   0m6.528s
sys   0m6.240s
Generating report...

real   0m16.024s
user   0m7.084s
sys   0m6.512s
Generating report...

commandsbefore (Forking)after (Forking)
time ./view Main.WebHome skin plain > /dev/null 
nytprofhtml --out Main.WebHome.plain_fast
time ./view Main.WebHome skin pattern > /dev/null 
nytprofhtml --out Main.WebHome.pattern_fast

time ./view TWiki.WebHome skin plain > /dev/null 
nytprofhtml --out TWiki.WebHome.plain_fast
time ./view TWiki.WebHome skin pattern > /dev/null 
nytprofhtml --out TWiki.WebHome.pattern_fast

time ./view TWiki.TWikiVariables skin plain > /dev/null 
nytprofhtml --out TWiki.TWikiVariables.plain_fast
time ./view TWiki.TWikiVariables skin pattern > /dev/null 
nytprofhtml --out TWiki.TWikiVariables.pattern_fast

time ./view Bugs.NewItems skin plain > /dev/null 
nytprofhtml --out Bugs.NewItems.plain_fast
time ./view Bugs.NewItems skin pattern > /dev/null 
nytprofhtml --out Bugs.NewItems.pattern_fast
real   0m1.842s
user   0m0.644s
sys   0m0.176s
Generating report...

real   0m1.379s
user   0m0.700s
sys   0m0.428s
Generating report...

real   0m1.137s
user   0m0.560s
sys   0m0.268s
Generating report...

real   0m1.734s
user   0m0.904s
sys   0m0.576s
Generating report...

real   0m7.813s
user   0m3.768s
sys   0m2.952s
Generating report...

real   0m8.619s
user   0m3.764s
sys   0m3.256s
Generating report...

real   0m9.535s
user   0m3.524s
sys   0m3.600s
Generating report...

real   0m9.758s
user   0m3.928s
sys   0m3.880s
Generating report...

real   0m1.098s
user   0m0.540s
sys   0m0.180s
Generating report...

real   0m1.190s
user   0m0.608s
sys   0m0.384s
Generating report...

real   0m0.967s
user   0m0.528s
sys   0m0.224s
Generating report...

real   0m1.680s
user   0m0.788s
sys   0m0.556s
Generating report...

real   0m7.434s
user   0m3.148s
sys   0m2.720s
Generating report...

real   0m7.790s
user   0m3.636s
sys   0m2.848s
Generating report...

real   0m8.268s
user   0m3.536s
sys   0m3.772s
Generating report...

real   0m9.809s
user   0m4.032s
sys   0m3.784s
Generating report...

-- TWiki:Main.SvenDowideit - 03 Aug 2008

I'm uploading the nytprofhtml output to http://distributedinformation.com/TWikiRelease04x02/nytprofhtml/ , though its taking a looong time...

-- TWiki:Main.SvenDowideit - 03 Aug 2008

Cleaned "WaitingFor" field.

-- TWiki:Main.GilmarSantosJr - 10 Aug 2008

ItemTemplate
Summary shortcircuit TWiki::_processTags shortpath for 10-30% TWiki render speed improvement
ReportedBy TWiki:Main.SvenDowideit
Codebase 4.2.0
SVN Range TWiki-5.0.0, Sun, 27 Jul 2008, build 17148
AppliesTo Engine
Component

Priority Urgent
CurrentState Closed
WaitingFor

Checkins TWikirev:17279 TWikirev:17280
TargetRelease patch
ReleasedIn 4.2.1, 5.0.0
Edit | Attach | Watch | Print version | History: r8 < r7 < r6 < r5 < r4 | Backlinks | Raw View | Raw edit | More topic actions
Topic revision: r8 - 2008-08-10 - GilmarSantosJr
 
This site is powered by the TWiki collaboration platform Powered by PerlCopyright © 2008-2019 by the contributing authors. All material on this collaboration platform is the property of the contributing authors.
Ideas, requests, problems regarding TWiki? Send feedback