Profiling

[goschtl]

Frist thanks for this amazing piece of work.

I have one question regarding profiling a Plone-Site in development.
Are there any tools which you recommend. Would it make sense to integrate it to
the local development environment.

Christian

[pbauer]

Here's how I experimented with profiling a method in Plone:

Assumption: You want to do profiling yourself and not add it as a feature to your buildout.

Install required packages

In your virtualenv install the packages profilehooks (http://mg.pov.lt/profilehooks/) and snakeviz (https://jiffyclub.github.io/snakeviz/):

./bin/pip install profilehooks
./bin/pip install snakeviz

Prepare your code for profiling

Add a decorator to the method you want to profile::

from profilehooks import profile

class TestMyStuff(unittest.TestCase):

    layer = MY_LAYER

    @profile(filename='test_stuff.prof', dirs=True, entries=1000, profiler='cProfile')  # noqa
    def test_stuff(self):
        self.portal.do_something_expensive()

Profile!

Run the test like usual

./bin/test -t test_stuff

That will produce results like this:

*** PROFILER RESULTS ***
test_speed_1 (/Users/philip/workspace/kbo/src/kbo.webapp/src/kbo/webapp/tests/test_speed.py:24)
function called 1 times

         84602374 function calls (80478722 primitive calls) in 88.800 seconds

   Ordered by: cumulative time, internal time, call count
   List reduced from 1694 to 200 due to restriction <200>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000   88.931   88.931 /Users/philip/workspace/kbo/src/kbo.webapp/src/kbo/webapp/tests/test_speed.py:24(test_speed_1)
        5    0.000    0.000   88.931   17.786 /Users/philip/workspace/kbo/src/kbo.webapp/src/kbo/webapp/content/decision_factory.py:23(create)
    21065    0.133    0.000   64.081    0.003 /Users/philip/.cache/buildout/eggs/plone.api-1.5-py2.7.egg/plone/api/validation.py:59(wrapped
   500/90    0.001    0.000   62.890    0.699 /Users/philip/.cache/buildout/eggs/zope.event-3.5.2-py2.7.egg/zope/event/__init__.py:27(notify)

ncalls is relevant only to the extent that comparing the numbers against other counts such as number of chars/fields/lines in a file may highligh anomalies. tottime and cumtime is what really matters:

cumtime is the time spent in the function/method including the time spent in the functions/methods that it calls.
tottime is the time spent in the function/method excluding the time spent in the functions/methods that it calls.

Visualize and analyze

The test-run created a file called test_stuff.prof in parts/test/. Use snakeviz to to analyze it:

./bin/snakeviz parts/test/test_stuff.prof

That will open your browser at http://127.0.0.1:8080/snakeviz/home/pbauer/workspace/foo/parts/test/test_stuff.prof and shows a diagram that show the time used by the functions the test and lets you drill down into the methods called by your code and see what takes how long.

See https://jiffyclub.github.io/snakeviz/#interpreting-results on how to interpret results. It takes some time to get used to it but it gets really usefull after a while!