[Grok-dev] a nice research project

[Uli Fouquet]

Hi there,

before going into detail: I generated some call graph graphics out of
the profiler stats discussed in this thread. They might be useful for
further investigations. Please see below for the links.

Martijn Faassen wrote:

>  > At least the XML parsing (with following calls to `minidom`) seems to
>  > be triggered by `zope.i18n` when a locale is loaded (`getLocale()` and
>  > `loadLocale()` on request of zope.publisher). This happend here only
>  > on the first request. All subsequent calls (as Michaels output shows),
>  > do not call TAL- or XML-stuff. Even when the server was restarted.
> 
> So you mean that this initialization is cached somehow even after a 
> server restart?

That was a lie, maybe caused by too little profiler runs and concurrent
things happening on the profiling machine.

Afer every restart the locales are loaded again, consuming the most time
when the first request comes in. Subsequent calls (at leat such with the
same browser locale setting) do not load the locale again and are about
10 times faster than the initial request.

>  > The XML stuff looks to me like some initialization code. Also the
>  > number of function calls decreases to about 300 on subsequent calls
>  > (also shown in Michaels result). Should I dig deeper?
> 
> I think we should translate the things we learn from this investigations 
> into steps to take. Could we make the i18n system load earlier? Would 
> that have negative impact on the startup time? Why does the i18n system 
> appear to need ZPT?

The latter is difficult to say. I could not reproduce calls to any ZPT
code as long as no template is called. Even not on the initial request.

> To go even further I think looking at the publisher is a good next step. 
> I wrote more about that elsewhere on this thread, and this is also a 
> good place to start the work:
> 
> http://shane.willowrise.com/archives/repozublisher/
> 
> In fact, Shane started some of the work already, decomposing Zope 
> publisher functionality into a WSGI stack. There's now a zope.httpform 
> package:
> 
> http://pypi.python.org/pypi/zope.httpform/
> 
>  > A maybe interesting sidenote: when using a page template insted of
>  > returning a string in the view, I get slightly faster results here.
> 
> That seems a totally bizarre result. The page template engine is doing a 
> lot more work than just returning a string! Could you dig deeper into 
> that one?

That was also a false alarm, sorry. After doing many profiler runs, it
looks like the templated version of Chris' sample application consumes
about one third more time.

To get a better visual impression of all the calls, that happen during
requests to a plain Grok application, I generated some call-graphs out
of the profiling information.

They have been produced like this:

1) I set up a normal Grok instance with repoze.profiler as shown by
Chris.

2) Grabbed the ``wsgi.prof`` file generated by the profiler and mangled
it with GProf2Dot (http://code.google.com/p/jrfonseca/wiki/Gprof2Dot)

3) Processed the resulting dot-file with `dot`.

The graphs can be found here:

  https://gf1.gnufix.de/~uli/grokcallgraphs/

What do they present?

wsgi-1000.png:
  The call graph after calling Chris' sample application 1002 times.
  This graph does _not_ include the initial request. It is also a
  reduced version (see below).

wsgi.prof.png:
  The call graph for the initial request after an instance start. This
  is the reduced version not displaying every function call (see below).

wsgi.prof-all.png:
  The same 'initial-request-graph', but this time with all function 
  calls included. Beware, this file is _huge_.

Each node in the graphs represents a function and has the following
layout::

  +------------------------------+
  |        function name         |
  |        total time %          | 
  |       ( self time % )        |
  |         total calls          |
  +------------------------------+

As GProf2Dot by default skips tiny calls (i.e. calls, that did not
consume much time overall), you can get a reduced version, which only
displays calls (nodes) that really matter.

We can at least see from this graphs, that on the initial request it is
really zope.i18n, that takes the vast amount of time.

Best regards,

-- 
Uli

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 189 bytes
Desc: Dies ist ein digital signierter Nachrichtenteil
Url : http://mail.zope.org/pipermail/grok-dev/attachments/20090209/4699aede/attachment.bin