[Framework-Team] Some preliminary Plone 3.0 profiling results

Tue Nov 14 14:14:38 UTC 2006

Hi Alex,

I take it someone fixed PTProfiler for you?

On 11/14/06, Alexander Limi <limi at plone.org> wrote:
> Some preliminary results of running a quick PTProfiler session on Plone
> 3.0 and trying to figure out what is slowing it down.
>
> I was prompted to do this when I discovered that anonymous view of Plone
> 3.0 was about 30% slower than 2.5. Take these numbers as a general guide
> only, it's still early in the 3.0 process, and there's bound to be lots of
> improvement potential here.
>
> ANONYMOUS: 10 loads of front page, in seconds
>
> Template                               Total  Hits Per hit
> ==========================================================
> document_view.pt                       3.9707  10  0.3971
> plone_javascript_variables.js.pt       0.0441  10  0.0044
> portlet_navtree_macro.pt               0.0899  10  0.009
> portlets/browser/templates/column.pt   2.3798  20  0.119
> portlets/portlets/classic.pt           2.0051  50  0.0401
> portlets/portlets/events.pt            0.0221  10  0.0022
> portlets/portlets/login.pt             0.2678  10  0.0268
> portlets/portlets/news.pt              0.021   10  0.0021
>
> Breakdown of document_view shows (same order/units as above):
> path: plone_view/globalize             0.232   10  0.0232
>
> The rest of the things here use much less time, but there's probably some
> interesting things there too.
>
> It seems the portlets stuff is what is making it slower (more about that
> below), along with globalize.

classic.pt is nasty, because it calls globalize *for each portlet*.
This is basically to work around namespace issues (the global
namespace isn't available inside the page template).

http://svn.plone.org/svn/plone/plone.app.portlets/trunk/plone/app/portlets/portlets/classic.pt

For classic portlets, you need to have the global variables around,
obviously. I'd like to find a better way to carry that namespace over
or at least do some more clever cacheing, though. Suggestions welcome!

I'm a bit surprised by the login portlet:

http://svn.plone.org/svn/plone/plone.app.portlets/trunk/plone/app/portlets/portlets/login.py
http://svn.plone.org/svn/plone/plone.app.portlets/trunk/plone/app/portlets/portlets/login.pt

It's a complex view, and maybe it needs some cacheing. It should
probably cache tools looked up with getToolByName(), if nothing else.

> LOGGED IN: 10 loads of front page, in seconds
>
> Template                               Total  Hits Per hit
> ==========================================================
> contentmenu.pt                         3.476   10  0.3476

There is a lot going on in the content menu, which was previously in a
template. I'd be surprised if the new code was *slower*, but it may be
that it needs to duplicate some action lookup that would otherwise be
in global_defines. In particular, there are multiple calls to
listFilteredActionsFor(). I thought this was faster now in CMF 2.1,
but maybe it's a bottleneck still.

http://svn.plone.org/svn/plone/CMFPlone/trunk/browser/contentmenu/menu.py

Again, comments welcome!

If we don't mind customisation, btw, I can cut out some template fat
that was an attempt to let old customisations of global_contentmenu.pt
work.

> document_view.pt                      10.563   10  1.0563
> plone_javascript_variables.js.pt      0.0464   10  0.0046
> portlet_navtree_macro.pt              0.0934   10  0.0093
>
> portlets/browser/templates/column.pt  3.0892   20  0.1545

Bear in mind this renders all portlets.

> portlets/portlets/classic.pt          2.9249   50  0.0585

As above.

> portlets/portlets/events.pt           0.0211   10  0.0021
> portlets/portlets/login.pt            0.005    10  0.0005
> portlets/portlets/news.pt             0.0183   10  0.0018
>
> Breakdown of document_view shows (same order/units as above):
> path: plone_view/globalize            0.8519s  10  0.08519s

This is some portlets BBB stuff for people with main_template
customisations that make globalize do slightly silly things. We could
probably cut that out if we don't mind breaking some customisations.

At the same time, I think the check for 'visible' in _prepare_slots()
(http://svn.plone.org/svn/plone/CMFPlone/trunk/browser/plone.py) may
be the source of some grief. This could end up calculating the
portlets for a particular user once to determine whether the column
should be shown, and then again to find the actual portlets to show.

This one is a bit nasty, because we need to know before-the-fact
whether there are any portlets so that we can put a tal:condition on
the <td> that is the left/right column, but without globalizing more
stuff, we may not be able to keep that information around until the
actual rendering takes place. Before, we were just acquiring a
property and seeing if it was empty. Now we look in annotations,
annotations of parents, and a site-local store of user, group and
content type portlets. It's not massively slow, but it's probably not
optimal.

> python: [history[i] for i in (…)      0.8055s  10  0.08055s

What is this?

> So for logged-in, "globalize" and the versioning stuff seems to be the two
> biggest offenders by an order of magnitude, and seem to both take about
> the same amount of time.
>
> The portlets also seem to be inefficient both for logged in or not, but a
> lot of this time is spent in classic.pt, which we should be able to
> eliminate (since we should convert all the portlets to new-style portlets
> before shipping the release). I'm not sure if column.pt wraps/includes the
> classic.pt time.

column.pt should include the classic.pt time, since all column.pt does
is loop over each portlet (after finding them, as above) and then
render each one.

> Of course, all this might be wrong, but that's what happens when you let
> the UI guy do your benchmarking. ;)

It's useful!

Martin