Bug 50229 - Slow down in StreamPumper
Summary: Slow down in StreamPumper
Status: RESOLVED DUPLICATE of bug 54128
Alias: None
Product: Ant
Classification: Unclassified
Component: Core (show other bugs)
Version: 1.8.2
Hardware: PC Windows XP
: P2 normal with 5 votes (vote)
Target Milestone: ---
Assignee: Ant Notifications List
URL:
Keywords:
: 49888 (view as bug list)
Depends on:
Blocks:
 
Reported: 2010-11-07 13:03 UTC by msunde
Modified: 2013-12-21 19:53 UTC (History)
5 users (show)



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description msunde 2010-11-07 13:03:23 UTC
Upgrading from ant 1.7.1 to ant 1.8.1 resulted in build times doubling (2hrs vs 1hr). Most of the time increase seems to be related to lines similar to the following:

<java classname="com.MyClass" fork="true" failonerror="true"
	input="${destdir}/inputFile.zip"
	output="${destdir}/outputFile.zip">
	<classpath refid="my.classpath"/>
	<arg value="AppSrv"/>
</java>

I put together a simple test that uses exec and cat to copy a 38MB file and times went from 6sec to 9min when the version of ant changed. My guess is that this is being caused by changes to StreamPumper.

----------------------------------------------
Buildfile: build.xml

init:
     [echo] Start Time: Sun, Nov 7, 2010 - 12:00:05 EST
     [echo] Ant version: Apache Ant version 1.7.1 compiled on June 27 2008
     [echo] Java version: 1.5.0_22-b03
     [echo] OS Name: Windows XP
     [echo]

all:

BUILD SUCCESSFUL
Total time: 6 seconds
----------------------------------------------
Buildfile: S:\ant\test\build.xml

init:
     [echo] Start Time: Sun, Nov 7, 2010 - 12:05:19 EST
     [echo] Ant version: Apache Ant version 1.8.2alpha compiled on October 27 2010
     [echo] Java version: 1.5.0_22-b03
     [echo] OS Name: Windows XP
     [echo]

all:

BUILD SUCCESSFUL
Total time: 9 minutes 10 seconds
----------------------------------------------
<project name="test" default="all" basedir=".">

<target name="init">
	<tstamp>
		<format property="start_time" pattern="E, MMM d, yyyy - HH:mm:ss z" locale="en" />
	</tstamp>

	<echo>Start Time: ${start_time}</echo>
	<echo>Ant version: ${ant.version}</echo>
	<echo>Java version: ${java.vm.version}</echo>
	<echo>OS Name: ${os.name}</echo>
	<echo message="" />

	<!-- 38MB file -->
	<property name="largefile" location="large_file.zip" />
	<property name="outfile" location="copy.zip" />
</target>

<target name="all" depends="init">
	<exec executable="cat" input="${largefile}" output="${outfile}"/>
</target>

<target name="clean" depends="init">
	<delete file="${outfile}"/>
</target>

</project>

----------------------------------------------
Suspected changes:
src\main\org\apache\tools\ant\taskdefs\StreamPumper.java
Ant 1.7.1
    while ((length = is.read(buf)) > 0 && !finish) {
        os.write(buf, 0, length);
        if (autoflush) {
            os.flush();
        }
    }

Ant 1.8.2
    while (true) {
        waitForInput(is);

        if (finish || Thread.interrupted()) {
            break;
        }

        length = is.read(buf);
        if (length <= 0 || finish || Thread.interrupted()) {
            break;
        }
        os.write(buf, 0, length);
        if (autoflush) {
            os.flush();
        }
    }
Comment 1 msunde 2010-11-07 13:05:52 UTC
This might be related to Bug 49888, although in that case, exec is called many times. In this case, exec is only called once.
Comment 2 Antoine Levy-Lambert 2010-12-15 18:49:41 UTC
*** Bug 49888 has been marked as a duplicate of this bug. ***
Comment 3 Antoine Levy-Lambert 2010-12-15 19:11:03 UTC
Michael, you are right, the loop in StreamPumper#run is causing the problem.
Rolling it back to 1.7.1 style brings back the same performance.
Comment 4 msunde 2010-12-16 01:02:59 UTC
It looks like the StreamPumper changes were checked in as part of Bug 5003, specifically svn revision 711860.
Comment 5 Stefan Bodewig 2010-12-16 03:49:44 UTC
The change is necessary in order to properly deal with grandchild processes
on Windows - that's why it used to be explicitly restricted to Windows
initially.

If you take out the change the AntUnit test testDoesntWaitForChildren in
exec-test is going to take more than 20 seconds because Ant now waits
for the grandchildren the forked (and long finished) child process
has spawned.

So reverting the change is no option.  Finding a different solution for
bug 5003 would be one, but so far nobody has found one.

One option may be to not set useAvailable to true if we know the forked
process is not going to spawn additional child prcesses - like in <attrib>'s
case and make it configurable via attributes on <exec> and friends.

One thing to consider is that a while back the useAvailable flag has
been set to true on all operating systems because it seemed to fix
another bug.  I don't recall which bug it has been and don't have the time
to search for it right away, but I recall it was not related to grandchildren
at all - so this bug might reappear with my idea above.  Then again I also
recall somebody (I think Jesse) questioned whether the bug has really been
fixed and whether the change was the correct one at all.
Comment 6 Stefan Bodewig 2010-12-16 03:55:12 UTC
I knew I had pulled together related bug ids once.

http://marc.info/?t=127652142200010&r=1&w=2
Comment 7 Antoine Levy-Lambert 2010-12-16 10:22:37 UTC
Hello Stefan,

I changed PumpStreamHandler to always set "useavailable" to true in order to fix the bug 48746, "exec task sometimes inserts extraneous newlines". This was svn revision 912298. 

I remember that I was able to reproduce bug 48746 on MacOS with useavailable="false" and that setting useavailable="true" there helped.

Maybe we would need to have useavailable="true" by default on Windows and MacOS and set it to false on other operating systems including Linux.

Antoine
Comment 8 msunde 2010-12-16 11:08:19 UTC
Is there a reason StreamPumper uses a SMALL_BUFFER_SIZE (128)? In this particular bug, a large file on disk is being read in so a larger buffer may be beneficial (not tested).

In this bug, the parent java/exec task knows that it is reading from a file on disk so does useavailable make sense for that input stream?
Comment 9 James.Poli 2011-12-08 14:32:01 UTC
Stefan,
This bug has caused significant degradation in the performance of our testing framework which runs Ant with AntUnit and then forks off another ANT process with the ANT Java task.  Our forked ANT produces a large amount of output.  Do you see a solution coming soon to fix this?  
Thanks in advance,
James Poli
Comment 10 Markus Schlegel 2012-06-13 16:02:15 UTC
hi ant maintainers,

Is there any work planned on this issue?
We are still on ant 1.7.1 here because of this issue, since our build takes 1h 15min with 1.8.4 instead of 44min with ant 1.7.1
Now we'd like to use IVY and some other new stuff. This is a showstopper for years now. We never had problems with the ant 1.7.1 StreamPumper.
Comment 11 Markus Schlegel 2012-06-13 16:15:37 UTC
Did anyone tried out the patch provided by Rohit Kelapure on  [Bug 5003] ?
Comment 12 Markus Schlegel 2012-06-13 20:52:18 UTC
I tried the patch from Rohit, but it does not speed up anything (tested with attrib).

For me, I have a workaround by using exec directly, since I have to attrib all files contained in a folder:

<exec executable="attrib" dir="${my.dir}" >
    <arg value="-R"/>
    <arg value="/S"/>
</exec>

The exec command takes 2 seconds, while the attrib-command for the same folder takes more than 9 Minutes.

Maybe, you could add some note to the doc of attrib...
Comment 13 paltzern 2013-07-16 08:12:04 UTC
I have an ANT-script that takes 37min instead of 2min because ist makes heavy use of exec.

Is there any workaround except using ANT 1.7 to obtain the 'old' performance?
Comment 14 paltzern 2013-08-27 08:41:46 UTC
Bug 54128 seems to address this issue more actively.
Comment 15 Stefan Bodewig 2013-12-21 19:53:33 UTC

*** This bug has been marked as a duplicate of bug 54128 ***