You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@forrest.apache.org by Ron Blaschke <ma...@rblasch.org> on 2005/08/11 16:25:41 UTC
Quick glimpse at Forrest's build times
I did a quick comparison of Forrest revision 231407 (before Cocoon
update) and revision 230867 (somewhere near HEAD).
Unfortunately, very little showed up. Here's what I did.
I ran a CPU profile on both revisions, which wasn't very helpful at
all. Nothing interesting showed up. "chaperon" seems to eat a
significant amount of CPU time, though.
Then I tried something else: Taking a look at the numbers output by
Cocoon, which prints statements like the following.
* [3/43] [8/25] 1.892s 5.4Kb pluginDocs/index.html
* [4/43] [1/25] 0.962s 5.7Kb issues.html
* [6/42] [1/29] 0.971s 6.2Kb tools/index.html
^^^^^^
I decided to compare the time reported between the two revisions,
using a single run on each revision.
First the totals.
Revision 231407 Total time: 20 minutes 31 seconds ( 624 seconds)
Revision 230867 Total time: 10 minutes 24 seconds (1231 seconds)
Seems to be similar to the time difference reported by others.
There's a difference of about 607 seconds to account for (on my box).
I matched the individual times for each document, using a simple
script. The result is like this:
Page Old New Diff
/docs_0_60/changes.html 4.487s -> 9.534s 5.047s
/docs_0_60/changes.pdf 5.538s -> 9.914s 4.376s
/docs_0_60/changes.rss 0.170s -> 0.110s -0.060s
/docs_0_60/compliance.html 0.942s -> 1.722s 0.780s
/docs_0_60/compliance.pdf 0.440s -> 0.241s -0.199s
/docs_0_60/faq.html 1.712s -> 8.232s 6.520s
/docs_0_60/faq.pdf 0.882s -> 6.359s 5.477s
...
I pulled everything into a spreadsheet, and took the total of all time
differences. The total is about 602 seconds, in my opinion close
enough to the expected 607.
Below are the pages that contribute 5 seconds or more to the
difference. All numbers are in seconds.
Be warned that I currently don't know if these numbers have any
significance at all. They may mean a lot, or nothing at all! The
main reason I am presenting them is that I'll probably don't
have any more time for this issue this week, and they may (or may
not!) be useful to someone.
Note that many pages seem to be generated twice, because of slightly
different URLs; eg
/docs_0_80/changes.pdf 2,453 14,411 11,958
docs_0_80/changes.pdf 3,184 14,772 11,588
(second and third line in the table below)
Also note that the times (generation and difference) may be close
together, like above. But they may also differ quite significantly.
docs_0_60/changes.html 2,003 13,409 11,406
/docs_0_60/changes.html 4,487 9,534 5,047
Not quite unexpected, as these times are wall clock. There are other
processes running on my box, the garbage collector, ...
Page Old New Difference
docs_0_60/changes.pdf 2,653 15,673 13,020
/docs_0_80/changes.pdf 2,453 14,411 11,958
docs_0_80/changes.pdf 3,184 14,772 11,588
docs_0_60/changes.html 2,003 13,409 11,406
/docs_0_80/changes.html 1,973 12,718 10,745
/docs_0_70/changes.html 2,684 13,339 10,655
docs_0_70/changes.pdf 5,188 15,623 10,435
docs_0_80/faq.html 1,312 11,386 10,074
/docs_0_80/faq.pdf 2,043 12,077 10,034
/docs_0_70/changes.pdf 2,623 11,757 9,134
docs_0_70/changes.html 1,592 9,934 8,342
index.html 1,221 9,184 7,963
index.pdf 2,073 10,004 7,931
docs_0_80/changes.html 3,115 10,815 7,700
/docs_0_80/faq.html 0,811 8,352 7,541
/docs_0_70/faq.html 1,322 8,172 6,850
docs_0_70/your-project.html 1,301 7,871 6,570
docs_0_70/faq.pdf 1,102 7,641 6,539
/docs_0_60/faq.html 1,712 8,232 6,520
docs_0_80/faq.pdf 1,232 7,741 6,509
docs_0_60/your-project.pdf 1,302 7,561 6,259
docs_0_60/sitemap-ref.pdf 0,931 7,181 6,250
/docs_0_60/your-project.pdf 0,752 6,980 6,228
docs_0_80/your-project.pdf 1,091 7,240 6,149
/docs_0_60/sitemap-ref.html 1,241 7,260 6,019
/docs_0_70/sitemap-ref.html 1,262 7,180 5,918
docs_0_70/sitemap-ref.pdf 1,191 6,879 5,688
docs_0_60/your-project.html 1,282 6,789 5,507
/docs_0_60/faq.pdf 0,882 6,359 5,477
docs_0_70/faq.html 1,803 7,271 5,468
/docs_0_70/faq.pdf 2,403 7,601 5,198
/docs_0_60/changes.html 4,487 9,534 5,047
Ron
Re: Quick glimpse at Forrest's build times
Posted by Ross Gardler <rg...@apache.org>.
Ron Blaschke wrote:
> Thursday, August 11, 2005, 11:24:55 PM, Ross Gardler wrote:
>
>>Ron Blaschke wrote:
>>
>>>I did a quick comparison of Forrest revision 231407 (before Cocoon
>>>update) and revision 230867 (somewhere near HEAD).
>
>
>>Ron, this work you are doing is fantastic. I don't know how you can call
>>it "quick", it seems very detailed to me.
...
> Also, please let me know if anyone is interested in the script to
> extract and compare the page times, as printed by Cocoon.
> /docs_0_60/changes.html 4.487s -> 9.534s 5.047s
That would probably be a useful addition to our etc folder. If you
provide it as a patch I'm sure someone will apply it.
Ross
Re: Quick glimpse at Forrest's build times
Posted by Ron Blaschke <ma...@rblasch.org>.
Thursday, August 11, 2005, 11:24:55 PM, Ross Gardler wrote:
> Ron Blaschke wrote:
>> I did a quick comparison of Forrest revision 231407 (before Cocoon
>> update) and revision 230867 (somewhere near HEAD).
> Ron, this work you are doing is fantastic. I don't know how you can call
> it "quick", it seems very detailed to me.
> I've not got the time to go into it in detail right now, I hope someone
> else can follow up with you. I just want to show my appreciation.
> CHEERS!!!
:-) Thank you, and the others, for your kind words. I'm glad I
finally found a way I can contribute to this fine project. Keep up
the great work!
As a short update, I have reported the memory issue to Cocoon (and
added a link to FOR-572).
Possible Memory Leak with LinkRewriterTransformer
http://issues.apache.org/bugzilla/show_bug.cgi?id=36162
Also, please let me know if anyone is interested in the script to
extract and compare the page times, as printed by Cocoon.
/docs_0_60/changes.html 4.487s -> 9.534s 5.047s
Ron
Re: Quick glimpse at Forrest's build times
Posted by Ross Gardler <rg...@apache.org>.
Ron Blaschke wrote:
> I did a quick comparison of Forrest revision 231407 (before Cocoon
> update) and revision 230867 (somewhere near HEAD).
Ron, this work you are doing is fantastic. I don't know how you can call
it "quick", it seems very detailed to me.
I've not got the time to go into it in detail right now, I hope someone
else can follow up with you. I just want to show my appreciation.
CHEERS!!!
Ross
Re: Quick glimpse at Forrest's build times
Posted by Ron Blaschke <ma...@rblasch.org>.
Thursday, August 18, 2005, 4:57:49 PM, David Crossley wrote:
> Ron Blaschke wrote:
[snip]
>> Unfortunately, very little showed up. Here's what I did.
>>
>> I ran a CPU profile on both revisions, which wasn't very helpful at
>> all. Nothing interesting showed up. "chaperon" seems to eat a
>> significant amount of CPU time, though.
> Is Chaperon being used all the time, or just for
> certain processing? The latter i hope.
Unfortunately, I've already deleted the old CPU profiles. I'll try to
get a better profile by next week.
[snip]
>> docs_0_70/changes.html 1,592 9,934 8,342
>> index.html 1,221 9,184 7,963
> This is the strangest one. The index page is simple.
I'll try to focus on the index page, and try to get some comparable
numbers, like CPU profile, or whatever I come up with.
> Cocoon has a basic Profiler block that we can use to
> debug certain parts of our sitemap process.
> See their live demo:
> http://cocoon.zones.apache.org/demos/release/samples/blocks/profiler/welcome
> We have the Cocoon Profiler block in our core already.
Looks promising. Can we make this into a plugin, which generates a
"profile.html," with all site URIs listed when creating a static site?
> Perhaps we should also look at simple things
> like rolling back the versions of Xerces and Xalan.
I'll try to get some useful CPU profiles. I'm still hoping comparing
two profiles will bring up a simple answer (just like the memory
profile did).
Ron
Re: Measuring and improving Forrest build times
Posted by Ross Gardler <rg...@apache.org>.
Ron Blaschke wrote:
> Thursday, August 18, 2005, 5:58:54 PM, David Crossley wrote:
>
>>Ross Gardler wrote:
>>
>>>David Crossley wrote:
>>>
>>>>Ron Blaschke wrote:
>
>
>>>Thought for the future when this is sorted out. Can we create a new test
>>>target that will do this profiling for us?
>
>
>>>That way, each time we upgrade a dependency we can see if it impacts
>>>performance.
>
>
>>Yep i wondered that too. We can take it a step further
>>and have it running on our zone and save a set of daily
>>logfiles. Perhaps analyse them with Ron's script.
>
>
> The script is written in perl, and currently in no condition to show
> someone else. ;-) If you think the script is helpful, I'll polish it
> a bit, so we can use it.
>
> Currently, I guess there are three ways we can get numbers:
>
> 1) CPU profile with a real profiler
> Should give the most detailed results, but probably not useful for
> daily use. This is what I am currently working on.
>
> 2) Cocoon profiler block
> Judging from the demo page, this might be what we look for.
Your idea of creating a plugin to do this profiling is a good one. I've
not looked at what is involved, but I like the idea.
> 3) "The script"
> The numbers print by Cocoon, and used by my script, are probably
> equal to the total times as output by the profiler block.
> It's simple, and if we average a few runs probably quite effective.
4) Use an Open Source profiler that provides and XML output and create a
plugin that way.
Ross
Measuring and improving Forrest build times (was: Quick glimpse at Forrest's build times)
Posted by Ron Blaschke <ma...@rblasch.org>.
Thursday, August 18, 2005, 5:58:54 PM, David Crossley wrote:
> Ross Gardler wrote:
>> David Crossley wrote:
>> >Ron Blaschke wrote:
>> Thought for the future when this is sorted out. Can we create a new test
>> target that will do this profiling for us?
>> That way, each time we upgrade a dependency we can see if it impacts
>> performance.
> Yep i wondered that too. We can take it a step further
> and have it running on our zone and save a set of daily
> logfiles. Perhaps analyse them with Ron's script.
The script is written in perl, and currently in no condition to show
someone else. ;-) If you think the script is helpful, I'll polish it
a bit, so we can use it.
Currently, I guess there are three ways we can get numbers:
1) CPU profile with a real profiler
Should give the most detailed results, but probably not useful for
daily use. This is what I am currently working on.
2) Cocoon profiler block
Judging from the demo page, this might be what we look for.
3) "The script"
The numbers print by Cocoon, and used by my script, are probably
equal to the total times as output by the profiler block.
It's simple, and if we average a few runs probably quite effective.
Ron
Re: Quick glimpse at Forrest's build times
Posted by David Crossley <cr...@apache.org>.
Ross Gardler wrote:
> David Crossley wrote:
> >Ron Blaschke wrote:
> >
> >>I did a quick comparison of Forrest revision 231407 (before Cocoon
> >>update) and revision 230867 (somewhere near HEAD).
> >
> >
> >Flip those revision numbers of course.
> >
> >Thanks a million for starting this Ron.
> >
> >Hopefully it will lead into techiques that we can
> >use to continually monitor and fine-tune our product.
>
> Thought for the future when this is sorted out. Can we create a new test
> target that will do this profiling for us?
>
> That way, each time we upgrade a dependency we can see if it impacts
> performance.
Yep i wondered that too. We can take it a step further
and have it running on our zone and save a set of daily
logfiles. Perhaps analyse them with Ron's script.
-David
Re: Quick glimpse at Forrest's build times
Posted by Ross Gardler <rg...@apache.org>.
David Crossley wrote:
> Ron Blaschke wrote:
>
>>I did a quick comparison of Forrest revision 231407 (before Cocoon
>>update) and revision 230867 (somewhere near HEAD).
>
>
> Flip those revision numbers of course.
>
> Thanks a million for starting this Ron.
>
> Hopefully it will lead into techiques that we can
> use to continually monitor and fine-tune our product.
Thought for the future when this is sorted out. Can we create a new test
target that will do this profiling for us?
That way, each time we upgrade a dependency we can see if it impacts
performance.
Ross
Re: Quick glimpse at Forrest's build times
Posted by David Crossley <cr...@apache.org>.
Ron Blaschke wrote:
> I did a quick comparison of Forrest revision 231407 (before Cocoon
> update) and revision 230867 (somewhere near HEAD).
Flip those revision numbers of course.
Thanks a million for starting this Ron.
Hopefully it will lead into techiques that we can
use to continually monitor and fine-tune our product.
> Unfortunately, very little showed up. Here's what I did.
>
> I ran a CPU profile on both revisions, which wasn't very helpful at
> all. Nothing interesting showed up. "chaperon" seems to eat a
> significant amount of CPU time, though.
Is Chaperon being used all the time, or just for
certain processing? The latter i hope.
> Then I tried something else: Taking a look at the numbers output by
> Cocoon, which prints statements like the following.
>
> * [3/43] [8/25] 1.892s 5.4Kb pluginDocs/index.html
> * [4/43] [1/25] 0.962s 5.7Kb issues.html
> * [6/42] [1/29] 0.971s 6.2Kb tools/index.html
> ^^^^^^
>
> I decided to compare the time reported between the two revisions,
> using a single run on each revision.
> First the totals.
>
> Revision 231407 Total time: 20 minutes 31 seconds ( 624 seconds)
> Revision 230867 Total time: 10 minutes 24 seconds (1231 seconds)
>
> Seems to be similar to the time difference reported by others.
>
> There's a difference of about 607 seconds to account for (on my box).
> I matched the individual times for each document, using a simple
> script. The result is like this:
> Page Old New Diff
> /docs_0_60/changes.html 4.487s -> 9.534s 5.047s
> /docs_0_60/changes.pdf 5.538s -> 9.914s 4.376s
> /docs_0_60/changes.rss 0.170s -> 0.110s -0.060s
> /docs_0_60/compliance.html 0.942s -> 1.722s 0.780s
> /docs_0_60/compliance.pdf 0.440s -> 0.241s -0.199s
> /docs_0_60/faq.html 1.712s -> 8.232s 6.520s
> /docs_0_60/faq.pdf 0.882s -> 6.359s 5.477s
> ...
>
> I pulled everything into a spreadsheet, and took the total of all time
> differences. The total is about 602 seconds, in my opinion close
> enough to the expected 607.
>
> Below are the pages that contribute 5 seconds or more to the
> difference. All numbers are in seconds.
> Be warned that I currently don't know if these numbers have any
> significance at all. They may mean a lot, or nothing at all! The
> main reason I am presenting them is that I'll probably don't
> have any more time for this issue this week, and they may (or may
> not!) be useful to someone.
Well they certainly prove that it is damn slow. :-)
> Note that many pages seem to be generated twice, because of slightly
> different URLs; eg
> /docs_0_80/changes.pdf 2,453 14,411 11,958
> docs_0_80/changes.pdf 3,184 14,772 11,588
> (second and third line in the table below)
Yeah, i have wondered about that for ages. A build
of site-author today reports building 785 documents
yet 'cd site-author; find . -type f | wc -l' gives 442.
I wonder if that is something to do with
resources/stylesheets/absolutize-linkmap.xsl
> Also note that the times (generation and difference) may be close
> together, like above. But they may also differ quite significantly.
> docs_0_60/changes.html 2,003 13,409 11,406
> /docs_0_60/changes.html 4,487 9,534 5,047
> Not quite unexpected, as these times are wall clock. There are other
> processes running on my box, the garbage collector, ...
>
> Page Old New Difference
> docs_0_60/changes.pdf 2,653 15,673 13,020
> /docs_0_80/changes.pdf 2,453 14,411 11,958
> docs_0_80/changes.pdf 3,184 14,772 11,588
> docs_0_60/changes.html 2,003 13,409 11,406
> /docs_0_80/changes.html 1,973 12,718 10,745
> /docs_0_70/changes.html 2,684 13,339 10,655
> docs_0_70/changes.pdf 5,188 15,623 10,435
> docs_0_80/faq.html 1,312 11,386 10,074
> /docs_0_80/faq.pdf 2,043 12,077 10,034
> /docs_0_70/changes.pdf 2,623 11,757 9,134
> docs_0_70/changes.html 1,592 9,934 8,342
> index.html 1,221 9,184 7,963
This is the strangest one. The index page is simple.
The other pages like faq, changes, include a cumulative
effect because there is more complex Cocoon sitemap
for those.
Cocoon has a basic Profiler block that we can use to
debug certain parts of our sitemap process.
See their live demo:
http://cocoon.zones.apache.org/demos/release/samples/blocks/profiler/welcome
We have the Cocoon Profiler block in our core already.
Perhaps we should also look at simple things
like rolling back the versions of Xerces and Xalan.
-David