Attention

This document was written for an old version of Plone, Plone 3, and was last updated 1125 days ago.

To learn how to upgrade to the current version of Plone, read the upgrade manual.

Profiling Plone and tuning add on product performance

by Mikko Ohtamaa — last modified Apr 23, 2009 10:12 PM
This document will tell how to profile Plone. Profiling is an action to find out bottlenecks to improve the performance of code. The primary audience of this document is add-on product developers who want to make their products scale better.

Introduction

We will install two products designed to aid Plone profiling and go through how to use them.

This document will not discuss about the caching of pages.

Prerequisites

  • You need to be familiar with Python programming and low level Zope work
  • You need to be familiar with generic software profiling concepts like cumulative time spent and how you track down CPU time hungry functions

Installing

We will install ZopeProfiler and PageTemplate profiler (PTProfiler) products.

The PTProfiler product is eggified, so we add it as an egg in buildout.cfg.

For Zope 2.10 (Plone 3.2 and below) we must use ZopeProfiler 1.7.x. which isn't eggified. Include the URL of the ZopeProfiler tarball with the plone.recipe.distros buildout recipe:

[buildout]
...
eggs =
    ...
    Products.PTProfiler

[productdistros]
recipe = plone.recipe.distros
...
urls = http://www.dieter.handshake.de/pyprojects/zope/ZopeProfiler.tgz

Run bin/buildout and restart Zope.

Using ZopeProfiler

Go to Zope control panel in ZMI root. There should be now new entry "ZopeProfiler". Press the Enable button there. This will seriously slow down the site, so enable it only when necessary.

Now go to your site and load some pages. After generating some site load, revisit ZopeProfiler section. There are tabs "Zope level" and "Python level" tabs which tell where the time has been spent.

You can click Reset button to restart profiling.

Here is some sample timing data you should see:

  1852567 function calls (1793141 primitive calls) in 22.969 CPU seconds

  Ordered by: cumulative time
  List reduced from 1888 to 200 due to restriction <200>

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     9    0.001    0.000   22.969    2.552 profile:0(<function publish_module at 0xb750a17c>)
     9    0.000    0.000   22.969    2.552 profile:0(profiler)
     9    0.000    0.000   22.953    2.550 Publish.py:392(publish_module)
     9    0.000    0.000   22.953    2.550 Publish.py:181(publish_module_standard)
  12/9    0.000    0.000   22.874    2.542 patches.py:63(new_publish)
  12/9    0.002    0.000   22.739    2.527 Publish.py:63(publish)
 33/21    0.000    0.000   16.998    0.809 :0(apply)
    12    0.001    0.000   16.767    1.397 mapply.py:32(mapply)
    12    0.000    0.000   16.765    1.397 Publish.py:41(call_object)
  2100    0.015    0.000   12.840    0.006 hooks.py:94(adapter_hook)
   543    0.014    0.000   12.827    0.024 BaseObject.py:825(Schema)
  2100    0.027    0.000   12.825    0.006 :0(adapter_hook)
   543    0.063    0.000   12.786    0.024 extender.py:95(instanceSchemaFactory)
     1    0.000    0.000   11.272   11.272 layout.py:43(__call__)
  25/1    0.000    0.000   11.272   11.272 Bindings.py:311(__call__)
  29/1    0.001    0.000   11.272   11.272 Bindings.py:331(_bindAndExec)
  23/1    0.002    0.000   11.272   11.272 PageTemplateFile.py:107(_exec)
  23/1    0.001    0.000   11.272   11.272 ProfilerPatch.py:71(__patched_render__)
  23/1    0.004    0.000   11.272   11.272 patch_cmf.py:69(PT_pt_render)
  34/1    0.000    0.000   11.034   11.034 talinterpreter.py:267(__call__)

See this page for a description of what each column means.

Make sure that portal_css or portal_javascripts debugging is not enabled, otherwise you'll also see stats for served CSS and Javascript preprocessing.

When running Zope in foreground it will run in the debug mode and do extensively stat() calls on files and folders to check whether they need to be reloaded:

505    1.372    0.003    1.372    0.003 :0(stat)

Using PTProfiler

Page template profiler tells which parts of page templates take most of the time. Since Plone used to do lots of processing inside page templates and Python scripts, it's hard to grasp how page template processing unravels. After Plone 3.x branch started to more towards using views and different update() / render() methods profiling has become easier with normal Python tools.

Go to ZMI and Plone site root. Create dummy object "PTProfiler Viewer" using Zope's Add... menu. Pick any id you wish.

Go to viewer object. Click enable.

Load some pages.

Go to viewer again. Click refresh. Now you should see template profiling output.

Sample output:

...
/home/moo/sits/products/SitsPatient/browser/form.pt             0.9     3       0.3
/home/moo/sits/products/SitsPatient/browser/form_wrapper.pt     1.96    3       0.6533
patient_selection_dropdowns                                     0.03    3       0.01
...

The names of the columns should be auto-explicative. You can click on any template to see a detailed profiling of each call in the template.

Client side profiling

Some page loading bottlenecks can be in the user browser itself. Use Firefox + Firebug Net tab to monitor the client side page rendering performance. Yahoo's YSlow is another to tool for Firefox to give a general overview of page loading times.

For example <script> tags in <body>, like out-of-the-box Google analytics script, are a performance killer.

Make sure that the source URLs of your images are relative to the site root. If you accidentally use a global image with relative src syntax like <img src="myimage.jpg">, Zope finds it from a "wrong" URL due to acquisition, but the browser reloads it for every page.

Performance optimizing tips

  • Plain old Zope instance utilizes only one CPU. Not very useful on modern servers. Setup your production sites using ZEO.
  • Make sure that you don't get any HTTP Not Found 404 pages, since they are very expensive in Zope. You can log not found pages if you clear "NotFound" in error_log / "Ignored exception types".
  • Use Chameleon template engine to speed up template generating. Chameleon will compile templates to Python bytecode making template performance far greater. Plone 3.2 usually spends 50% of its time to produce HTML from TAL templates. Chameleon is available from Plone 3.3 onwards.
  • Check plone.memoize product which contain function decorators for caching the function value during subsequent function runs. This is easy way to solve the problem if a heavy function or view is called several times per request
  • If Archetypes schema traveling (especially when using archetypes.schemaextender product) is giving you hard time check out archetypes.schematuning and this discussion.
  • If you have lots of content items and catalog queries are your bottleneck check collective.indexing product
  • Move template expression (python:, string: and traversing expressions) to BrowserView methods, since template expressions are run under RestrictedPython sandbox which comes with heavy execution penalty.
  • globalize template function is an old backwards compability hack which is a major time consumer. If you heavily edit Plone templates you can rip it off, at your own risk. Some discussion here and here(2) and here(3). globalize() will be gone in Plone 4.0.

Resources


Contribute

Something wrong or out of date? Anybody can edit or create a new article in the knowledge base. Simply create an account on this site, log in, and click the Edit button to contribute.