You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@cocoon.apache.org by Vadim Gritsenko <va...@verizon.net> on 2003/08/15 23:28:56 UTC
[OT] Build Time
Just ran Cocoon build under optimize it. Not the clean build, but second
one, when there is nothing to do. It took 6 minutes on 1.6GHz P4 desktop
box. Guess where all this time has been spent? Logging!
45.26%: Project.fireMessageLoggedEvent() method
Made a quick hack of Project, replaced Vector of BuildListeners with
BuildListener[]. Build took 5 minutes.
32.1%: Project.fireMessageLoggedEvent() method
Next hotspot is:
3.78%: DefaultLogger.printMessage
And, after some xerces classes, comes DirectoryScanner - the one who is
doing the actual work:
2.2%: DirectoryScanner.scandir
Does somebody know anybody working on Ant logging system? Is Ant 1.6
better in this regard?
PS Removing synchronized() in this method gives even better results:
build runs 3 minutes, 43 seconds and fireMessageLoggedEvent method takes
just 9.5% of total execution time
PPS Hacked version of Ant-1.5.3's Project.java attached for curious folks
Vadim
Re: [OT] Build Time
Posted by Geoff Howard <co...@leverageweb.com>.
Vadim Gritsenko wrote:
> Sylvain Wallez wrote:
>
>> Vadim Gritsenko wrote:
>>
>>> Just ran Cocoon build under optimize it. Not the clean build, but
>>> second one, when there is nothing to do. It took 6 minutes on 1.6GHz
>>> P4 desktop box. Guess where all this time has been spent? Logging!
>>>
>>> 45.26%: Project.fireMessageLoggedEvent() method
>>
>> Just curious : have you tried build.sh>/dev/null ?
>
> No, it does not print *that* much. AFAIU, these are mostly DEBUG events
> (try using that verbose option!).
>
>> I/O is sometimes soooooo slow ;-)
>
> [build CPU is almost always 100% -- clear indication that that's not IO]
> Just don't tell me no-op build takes less then one minute for you! I
> won't belive you!!! :-)
I think there are some steps that are not optimized when rebuilding.
Didn't get a firm enough grasp when I looked into it or I would have
fixed it already, but the blocks builds for instance - are the temp
build files getting re-created every time? Carsten also had to reverse
some optimization in the blocks build in order to preserve build order.
You'd probably find a cvs log for the blocks build xsl file.
> Hmmm... Now when I run it without optimizeit I can't see the advantage
> of the patched version... Hmmm... Can cost of synchronized() statement
> differ highly under optimizeit comparing with regular jvm?
Uh oh. Aren't you supposed to practicing on your motorcycle? ;)
Geoff
Re: [OT] Build Time
Posted by Berin Loritsch <bl...@apache.org>.
Vadim Gritsenko wrote:
>
>
> [build CPU is almost always 100% -- clear indication that that's not IO]
> Just don't tell me no-op build takes less then one minute for you! I
> won't belive you!!! :-)
>
>
> Hmmm... Now when I run it without optimizeit I can't see the advantage
> of the patched version... Hmmm... Can cost of synchronized() statement
> differ highly under optimizeit comparing with regular jvm?
Yep.
There are a number of issues within the whole of ANT where it could be made
even faster; however, when you use it simply, there is nothing better. I am
sure that there are some issues if you have ANT trying to talk accross JVMs
(i.e. invoking sub-ANT build file targets), etc.
--
"They that give up essential liberty to obtain a little temporary safety
deserve neither liberty nor safety."
- Benjamin Franklin
Re: [OT] Build Time
Posted by Stefano Mazzocchi <st...@apache.org>.
On Saturday, Aug 16, 2003, at 01:28 Europe/Rome, Vadim Gritsenko wrote:
> Can cost of synchronized() statement differ highly under optimizeit
> comparing with regular jvm?
very likely on hotspot since hotspot is turned off on debug mode.
--
Stefano.
Re: [OT] Build Time
Posted by Vadim Gritsenko <va...@verizon.net>.
Sylvain Wallez wrote:
> Vadim Gritsenko wrote:
>
>> Just ran Cocoon build under optimize it. Not the clean build, but
>> second one, when there is nothing to do. It took 6 minutes on 1.6GHz
>> P4 desktop box. Guess where all this time has been spent? Logging!
>>
>> 45.26%: Project.fireMessageLoggedEvent() method
>
>
>
> Just curious : have you tried build.sh>/dev/null ?
No, it does not print *that* much. AFAIU, these are mostly DEBUG events
(try using that verbose option!).
> I/O is sometimes soooooo slow ;-)
[build CPU is almost always 100% -- clear indication that that's not IO]
Just don't tell me no-op build takes less then one minute for you! I
won't belive you!!! :-)
Hmmm... Now when I run it without optimizeit I can't see the advantage
of the patched version... Hmmm... Can cost of synchronized() statement
differ highly under optimizeit comparing with regular jvm?
Vadim
Re: [OT] Build Time
Posted by Sylvain Wallez <sy...@anyware-tech.com>.
Vadim Gritsenko wrote:
> Just ran Cocoon build under optimize it. Not the clean build, but
> second one, when there is nothing to do. It took 6 minutes on 1.6GHz
> P4 desktop box. Guess where all this time has been spent? Logging!
>
> 45.26%: Project.fireMessageLoggedEvent() method
Just curious : have you tried build.sh>/dev/null ?
I/O is sometimes soooooo slow ;-)
Sylvain
--
Sylvain Wallez Anyware Technologies
http://www.apache.org/~sylvain http://www.anyware-tech.com
{ XML, Java, Cocoon, OpenSource }*{ Training, Consulting, Projects }
Orixo, the opensource XML business alliance - http://www.orixo.com
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
> To solve this problem, you may consider the fact that listeners are
> more often fired than changed,
very true.
I've patched Ant along the lines of your suggestion. Vadim, if you
want to rerun the Cocoon build against Ant's CVS HEAD and could post
the results to dev@ant, that would be great.
I'm sorry for the delay, but I knew I wouldn't be available to fix any
Gump breakages my change could cause last week.
Cheers
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
> To solve this problem, you may consider the fact that listeners are
> more often fired than changed,
very true.
I've patched Ant along the lines of your suggestion. Vadim, if you
want to rerun the Cocoon build against Ant's CVS HEAD and could post
the results to dev@ant, that would be great.
I'm sorry for the delay, but I knew I wouldn't be available to fix any
Gump breakages my change could cause last week.
Cheers
Stefan
Re: [OT] Build Time
Posted by Sylvain Wallez <sy...@anyware-tech.com>.
Stefan Bodewig wrote:
>On Fri, 15 Aug 2003, Nicola Ken Barozzi <ni...@apache.org> wrote:
>
>
>
>>>DirectoryScanner.scandir Does somebody know anybody working on Ant
>>>logging system? Is Ant 1.6 better in this regard?
>>>
>>>
>
>Ant's DirectoryScanner may have become a lot (and I mean a lot) faster
>in 1.6, depending on the patterns you use.
>
>
>
>>>PS Removing synchronized() in this method gives even better
>>>results
>>>
>>>
>
>We allow listeners to be added and removed during event logging and we
>may be running several tasks in <parallel>, so I'm afraid that
>removing synchronized may be doing more harm than help.
>
>For the same reason we clone the Vector of listeners before we start
>to fire events. In the patched code, we'd at least have to copy the
>array and iterate over that copy to avoid problems when a listener
>removes itself in response to a logged message.
>
>
To solve this problem, you may consider the fact that listeners are more
often fired than changed, and therefore use a different pattern, which
does the cloning and synchronisation when the listener list has to be
changed, and not when it has to be traversed.
private List listenerers;
public void fireEvent(Event ev) {
Iterator iter = this.listeners.iterator();
while(iter.hasNext()) {
((EventListener)iter.next()).fireEvent(ev);
}
}
public void synchronized addListener(EventListener evl) {
// Make a local copy on which we will act : it avoids
// ConcurrentModificationException if someone is executing fireEvent()
List newListeners = this.listeners.clone();
newListeners.add(evl);
// and replace the listener list
this.listeners = newListeners;
}
Sylvain
--
Sylvain Wallez Anyware Technologies
http://www.apache.org/~sylvain http://www.anyware-tech.com
{ XML, Java, Cocoon, OpenSource }*{ Training, Consulting, Projects }
Orixo, the opensource XML business alliance - http://www.orixo.com
Re: [OT] Build Time
Posted by Sylvain Wallez <sy...@anyware-tech.com>.
Stefan Bodewig wrote:
>On Fri, 15 Aug 2003, Nicola Ken Barozzi <ni...@apache.org> wrote:
>
>
>
>>>DirectoryScanner.scandir Does somebody know anybody working on Ant
>>>logging system? Is Ant 1.6 better in this regard?
>>>
>>>
>
>Ant's DirectoryScanner may have become a lot (and I mean a lot) faster
>in 1.6, depending on the patterns you use.
>
>
>
>>>PS Removing synchronized() in this method gives even better
>>>results
>>>
>>>
>
>We allow listeners to be added and removed during event logging and we
>may be running several tasks in <parallel>, so I'm afraid that
>removing synchronized may be doing more harm than help.
>
>For the same reason we clone the Vector of listeners before we start
>to fire events. In the patched code, we'd at least have to copy the
>array and iterate over that copy to avoid problems when a listener
>removes itself in response to a logged message.
>
>
To solve this problem, you may consider the fact that listeners are more
often fired than changed, and therefore use a different pattern, which
does the cloning and synchronisation when the listener list has to be
changed, and not when it has to be traversed.
private List listenerers;
public void fireEvent(Event ev) {
Iterator iter = this.listeners.iterator();
while(iter.hasNext()) {
((EventListener)iter.next()).fireEvent(ev);
}
}
public void synchronized addListener(EventListener evl) {
// Make a local copy on which we will act : it avoids
// ConcurrentModificationException if someone is executing fireEvent()
List newListeners = this.listeners.clone();
newListeners.add(evl);
// and replace the listener list
this.listeners = newListeners;
}
Sylvain
--
Sylvain Wallez Anyware Technologies
http://www.apache.org/~sylvain http://www.anyware-tech.com
{ XML, Java, Cocoon, OpenSource }*{ Training, Consulting, Projects }
Orixo, the opensource XML business alliance - http://www.orixo.com
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
On Fri, 15 Aug 2003, Nicola Ken Barozzi <ni...@apache.org> wrote:
>> DirectoryScanner.scandir Does somebody know anybody working on Ant
>> logging system? Is Ant 1.6 better in this regard?
Ant's DirectoryScanner may have become a lot (and I mean a lot) faster
in 1.6, depending on the patterns you use.
>> PS Removing synchronized() in this method gives even better
>> results
We allow listeners to be added and removed during event logging and we
may be running several tasks in <parallel>, so I'm afraid that
removing synchronized may be doing more harm than help.
For the same reason we clone the Vector of listeners before we start
to fire events. In the patched code, we'd at least have to copy the
array and iterate over that copy to avoid problems when a listener
removes itself in response to a logged message.
I wouldn't expect the speed improvement to be as big after you've
thrown in a System.arraycopy.
Stefan
Re: [OT] Build Time
Posted by Steve Loughran <st...@iseran.com>.
Costin Manolache wrote:
> Nice work !
>
> Regarding ant logging system - I think we should eventually reopen the
> subject and pick a logger API ( I preffer commons-logging, but I won't -1
> any other choice ), then start using the normal
> if( log.isDebugEnabled()) log()
> that prevents useless string concatenations and calls.
Something for next iteration. One issue is that today it is the
listeners and loggers that choose the log level implicitly (by what they
output), rather than by communicating it to components. Maybe we could
extend these interfaces so that they get polled as to their logging
level and the merged set of all options gets presented to the tasks
(presumably via commons logging)
>
> Costin
>
>
>
> Nicola Ken Barozzi wrote:
>
>
>>Sending this to ant-dev too.
>>
>>Vadim Gritsenko wrote, On 15/08/2003 23.28:
>>
>>>Just ran Cocoon build under optimize it. Not the clean build, but second
>>>one, when there is nothing to do. It took 6 minutes on 1.6GHz P4 desktop
>>>box. Guess where all this time has been spent? Logging!
>>>
>>> 45.26%: Project.fireMessageLoggedEvent() method
>>>
>>>
>>>Made a quick hack of Project, replaced Vector of BuildListeners with
>>>BuildListener[]. Build took 5 minutes.
>>>
>>> 32.1%: Project.fireMessageLoggedEvent() method
>>>
>>>Next hotspot is:
>>> 3.78%: DefaultLogger.printMessage
>>>And, after some xerces classes, comes DirectoryScanner - the one who is
>>>doing the actual work:
>>> 2.2%: DirectoryScanner.scandir
>>>
>>>
>>>Does somebody know anybody working on Ant logging system? Is Ant 1.6
>>>better in this regard?
>>>
>>>PS Removing synchronized() in this method gives even better results:
>>>build runs 3 minutes, 43 seconds and fireMessageLoggedEvent method takes
>>>just 9.5% of total execution time
>>>
>>>PPS Hacked version of Ant-1.5.3's Project.java attached for curious folks
>>>
>>>Vadim
>>>
>>>
>>>------------------------------------------------------------------------
>>>
>>>Index: src/main/org/apache/tools/ant/Project.java
>>>===================================================================
>>>RCS file:
>>>/home/cvspublic/ant/src/main/org/apache/tools/ant/Project.java,v
>>>retrieving revision 1.108.2.12 diff -u -r1.108.2.12 Project.java
>>>--- src/main/org/apache/tools/ant/Project.java 17 Feb 2003 14:21:12 -0000
>>>1.108.2.12
>>>+++ src/main/org/apache/tools/ant/Project.java 15 Aug 2003 21:26:28 -0000
>>>@@ -198,7 +198,7 @@
>>> private File baseDir;
>>>
>>> /** List of listeners to notify of build events. */
>>>- private Vector listeners = new Vector();
>>>+ private BuildListener[] listeners = new BuildListener[0];
>>>
>>> /**
>>> * The Ant core classloader - may be <code>null</code> if using
>>>@@ -347,7 +347,13 @@
>>> * Must not be <code>null</code>.
>>> */
>>> public void addBuildListener(BuildListener listener) {
>>>- listeners.addElement(listener);
>>>+ synchronized (this) {
>>>+ int n = listeners.length;
>>>+ BuildListener[] newListeners = new BuildListener[n + 1];
>>>+ System.arraycopy(listeners, 0, newListeners, 0, n);
>>>+ newListeners[n] = listener;
>>>+ listeners = newListeners;
>>>+ }
>>> }
>>>
>>> /**
>>>@@ -358,7 +364,23 @@
>>> * Should not be <code>null</code>.
>>> */
>>> public void removeBuildListener(BuildListener listener) {
>>>- listeners.removeElement(listener);
>>>+ synchronized (this) {
>>>+ int n = listeners.length;
>>>+ int m = 0;
>>>+ for (int i = 0; i < n; i++) {
>>>+ if (listeners[i] != listener &&
>>>!listeners[i].equals(listener)) {
>>>+ m++;
>>>+ }
>>>+ }
>>>+ BuildListener[] newListeners = new BuildListener[m];
>>>+ m = 0;
>>>+ for (int i = 0; i < n; i++) {
>>>+ if (listeners[i] != listener &&
>>>!listeners[i].equals(listener)) {
>>>+ newListeners[m++] = listeners[i];
>>>+ }
>>>+ }
>>>+ listeners = newListeners;
>>>+ }
>>> }
>>>
>>> /**
>>>@@ -367,7 +389,11 @@
>>> * @return a list of build listeners for the project
>>> */
>>> public Vector getBuildListeners() {
>>>- return (Vector) listeners.clone();
>>>+ Vector v = new Vector(listeners.length);
>>>+ for (int i = 0; i < listeners.length; i++) {
>>>+ v.add(listeners[i]);
>>>+ }
>>>+ return v;
>>> }
>>>
>>> /**
>>>@@ -987,7 +1013,7 @@
>>> * Must not be <code>null</code>.
>>> */
>>> public void addDataTypeDefinition(String typeName, Class typeClass)
>>> {
>>>- synchronized(dataClassDefinitions) {
>>>+ synchronized (dataClassDefinitions) {
>>> Class old = (Class) dataClassDefinitions.get(typeName);
>>> if (null != old) {
>>> if (old.equals(typeClass)) {
>>>@@ -2003,20 +2029,17 @@
>>> private void fireMessageLoggedEvent(BuildEvent event, String
>>> message,
>>> int priority) {
>>> event.setMessage(message, priority);
>>>- Vector listeners = getBuildListeners();
>>>- synchronized(this) {
>>>- if (loggingMessage) {
>>>- throw new BuildException("Listener attempted to access "
>>>- + (priority == MSG_ERR ? "System.err" :
>>>"System.out")
>>>- + " - infinite loop terminated");
>>>- }
>>>- loggingMessage = true;
>>>- for (int i = 0; i < listeners.size(); i++) {
>>>- BuildListener listener = (BuildListener)
>>>listeners.elementAt(i);
>>>- listener.messageLogged(event);
>>>- }
>>>- loggingMessage = false;
>>>+ if (loggingMessage) {
>>>+ throw new BuildException("Listener attempted to access "
>>>+ + (priority == MSG_ERR ? "System.err" : "System.out")
>>>+ + " - infinite loop terminated");
>>>+ }
>>>+ loggingMessage = true;
>>>+ BuildListener[] listeners = this.listeners;
>>>+ for (int i = 0; i < listeners.length; i++) {
>>>+ listeners[i].messageLogged(event);
>>> }
>>>+ loggingMessage = false;
>>> }
>>>
>>> /**
>>>@@ -2089,6 +2112,4 @@
>>> public Task getThreadTask(Thread thread) {
>>> return (Task) threadTasks.get(thread);
>>> }
>>>-
>>>-
>>> }
>>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
> For additional commands, e-mail: dev-help@ant.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
On Fri, 22 Aug 2003, Costin Manolache <cm...@yahoo.com> wrote:
> If we make commons-logging/log4j/whatever as part of ant1.6, then in
> 1.6+ tasks can use it for _debug_ info.
I think I understand what you are getting at, but I guess I'd prefer
the approach described by Steve in bugzilla report 22460[1]. Write a
logger that uses Ant's logging system as its output, tasks can then
choose to log to this logger unstead of writing to project.log()
directly.
Stefan
Footnotes:
[1] http://issues.apache.org/bugzilla/show_bug.cgi?id=22460
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Steve Loughran <st...@iseran.com>.
Costin Manolache wrote:
> Stefan Bodewig wrote:
>
>
>>On Mon, 18 Aug 2003, <cm...@yahoo.com> wrote:
>>
>
>>>Most of the time the debug messages are not logged by anyone
>>
>>IIRC XmlLogger will log all levels.
>
>
> And generates huge files that sometimes are almost useless.
agreed. But sometimes they are very useful.
>
>
>>I understand the use case and where you are getting at, I don't see a
>>backwards compatible way to change it, though. I expect
>>BuildListeners to play a major role in IDE integration today, changing
>>the interface will break a lot of things.
>
>
> If we make commons-logging/log4j/whatever as part of ant1.6, then in 1.6+
> tasks can use it for _debug_ info.
> Things like the parameter used for javac or exec, or what files are beeing
> copied can use that.
>
> For backward compat, we could keep both paterns -
> if( project.debug ) -> use BuildListener to broadcast the info.
> if( taskLog.debug || target.debug ) -> use commons-logging to debug.
>
> It may seem like a huge amount of work - but it can be done incrementally,
> and at least in my experience this "fine tunned" debug is needed the most in
> few tasks ( javac, exec, copy, antcall and maybe few others )
Alternatively, Listeners could also support the commons-logging log
interface, and we could upgrade all the existing ones to do so (though
they may be subclassed; life is never simple). Then when running through
the list of listeners to send notifications to, Ant determines the
lowest common denominator of logging levels. If everything is commons
based, then if any have isDebugEnabled() set, then debug is enabled. If
not, well, we log at the relevant level. 'Legacy' Listeners are treated
as if they are logged at isDebugEnabled()==true, and we can provide a
bridge class to map from a commons logger interface to that of a classic
listener -every above the bridge can use the commons.
The nice thing about the commons approach is that it lets complex code
inside a task integrate properly with Ant's logging. As an example,
Axis' axis-wsdl2java uses the commons logger; to date it is not aligned
with Ant in logging modes.
W
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Costin Manolache <cm...@yahoo.com>.
Stefan Bodewig wrote:
> On Mon, 18 Aug 2003, <cm...@yahoo.com> wrote:
>
>> Something like log4j would allow us to enable debug on a particular
>> target or task.
>
> <record> solves this.
Thanks, didn't know about it.
>> Most of the time the debug messages are not logged by anyone
>
> IIRC XmlLogger will log all levels.
And generates huge files that sometimes are almost useless.
> I understand the use case and where you are getting at, I don't see a
> backwards compatible way to change it, though. I expect
> BuildListeners to play a major role in IDE integration today, changing
> the interface will break a lot of things.
If we make commons-logging/log4j/whatever as part of ant1.6, then in 1.6+
tasks can use it for _debug_ info.
Things like the parameter used for javac or exec, or what files are beeing
copied can use that.
For backward compat, we could keep both paterns -
if( project.debug ) -> use BuildListener to broadcast the info.
if( taskLog.debug || target.debug ) -> use commons-logging to debug.
It may seem like a huge amount of work - but it can be done incrementally,
and at least in my experience this "fine tunned" debug is needed the most in
few tasks ( javac, exec, copy, antcall and maybe few others )
Costin
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
On Mon, 18 Aug 2003, <cm...@yahoo.com> wrote:
> Something like log4j would allow us to enable debug on a particular
> target or task.
<record> solves this.
> Most of the time the debug messages are not logged by anyone
IIRC XmlLogger will log all levels.
I understand the use case and where you are getting at, I don't see a
backwards compatible way to change it, though. I expect
BuildListeners to play a major role in IDE integration today, changing
the interface will break a lot of things.
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by cm...@yahoo.com.
Stefan Bodewig wrote:
> On Sat, 16 Aug 2003, Costin Manolache <cm...@yahoo.com> wrote:
>
>> Regarding ant logging system - I think we should eventually reopen
>> the subject and pick a logger API
>
> I fail to see the benefit of using a different logging system, but I'm
> ceratinly open to discuss it.
>
> Ant's system currently is an event based system which goes beyond
> simple logging and we'd still have to maintain that anyway. It is
> getting used for much more things than just logging. AntClassLoader
> uses buildFinished events to deregister and clean itself up to allow
> garbage collection for example.
I know.
The problem is that we also use this logging system for debug info -
and IMO at least this doesn't work as well. If you want to find what's wrong
with a build ( and wrong things happen with complex build files ) - you can
enable debug/verbose, but that's far too much info to process.
Something like log4j would allow us to enable debug on a particular target
or task.
The second issue with using the current event-based system for debug is the
performance - we need to _allways_ do the string concatenations, and that
may have a significant impact on performance.
>> then start using the normal if( log.isDebugEnabled()) log() that
>> prevents useless string concatenations and calls.
>
> Vadim's stats say that cloning of the build listener list and
> iterating through them are the problem, not string concatenation.
That's one problem. IMO string concat is also a problem, but it won't show
in OptimizeIt if you do time-based profiles.
> And I doubt that you could implement isDebugEnabled() at all using
> Ant's BuildListener concept as the listener decides what to log, Ant
> just passes the events along. It is very well possible that one
> listener will log a MSG_DEBUG message while another one will not - and
> both are there at the same time.
That's exactly the problem. Most of the time the debug messages are not
logged by anyone - and if you need them, usually you need a small set.
By default that's hard to get, and in the most common use case ( no debug )
it is inefficient.
Costin
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
On Sat, 16 Aug 2003, Costin Manolache <cm...@yahoo.com> wrote:
> Regarding ant logging system - I think we should eventually reopen
> the subject and pick a logger API
I fail to see the benefit of using a different logging system, but I'm
ceratinly open to discuss it.
Ant's system currently is an event based system which goes beyond
simple logging and we'd still have to maintain that anyway. It is
getting used for much more things than just logging. AntClassLoader
uses buildFinished events to deregister and clean itself up to allow
garbage collection for example.
> then start using the normal if( log.isDebugEnabled()) log() that
> prevents useless string concatenations and calls.
Vadim's stats say that cloning of the build listener list and
iterating through them are the problem, not string concatenation.
And I doubt that you could implement isDebugEnabled() at all using
Ant's BuildListener concept as the listener decides what to log, Ant
just passes the events along. It is very well possible that one
listener will log a MSG_DEBUG message while another one will not - and
both are there at the same time.
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Costin Manolache <cm...@yahoo.com>.
Nice work !
Regarding ant logging system - I think we should eventually reopen the
subject and pick a logger API ( I preffer commons-logging, but I won't -1
any other choice ), then start using the normal
if( log.isDebugEnabled()) log()
that prevents useless string concatenations and calls.
Costin
Nicola Ken Barozzi wrote:
>
> Sending this to ant-dev too.
>
> Vadim Gritsenko wrote, On 15/08/2003 23.28:
>> Just ran Cocoon build under optimize it. Not the clean build, but second
>> one, when there is nothing to do. It took 6 minutes on 1.6GHz P4 desktop
>> box. Guess where all this time has been spent? Logging!
>>
>> 45.26%: Project.fireMessageLoggedEvent() method
>>
>>
>> Made a quick hack of Project, replaced Vector of BuildListeners with
>> BuildListener[]. Build took 5 minutes.
>>
>> 32.1%: Project.fireMessageLoggedEvent() method
>>
>> Next hotspot is:
>> 3.78%: DefaultLogger.printMessage
>> And, after some xerces classes, comes DirectoryScanner - the one who is
>> doing the actual work:
>> 2.2%: DirectoryScanner.scandir
>>
>>
>> Does somebody know anybody working on Ant logging system? Is Ant 1.6
>> better in this regard?
>>
>> PS Removing synchronized() in this method gives even better results:
>> build runs 3 minutes, 43 seconds and fireMessageLoggedEvent method takes
>> just 9.5% of total execution time
>>
>> PPS Hacked version of Ant-1.5.3's Project.java attached for curious folks
>>
>> Vadim
>>
>>
>> ------------------------------------------------------------------------
>>
>> Index: src/main/org/apache/tools/ant/Project.java
>> ===================================================================
>> RCS file:
>> /home/cvspublic/ant/src/main/org/apache/tools/ant/Project.java,v
>> retrieving revision 1.108.2.12 diff -u -r1.108.2.12 Project.java
>> --- src/main/org/apache/tools/ant/Project.java 17 Feb 2003 14:21:12 -0000
>> 1.108.2.12
>> +++ src/main/org/apache/tools/ant/Project.java 15 Aug 2003 21:26:28 -0000
>> @@ -198,7 +198,7 @@
>> private File baseDir;
>>
>> /** List of listeners to notify of build events. */
>> - private Vector listeners = new Vector();
>> + private BuildListener[] listeners = new BuildListener[0];
>>
>> /**
>> * The Ant core classloader - may be <code>null</code> if using
>> @@ -347,7 +347,13 @@
>> * Must not be <code>null</code>.
>> */
>> public void addBuildListener(BuildListener listener) {
>> - listeners.addElement(listener);
>> + synchronized (this) {
>> + int n = listeners.length;
>> + BuildListener[] newListeners = new BuildListener[n + 1];
>> + System.arraycopy(listeners, 0, newListeners, 0, n);
>> + newListeners[n] = listener;
>> + listeners = newListeners;
>> + }
>> }
>>
>> /**
>> @@ -358,7 +364,23 @@
>> * Should not be <code>null</code>.
>> */
>> public void removeBuildListener(BuildListener listener) {
>> - listeners.removeElement(listener);
>> + synchronized (this) {
>> + int n = listeners.length;
>> + int m = 0;
>> + for (int i = 0; i < n; i++) {
>> + if (listeners[i] != listener &&
>> !listeners[i].equals(listener)) {
>> + m++;
>> + }
>> + }
>> + BuildListener[] newListeners = new BuildListener[m];
>> + m = 0;
>> + for (int i = 0; i < n; i++) {
>> + if (listeners[i] != listener &&
>> !listeners[i].equals(listener)) {
>> + newListeners[m++] = listeners[i];
>> + }
>> + }
>> + listeners = newListeners;
>> + }
>> }
>>
>> /**
>> @@ -367,7 +389,11 @@
>> * @return a list of build listeners for the project
>> */
>> public Vector getBuildListeners() {
>> - return (Vector) listeners.clone();
>> + Vector v = new Vector(listeners.length);
>> + for (int i = 0; i < listeners.length; i++) {
>> + v.add(listeners[i]);
>> + }
>> + return v;
>> }
>>
>> /**
>> @@ -987,7 +1013,7 @@
>> * Must not be <code>null</code>.
>> */
>> public void addDataTypeDefinition(String typeName, Class typeClass)
>> {
>> - synchronized(dataClassDefinitions) {
>> + synchronized (dataClassDefinitions) {
>> Class old = (Class) dataClassDefinitions.get(typeName);
>> if (null != old) {
>> if (old.equals(typeClass)) {
>> @@ -2003,20 +2029,17 @@
>> private void fireMessageLoggedEvent(BuildEvent event, String
>> message,
>> int priority) {
>> event.setMessage(message, priority);
>> - Vector listeners = getBuildListeners();
>> - synchronized(this) {
>> - if (loggingMessage) {
>> - throw new BuildException("Listener attempted to access "
>> - + (priority == MSG_ERR ? "System.err" :
>> "System.out")
>> - + " - infinite loop terminated");
>> - }
>> - loggingMessage = true;
>> - for (int i = 0; i < listeners.size(); i++) {
>> - BuildListener listener = (BuildListener)
>> listeners.elementAt(i);
>> - listener.messageLogged(event);
>> - }
>> - loggingMessage = false;
>> + if (loggingMessage) {
>> + throw new BuildException("Listener attempted to access "
>> + + (priority == MSG_ERR ? "System.err" : "System.out")
>> + + " - infinite loop terminated");
>> + }
>> + loggingMessage = true;
>> + BuildListener[] listeners = this.listeners;
>> + for (int i = 0; i < listeners.length; i++) {
>> + listeners[i].messageLogged(event);
>> }
>> + loggingMessage = false;
>> }
>>
>> /**
>> @@ -2089,6 +2112,4 @@
>> public Task getThreadTask(Thread thread) {
>> return (Task) threadTasks.get(thread);
>> }
>> -
>> -
>> }
>
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Stefan Bodewig <bo...@apache.org>.
On Fri, 15 Aug 2003, Nicola Ken Barozzi <ni...@apache.org> wrote:
>> DirectoryScanner.scandir Does somebody know anybody working on Ant
>> logging system? Is Ant 1.6 better in this regard?
Ant's DirectoryScanner may have become a lot (and I mean a lot) faster
in 1.6, depending on the patterns you use.
>> PS Removing synchronized() in this method gives even better
>> results
We allow listeners to be added and removed during event logging and we
may be running several tasks in <parallel>, so I'm afraid that
removing synchronized may be doing more harm than help.
For the same reason we clone the Vector of listeners before we start
to fire events. In the patched code, we'd at least have to copy the
array and iterate over that copy to avoid problems when a listener
removes itself in response to a logged message.
I wouldn't expect the speed improvement to be as big after you've
thrown in a System.arraycopy.
Stefan
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org
Re: [OT] Build Time
Posted by Nicola Ken Barozzi <ni...@apache.org>.
Sending this to ant-dev too.
Vadim Gritsenko wrote, On 15/08/2003 23.28:
> Just ran Cocoon build under optimize it. Not the clean build, but second
> one, when there is nothing to do. It took 6 minutes on 1.6GHz P4 desktop
> box. Guess where all this time has been spent? Logging!
>
> 45.26%: Project.fireMessageLoggedEvent() method
>
>
> Made a quick hack of Project, replaced Vector of BuildListeners with
> BuildListener[]. Build took 5 minutes.
>
> 32.1%: Project.fireMessageLoggedEvent() method
>
> Next hotspot is:
> 3.78%: DefaultLogger.printMessage
> And, after some xerces classes, comes DirectoryScanner - the one who is
> doing the actual work:
> 2.2%: DirectoryScanner.scandir
>
>
> Does somebody know anybody working on Ant logging system? Is Ant 1.6
> better in this regard?
>
> PS Removing synchronized() in this method gives even better results:
> build runs 3 minutes, 43 seconds and fireMessageLoggedEvent method takes
> just 9.5% of total execution time
>
> PPS Hacked version of Ant-1.5.3's Project.java attached for curious folks
>
> Vadim
>
>
> ------------------------------------------------------------------------
>
> Index: src/main/org/apache/tools/ant/Project.java
> ===================================================================
> RCS file: /home/cvspublic/ant/src/main/org/apache/tools/ant/Project.java,v
> retrieving revision 1.108.2.12
> diff -u -r1.108.2.12 Project.java
> --- src/main/org/apache/tools/ant/Project.java 17 Feb 2003 14:21:12 -0000 1.108.2.12
> +++ src/main/org/apache/tools/ant/Project.java 15 Aug 2003 21:26:28 -0000
> @@ -198,7 +198,7 @@
> private File baseDir;
>
> /** List of listeners to notify of build events. */
> - private Vector listeners = new Vector();
> + private BuildListener[] listeners = new BuildListener[0];
>
> /**
> * The Ant core classloader - may be <code>null</code> if using
> @@ -347,7 +347,13 @@
> * Must not be <code>null</code>.
> */
> public void addBuildListener(BuildListener listener) {
> - listeners.addElement(listener);
> + synchronized (this) {
> + int n = listeners.length;
> + BuildListener[] newListeners = new BuildListener[n + 1];
> + System.arraycopy(listeners, 0, newListeners, 0, n);
> + newListeners[n] = listener;
> + listeners = newListeners;
> + }
> }
>
> /**
> @@ -358,7 +364,23 @@
> * Should not be <code>null</code>.
> */
> public void removeBuildListener(BuildListener listener) {
> - listeners.removeElement(listener);
> + synchronized (this) {
> + int n = listeners.length;
> + int m = 0;
> + for (int i = 0; i < n; i++) {
> + if (listeners[i] != listener && !listeners[i].equals(listener)) {
> + m++;
> + }
> + }
> + BuildListener[] newListeners = new BuildListener[m];
> + m = 0;
> + for (int i = 0; i < n; i++) {
> + if (listeners[i] != listener && !listeners[i].equals(listener)) {
> + newListeners[m++] = listeners[i];
> + }
> + }
> + listeners = newListeners;
> + }
> }
>
> /**
> @@ -367,7 +389,11 @@
> * @return a list of build listeners for the project
> */
> public Vector getBuildListeners() {
> - return (Vector) listeners.clone();
> + Vector v = new Vector(listeners.length);
> + for (int i = 0; i < listeners.length; i++) {
> + v.add(listeners[i]);
> + }
> + return v;
> }
>
> /**
> @@ -987,7 +1013,7 @@
> * Must not be <code>null</code>.
> */
> public void addDataTypeDefinition(String typeName, Class typeClass) {
> - synchronized(dataClassDefinitions) {
> + synchronized (dataClassDefinitions) {
> Class old = (Class) dataClassDefinitions.get(typeName);
> if (null != old) {
> if (old.equals(typeClass)) {
> @@ -2003,20 +2029,17 @@
> private void fireMessageLoggedEvent(BuildEvent event, String message,
> int priority) {
> event.setMessage(message, priority);
> - Vector listeners = getBuildListeners();
> - synchronized(this) {
> - if (loggingMessage) {
> - throw new BuildException("Listener attempted to access "
> - + (priority == MSG_ERR ? "System.err" : "System.out")
> - + " - infinite loop terminated");
> - }
> - loggingMessage = true;
> - for (int i = 0; i < listeners.size(); i++) {
> - BuildListener listener = (BuildListener) listeners.elementAt(i);
> - listener.messageLogged(event);
> - }
> - loggingMessage = false;
> + if (loggingMessage) {
> + throw new BuildException("Listener attempted to access "
> + + (priority == MSG_ERR ? "System.err" : "System.out")
> + + " - infinite loop terminated");
> + }
> + loggingMessage = true;
> + BuildListener[] listeners = this.listeners;
> + for (int i = 0; i < listeners.length; i++) {
> + listeners[i].messageLogged(event);
> }
> + loggingMessage = false;
> }
>
> /**
> @@ -2089,6 +2112,4 @@
> public Task getThreadTask(Thread thread) {
> return (Task) threadTasks.get(thread);
> }
> -
> -
> }
--
Nicola Ken Barozzi nicolaken@apache.org
- verba volant, scripta manent -
(discussions get forgotten, just code remains)
---------------------------------------------------------------------
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@ant.apache.org
For additional commands, e-mail: dev-help@ant.apache.org