forrest-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From David Crossley <cross...@apache.org>
Subject Re: Profiling Forrest [FOR-572]
Date Tue, 06 Sep 2005 09:29:39 GMT
David Crossley wrote:
> Ron Blaschke wrote:
> > Ron Blaschke wrote:
> > >
> > > I've started to look at things, and were able to look at the Cocoon
> > > profiler things with "forrest run" in site-author/.
> > 
> > Here's a short, edited, sample:
> > 
> > body-index.html
> > 
> > NN  Components(Role)    Average time   Lastest times
> > 1   file ([1])           213 ms         30 ms    30 ms   581 ms
> > 2   idgen                  6 ms         10 ms     0 ms    10 ms
> > 3   xinclude            4202 ms       6219 ms  6389 ms     0 ms
> > 4   linkrewriter ([2])  2333 ms          0 ms    10 ms  6990 ms
> > 5   xslt ([3])            13 ms         20 ms    20 ms     0 ms
> > 6   xslt ([4])            66 ms         20 ms    10 ms   170 ms
> > 7   xslt ([5])             6 ms          0 ms    10 ms    10 ms
> > 8   html                   0 ms          0 ms     0 ms     0 ms
> >     Total time          6269 ms       6269 ms  6429 ms  7311 ms
> > 
> > [1] cocoon:/index.xml
> > [2] cocoon:/linkmap-index.html
> > [3] resources/stylesheets/declare-broken-site-links.xsl
> > [4] .../skins/pelt/xslt/html/document2html.xsl
> > [5].../skins/common/xslt/html/strip_namespaces.xsl
> 
> Let us interpret that. The body-index.html was requested
> three times. The right-hand column is the initial request.
> 
> Other columns are the subsequent requests. These should all
> come from the cache, and that is true for most components.
> 
> However, "xinclude" does not. Its first processing is fast
> (there are no xinclude statements in the source). On every
> subsequent occasion it is being processed and taking too
> much time.
> 
> Comment-out that xinclude transformer in sitemap.xmap
> and the "extra" time then gets listed on the "idgen".
> Comment-out that and the time moves to "linkrewriter".
> 
> I wondered if the stylesheet that does the profiler
> presentation might have some bug. So i added the
> prettier stylesheet that is provided in the Cocoon block.
> Same effect. (The stylesheet seems better so i left that
> in place).
> 
> Sorry, i don't don't know what to do now.

I added some content to the 'forrest seed-benchmark" site.
There is a plain document with no link, another doc with
a simple link, and another that uses a site: URI.

I also added a LogTranformer after each of idgen, xinclude,
and linkrewriter transformers. Two logs after xinclude.

Proceessing the "plain"
and "link-simple" documents shows that all is well.
Processing the "link-site" document shows the problem.

body-link-site.html
1  file          70  31  25 154
2  idgen          4   5   5   2
3  log            5   1   1  14
4  xinclude       4   7   7   0
5  log            2   1   1   6
6  log          218 332 313   9
7  linkrewriter 131   5   6 384
8  log            4   1   3   8
9  xslt           5   5   8   4
10 xslt          91   8  10 256
11  xslt          6   8   6   6
12  xslt          6   4   7   8
13  html          0   0   0   0
14  TOTAL       407 360 340 523

So the linkrewriter transformer is where the problem is,
but i think that we knew that.

I still cannot explain why that extra time is not recorded
inside a component. 
Comments at the Cocooon docs might provide a clue:
http://cocoon.apache.org/2.1/userdocs/concepts/profiler.html

-David

Mime
View raw message