Profiling Plone 4 (well, profiling Zope while >running< Plone 4)

I mentioned in my last post that RelStorage is the new cool, and I lamented briefly about how my application shouldn’t suck, but it does because of something I can’t really figure out, because none of the profiling tools of yore work with the newest zope and, by the transitive property of major suckage, they don’t work with newer Plone (specifically, plone 4.0) either.

So I consolidated my code, optimized the crap out of it, checked out the trunk of ZCatalog (hastily following some new developments) and sat down to wrap python’s cProfiler around my browser view, in a vain attempt at trying to make some sense out of my issue (I’ll probably post about it in detail soon, I’m still tinkering)

Anyway, after some trial and error, I came across a feature of Zope that I didn’t know existed: it has a built-in profiler. :P

Here’s how to turn it on in a typical buildout (this is untested, so please, if you try it out let me know if you run into any weirdness):

[buildout]
parts =
    instance
    
extends = 
    http://dist.plone.org/release/4.1-latest/versions.cfg

find-links =
    http://dist.plone.org/release/4.1-latest
    http://pypi.blitzen.unc.edu
    http://dist.plone.org/thirdparty
    
[instance]
recipe = plone.recipe.zope2instance
user = admin:secret
http-address = 1040
debug-mode = on
verbose-security = on
blob-storage = var/blobstorage

eggs =
    Zope2
    Plone
    ${buildout:eggs}

environment-vars =
    PROFILE_PUBLISHER 1

zope-conf-additional =
    publisher-profile-file ${buildout:directory}/profile.dat

The important part would be the environment-vars and zope-conf-additional bits. I’m not sure if the environment var is necessary or not.

This gives you a new tab under Debug Settings in the ZMI Control Panel.

So you’d navigate to http://127.0.0.1:1040/Control_Panel/manage_main, and you’d see something like this:

Clicking on the ‘Debug Information’ link brings you to a page with a couple of tabs at the top. Clicking on the “Profiling” tab, brings up this interface: (assuming you’ve clicked around your plone site a bit)

So this is really great. I now have the full power of python’s built-in profiling tools right there in Zope. I can use this interface to try to identify issues, or use the pstats module to analyze the profiler.dat file.

The downside is that nothing jumped out at me when I looked at the results after running my slow, memory-eating code. But hey, what I said before about Plone not having profiling is now totally False! I think I just need to get more familair with the results and processing them. Maybe something will shake out eventually.

One caveat: I’m not 100% sure just yet, but I think it’s best to do profiling when you’re not running in foreground mode (bin/instance fg). It seems a lot of time and function calls are spent checking/loading file system resources, which is done more frequently in that mode. I’m thinking that it’s best to try to emulate your production environment as much as possible (get rid of things like plone.reload, PDBDebugMode, DocFinderTab, etc).

w00t!

Advertisements
This entry was posted in Uncategorized. Bookmark the permalink.

4 Responses to Profiling Plone 4 (well, profiling Zope while >running< Plone 4)

  1. Noe Nieto says:

    I didn’t know it existed profiling tools for plone. Looking forward to hear more plone profiling from you.

    Regards.

  2. Thanks for brining light to this unfortunately under-documented feature of Zope2!

    It’s worth mentioning that enabling the profiler slows the site down a *lot*. When I’m doing profiling I usually just edit the parts/instance/etc/zope.conf file myself and add the “publisher-profile-file = ?whatever?” manually and restart my instance. Actually, I usually get my browser fully primed, I log in if needed, get ready to click the link whose view I want to profile, and then I make the change to zope.conf, restart the instance and click away. This considerably reduces the pain of the slowness.

    HTH

    • jjmojojjmojo says:

      I’ve only just begun messing with it, but I haven’t noticed any significant slowdown so far (not beyond the horrific computer-to-its-knees slowdown that the code makes). What I’ve been doing is letting zope start up, poke around a bit, and then clear the profiler data. Then I run my browser view that is giving me grief, and then I’ve got a pretty clean data set to work with (in theory anyway).

      For the record, I’ve got a development.cfg that extends my buildout.cfg and adds in the profiler bits. Will probably move it to something like profiler.cfg and get around the other debug tools moving forward.

  3. Jamie Lentin says:

    Another gotcha with PROFILE_PUBLISHER (probably why things get so slow), is that ZPublisher/Publish.py has a profiling lock that forces one request to be processed per-instance (or something along these lines). So leaving it on in your development buildout isn’t a good idea either.

    All that said, it’s still a very useful tool!

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s