Item14039: System.SkinBrowser takes too long to render due to Search performance.

Following up on a foswiki-discuss item: [Foswiki-discuss] Foswiki 2.1.0 on shared hosting: SkinBrowser

This is observed on an out-of-the-box Foswiki install (2.0.3 and 2.1.0)

I used nytprof to track down the issue. A summary of the result is posted in the Sandbox: ReFoswiki210onsharedhostingSkinBrowsertimesout

In an attempt to understand the results I added print statements

• in Search.pm around line 158.

  
  sub _extractPattern {
      my ( $text, $pattern, $encode ) = @_;
  
      # Pattern comes from topic, therefore tainted
      $pattern =
        Foswiki::Sandbox::untaint( $pattern, \&Foswiki::validatePattern );
  
      my $ok = 0;
  print "158: pattern=($pattern)\ntext=($text)\n";
      eval {
  
          # The eval acts as a try block in case there is anything evil in
          # the pattern.
          $ok = 1 if ( $text =~ s/$pattern/$1/is );
      };
      $text = '' unless $ok;
  

• and in Search/InfoCache.pm around line 447

  
      return sub {
          my $item = shift;
          return 0 unless !$topicFilter || $item =~ m/$topicFilter/;
          if ( defined $excludeTopics ) {
              return 0 if $item =~ m/$excludeTopics/;
              return 0 if !$casesensitive && $item =~ m/$excludeTopics/i;
          }
  print "447: return 1 for item=($item) and topicFilter=($topicFilter)\n";
          return 1;
        }
  }
  

I execute:

cd /var/www/Foswiki-2.0.3/bin; sudo -u www-data NYTPROF="file=/tmp/nytprof.out:addpid=1:endatexit=1" perl -wTd:NYTProf view -topic System.SkinBrowser -username BramVanOosterhout >/tmp/SS.html

with the the results below(edited from SS.html. The complete output is attached as a compressed tar file). The end has the expected 3 matches for

• Screenshot, Description and Base Name
• on the PatternSkin, PlainSkin and PrintSkin topics.

As you would expect from the three matched on line 447 in InfoCache

But before those occur, there are matches for Screenshot on all pages that start with PatternSkin... I could not work out why these occur. They seem unnecessary.

447: return 1 for item=(PatternSkin) and topicFilter=((?^u:^(.*Skin)$))
447: return 1 for item=(PlainSkin) and topicFilter=((?^u:^(.*Skin)$))
447: return 1 for item=(PrintSkin) and topicFilter=((?^u:^(.*Skin)$))
SNIP=============================
There are MANY other items checked with topicFilter=()
447: return 1 for item=(PatternSkin) and topicFilter=()
447: return 1 for item=(PatternSkinCss) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbook) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookCenterPage) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookCenterPageBorder) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookEditTableStyle) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookFonts) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookHideActions) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookNoLeftBar) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookNoTopBar) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookSidebarBackground) and topicFilter=()
447: return 1 for item=(PatternSkinCustomization) and topicFilter=()
447: return 1 for item=(PatternSkinElements) and topicFilter=()
447: return 1 for item=(PatternSkinGraphics) and topicFilter=()
447: return 1 for item=(PatternSkinHorizontalNavigationExample) and topicFilter=()
447: return 1 for item=(PatternSkinNavigation) and topicFilter=()
447: return 1 for item=(PatternSkinTheme) and topicFilter=()
447: return 1 for item=(PatternSkinTheme115) and topicFilter=()
447: return 1 for item=(PatternSkinTheme2009) and topicFilter=()
447: return 1 for item=(PatternSkinThemeFatWilly) and topicFilter=()
447: return 1 for item=(PatternSkinThemeFatWillyNavigation) and topicFilter=()
SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(%STARTINCLUDE%
---+!! Pattern skin
%FORMFIELD{"Description"}%
SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! CSS elements in !PatternSkin

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! %SYSTEMWEB%.PatternSkin CSS Cookbook

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Center the page

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Center the page with a border

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: [[Foswiki:Extensions.EditTablePlugin][EditTable]] style

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Font variation

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Hide action buttons

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Hide the left bar

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Hide the top bar

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! PatternSkinCssCookbook Recipe: Sidebar background color
To see if the background color really extends beyond the body, we make the body contents longer than the sidebar.

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! %SYSTEMWEB%.PatternSkin Customization

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! Pattern Skin Elements
Some intro text.

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! !PatternSkin Graphics

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! <nop>PatternSkin Navigation

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! <nop>PatternSkin theme
Default pattern skin theme.

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! <nop>PatternSkin theme: Foswiki release 1.1.5
Use this theme if you have created a theme or sub-skin that relies on the styling of PatternSkin around release 1.1.5 or before.

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! <nop>PatternSkin theme: 2009

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! <nop>PatternSkin theme: Foswiki "Fat Willy" Site Skin

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+!! <nop>PatternSkin theme: Foswiki "Fat Willy" Site Skin - Navigation

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(
---+!! Pattern skin
Pattern skin provides a CSS based default look and feel - flexible and [[http://www.w3.org/][W3C]] compliant. Its layout and color scheme are designed to provide a nice, clean and productive editing environment

SNIP=============================
158: pattern=(.*\| *Description\:[^\|]*\|([^\|]*).*)
text=(
---+!! Pattern skin
Pattern skin provides a CSS based default look and feel - flexible and [[http://www.w3.org/][W3C]] compliant. Its layout and color scheme are designed to provide a nice, clean and productive editing environment

SNIP=============================
158: pattern=(.*\| *Base Name\:[^\|]*\| *(\S*).*)
text=(
---+!! Pattern skin
Pattern skin provides a CSS based default look and feel - flexible and [[http://www.w3.org/][W3C]] compliant. Its layout and color scheme are designed to provide a nice, clean and productive editing environment

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+ Plain Skin

SNIP=============================
158: pattern=(.*\| *Description\:[^\|]*\|([^\|]*).*)
text=(---+ Plain Skin

SNIP=============================
158: pattern=(.*\| *Base Name\:[^\|]*\| *(\S*).*)
text=(---+ Plain Skin

SNIP=============================
158: pattern=(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)
text=(---+ Print Skin

SNIP=============================
158: pattern=(.*\| *Description\:[^\|]*\|([^\|]*).*)
text=(---+ Print Skin

SNIP=============================
158: pattern=(.*\| *Base Name\:[^\|]*\| *(\S*).*)
text=(---+ Print Skin

SNIP=============================

447: return 1 for item=(PatternSkin) and topicFilter=()
447: return 1 for item=(PatternSkinCss) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbook) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookCenterPage) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookCenterPageBorder) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookEditTableStyle) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookFonts) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookHideActions) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookNoLeftBar) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookNoTopBar) and topicFilter=()
447: return 1 for item=(PatternSkinCssCookbookSidebarBackground) and topicFilter=()
447: return 1 for item=(PatternSkinCustomization) and topicFilter=()
447: return 1 for item=(PatternSkinElements) and topicFilter=()
447: return 1 for item=(PatternSkinGraphics) and topicFilter=()
447: return 1 for item=(PatternSkinHorizontalNavigationExample) and topicFilter=()
447: return 1 for item=(PatternSkinNavigation) and topicFilter=()
447: return 1 for item=(PatternSkinTheme) and topicFilter=()
447: return 1 for item=(PatternSkinTheme115) and topicFilter=()
447: return 1 for item=(PatternSkinTheme2009) and topicFilter=()
447: return 1 for item=(PatternSkinThemeFatWilly) and topicFilter=()
447: return 1 for item=(PatternSkinThemeFatWillyNavigation) and topicFilter=()
SNIP=============================

-- BramVanOosterhout - 04 Apr 2016

Excellent debugging, thanks. This appears to be another case of a perl issue that is caused by our conversion to unicode. Until you get to perl 5.20 or 5.22, regexes have a terrible performance issue when matching unicode strings. And search makes the problem exponential. Small bugs like this have probably been in the code for a long time. but the pop up as major issues due to the slow regex problem.

-- GeorgeClark - 04 Apr 2016

And.... This is not a bug in search. There are actually multiple searches on those pages. The first search, directly within the SkinBrowser topic works fine. and filters correctly.

It then renders the PatternSkin topic itself which contains an embedded search, to find the screenshot. Simple fix to reduce that search to a single topic:

diff --git a/PatternSkin/data/System/PatternSkin.txt b/PatternSkin/data/System/PatternSkin.txt
index 195e70c..afc5ef4 100644
--- a/PatternSkin/data/System/PatternSkin.txt
+++ b/PatternSkin/data/System/PatternSkin.txt
@@ -44,7 +44,7 @@ Set these variables site wide in [[%LOCALSITEPREFS%]].
 ---++ Screenshot
 
 Click to enlarge:%BR%
-%SEARCH{ "%TOPIC%" scope="topic" nosearch="on" nototal="on" format="$pattern(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)" }%
+%SEARCH{ "%TOPIC%" scope="topic" topic="%TOPIC%" nosearch="on" nototal="on" format="$pattern(.*\| *Screenshot\:[^\|]*\|([^\|]*).*)" }%
 <div class="foswikiGrayText">Click to view full screenshot</div>
 

Finally, the WebLeftBar has a search for all Category topics. Again this one is not limited to a subset of topics so every topic is searched. Another simple fix.

diff --git a/PatternSkin/data/System/WebLeftBarExample.txt b/PatternSkin/data/System/WebLeftBarExample.txt
index 74ea3cc..5e7ab5d 100644
--- a/PatternSkin/data/System/WebLeftBarExample.txt
+++ b/PatternSkin/data/System/WebLeftBarExample.txt
@@ -35,7 +35,7 @@
    * %WEBPREFSTOPIC%
 
    * <b>%MAKETEXT{"Categories"}%</b>
-%SEARCH{"parent.name='Category' AND name!='%BASETOPIC%'" web="%BASEWEB%" type="query"
+%SEARCH{"parent.name='Category' AND name!='%BASETOPIC%'" web="%BASEWEB%" topic="*Category" type="query"
 nonoise="on" format="   * [[$topic]]"}%
 %ENDSECTION{"topics"}%
 

-- GeorgeClark - 04 Apr 2016

End results of changes

===================== SEARCH macro entered (1)
447: return 1 for item=(PatternSkin) and topicFilter=((?^u:^(.*Skin)$))
447: return 1 for item=(PlainSkin) and topicFilter=((?^u:^(.*Skin)$))
447: return 1 for item=(PrintSkin) and topicFilter=((?^u:^(.*Skin)$))
===================== SEARCH macro entered (PatternSkin)
447: return 1 for item=(PatternSkin) and topicFilter=((?^ui:^(PatternSkin)$))
===================== SEARCH macro entered (parent.name='Category' AND name!='SkinBrowser')
447: return 1 for item=(AdminDocumentationCategory) and topicFilter=((?^ui:^(.*Category)$))
447: return 1 for item=(AdminToolsCategory) and topicFilter=((?^ui:^(.*Category)$))
447: return 1 for item=(Category) and topicFilter=((?^ui:^(.*Category)$))
447: return 1 for item=(DeveloperDocumentationCategory) and topicFilter=((?^ui:^(.*Category)$))
447: return 1 for item=(UserDocumentationCategory) and topicFilter=((?^ui:^(.*Category)$))
447: return 1 for item=(UserToolsCategory) and topicFilter=((?^ui:^(.*Category)$))
<!DOCTYPE html><html lang="en">
...

-- GeorgeClark - 04 Apr 2016

Thanks for the prompt response. I made the changes in 2.0.3 and the topic now renders in <7 seconds. A screenshot of the profiler results is attached below.

I assume that the PatternSkin topic is "rendered" because I am using the pattern skin and Foswiki looks for preferences in the topic. Is that correct?

And the Category search for the left bar explains why Syed got a response in the Sandbox and timed out in System.

Thanks for your help.

-- BramVanOosterhout - 05 Apr 2016

Commenting is disabled while not logged in

• SS.tgz: SS.tgz

• nytprofAfterFixes.png: