Profiling with Grok
*******************

:Author: Uli Fouquet

When it comes to a web framework, profiling is not as easy as with commandline or desktop applications. You normally want to trigger certain requests and see, in which parts of your code how much time or memory was spent.

Here is how you can do this.

Prerequisites
=============

Before we start, we apparently need something to profile: your application. So if you haven't done it yet, create a typical Grok project::

  $ grokproject Sample

This will create our project in the ``Sample/`` folder. We assume, that the created project is based on ``paster``, which is the default as of ``grokproject v1.0a2``.

If you have an older version of `grokproject` installed, update your install by::

  $ easy_install -U grokproject

You should be able to start/stop the created project.

Installing a profiler
=====================

There are some profiling tools available with every Python installation. With web-frameworks, however, we often want to check only certain requests. This is difficult with the regular profiling tools, but with `paster` we luckily have a pipleine mechanism, where we can put in a profiler, which is even configurable over web frontend: `repoze.profile`

Install `repoze.profile`
------------------------

In the ``buildout.cfg`` of your project add the ``repoze.profile`` egg to list of eggs of your application. Look out for a section named ``[app]``, which could read like this::

  ...
  [app]
  recipe = zc.recipe.egg
  eggs = cptapp
         z3c.evalexception>=2.0
         Paste
         PasteScript
         PasteDeploy
         repoze.profile
  interpreter = python-console
  ...

Here the added ``repoze.profile`` line is important.

Now run::

  $ bin/buildout

to fetch the egg from the net if it is not already available and to make it known to the generated scripts.


Create a profiler.ini
---------------------

To make use of the new egg we must tell `paster`. This is done by an appropriate initialization file we create now::

  # profiler.ini
  [pipeline:main]
  pipeline = 
           egg:repoze.profile#profile
           egg:sample

  [server:main]
  use = egg:Paste#http
  host = 127.0.0.1
  port = 8080
  
  [DEFAULT]
  # set the name of the zope.conf file
  zope_conf = %(here)s/zope.conf

It is crucial, that you use the name of your project egg here in the pipeline. As we created a project named ``Sample``, our egg is named ``sample``.

Put this new file in the same directory as where your ``zope.conf`` lives (not: ``zope.conf.in``). For projects created with `grokproject >= v1.0a2` this is ``etc/``, newer projects might use ``parts/etc/``.

Start Profiling
===============

With the given setup we can start profiling by::

  $ bin/paster serve etc/profiler.ini

If your ``profiler.ini`` file resides elsewhere, you of course must use a different location.

The server will start as usual and you can do everything you like with it.

Browsing the Profiler
---------------------

To get to the profiler, enter the following URL:

  http://localhost:8080/__profile__

This brings us to the profiler web frontend. If you have browsed your instance before, you will get some values about the timings of last requests. If not, then browse a bit to collect some data. The data is collected 'in background' during each requests and added to the values already collected.

Profiling a certain view
------------------------

Say we want to profile the performance of the index view created by the default application. To do this, we first have to install an instance of our ``Sample`` application.

So go to the admin interface (http://localhost:8080/applications) and add an instance of your application under the name ``app`` (you can actually use any name you like, of course).

Now we can access

  http://localhost:8080/app

and the usual index page will appear.

If we go back to the profiler, however, we will see the summed up values of all requests we did up to now. Including all the actions in the admin interface etc. we are not interested in.

We therefore clear the current data by clicking on ``clear``.

Now we access the page we want to examine directly and go to the above URL directly.

When we now go back to the profiler, we only see the values of the last request. That's the data we are interested in.


Profiling mass requests
=======================

Very often a single request to a view does not give us reliable data: too many factors can influence the request to make its values not very representative. What we often want are **many** requests and the average values appearing here.

This means for our view: we want to do several hundreds requests to the same view. But as we are lazy, we don't want to press the reload button several hundred or even thousand times. Luckily there are tools available, which can do that for us.

One of this tools is the apache benchmarking tool ``ab`` from the apache project. On Ubuntu systems it is automatically installed, if you have the apache webserver installed.

We can trigger 1,000 requests to our index page now with one command::

  $ ab -n1000 -c4 http://127.0.0.1/app/@@index

This will give us 1,000 requests, of which at most four are triggered concurrently, to the URL http://127.0.0.1/app/@@index. Please don't do this on foreign machines.

The result might look like this::

  Benchmarking 127.0.0.1 (be patient)
  Completed 100 requests
  Completed 200 requests
  Completed 300 requests
  Completed 400 requests
  Completed 500 requests
  Completed 600 requests
  Completed 700 requests
  Completed 800 requests
  Completed 900 requests
  Finished 1000 requests
  
  
  Server Software:        PasteWSGIServer/0.5
  Server Hostname:        127.0.0.1
  Server Port:            8080
  
  Document Path:          /app/@@index
  Document Length:        198 bytes
  
  Concurrency Level:      4
  Time taken for tests:   38.297797 seconds
  Complete requests:      1000
  Failed requests:        0
  Write errors:           0
  Total transferred:      448000 bytes
  HTML transferred:       198000 bytes
  Requests per second:    26.11 [#/sec] (mean)
  Time per request:       153.191 [ms] (mean)
  Time per request:       38.298 [ms] (mean, across all concurrent requests)
  Transfer rate:          11.41 [Kbytes/sec] received

  Connection Times (ms)
                min  mean[+/-sd] median   max
  Connect:        0    0   0.0      0       0
  Processing:    94  152  17.3    151     232
  Waiting:       86  151  17.3    150     231
  Total:         94  152  17.3    151     232
  
  Percentage of the requests served within a certain time (ms)
    50%    151
    66%    153
    75%    156
    80%    158
    90%    176
    95%    189
    98%    203
    99%    215
   100%    232 (longest request)

Also this benchmarking results can be interesting. But we want to know more about the functions called during this mass request and how much time they spent each. This can be seen, if we now go back to the browser and open 

  http://localhost:8080/__profile__

again.

Turning the Data into a Graph
=============================

We now want to turn the data into a graph. To do this, we first have to 'export' the data from the web framework.

Getting the Data out of the Web
-------------------------------

The web frontend provided by ``repoze.profile`` is very comfortable and nice for analyzind ad-hoc. But sometimes we want to have the data 'exported' to process it further with other tools or simply archiving the results.

Luckily we can do so by grabbing the file ``wsgi.prof`` which contains all the data presented in the web interface. This file is created in the project directory (here: ``Sample/``).

Be careful: when you click ``clear`` in the webinterface, then the file will vanish. So copy it to some secure location where we can process the data further.

Because ``repoze.profile`` makes use of the standard Python profiler in the ``profile`` or ``cProfile`` module, the data in the ``wsgi.prof`` file conforms to output generated by this profilers.

Converting the Data into ``dot``-format
---------------------------------------

One of the more advanced tools to create graphs from profiling information is ``dot``. To make use of it, we first have to convert the data in ``wsgi.prof`` into something ``dot``-compatible.

There is a tool available, which can do the job for us, a Python script named ``GProf2Dot`` which is available here:

   http://code.google.com/p/jrfonseca/wiki/Gprof2Dot

Download the script from:

   http://jrfonseca.googlecode.com/svn/trunk/gprof2dot/gprof2dot.py

We can now turn our profiling data into a ``dot`` graph by doing::

  $ python grprof2dot.py -f pstats -o wsgi.prof.dot wsgi.prof

This will turn our input file ``wsgi.prof`` of format ``pstats`` (=Python stats) into a dot-file named ``wsgi.prof.dot``.

Converting the ``dot`` file into Graphics
-----------------------------------------

Now can do the last step and turn our dot file into a nice graphics file. For this we need of course the ``dot`` programme, which on Ubuntu systems can be easily installed doing::

  $ sudo apt-get install dot

Afterwards we do the final transformation by::

  $ dot -Tpng -omygraph.png wsgi.prof.dot

This will generate a PNG file.

All the used tools (``ab``, ``dot``, ``gprof2dot``) provide a huge bunch of options you might want to explore further. This way we can generate more or less complete graphs (leaving out functions of little impact), coulours etc.

In the end you hopefully know more about your application and where it spends its time.