Bug 54128

I have an ANT build.xml that perform <exec> task for 400++ times.  The job use about 84 seconds in Ant 1.7.1.

I perform the same task in Ant 1.8.4 and it use 227 seconds.

I then patch my ANT 1.8.4 with your diff patch and now it takes 99 seconds to finish the job.  There is still a significant 17% increase of time in seconds to finish the job compare to ANT 1.7.1.  Is that possible to further optimize?

Thank you.

This problem doesn't fix in version 1.9.0

The patch doesn't seems to fix all the speed issue in ANT 1.8.

An exec task with redirector and outputfilterchain perform badly in ANT 1.8 even the patch has applied:

<exec executable="${p.tdump.bat}" failonerror="false">
  <redirector output="${p.file.bpl}" append="true">
    <outputfilterchain>
      <headfilter lines="-1" skip="2" />
      <linecontainsregexp>
        <regexp pattern="^IMPORT:"/>
      </linecontainsregexp>

      <replacestring from="IMPORT:" />
      <tokenfilter delimoutput=" ">
        <StringTokenizer />
      </tokenfilter>
    </outputfilterchain>
  </redirector>
</exec>

This also appears to affect the symlink task.

I have builds using repeated symlink invocations to link reasonably sized (10s-100s) collections of files - with Ant 1.7 this is almost instantaneous, but with Ant 1.9.2 there is a large pause (~300 ms per invocation, which adds up quickly).

Created attachment 30720 [details]
Alternative patch to speed up exec

I've attached an alternative fix, which addresses the core problem of the PumpStreamHandler blindly joining the StreamPumper thread for 200ms without signalling it to exit.
StreamPumper is also changed to drain available output on finish, which is required when it is in 'use available' mode as fast executing tasks will most often exit before the output is read.

A fixed tree is also available at https://github.com/orionhealth/ant/tree/features/fast-exec.

Created attachment 30721 [details]
Alternative patch to speed up exec

I've updated my fix to correct a problem with dropping data blocks if the stream pumper was stopped between reading and writing a block.

Also fixed a race condition observed in testing where the stream pumper is stopped before the thread running it enters the run() method, which can cause hanging/require interruption.

Any chance that this patch is reviewed and merged? I tested it on some builds which use apply tasks a lot, and reduced build times from several minutes to several seconds...

this looks interesting.

I have applied the patch supplied by Tim Whittington and yes, it has a dramatic effect. On my Mac I have been able to run 100 exec invocations of "ls" in 1 second with your patch as opposed to  41 seconds before. Well done ! The code is checked in in ant trunk and will be part of the release when someone creates Ant 1.9.3

Awesome! Thank you Tim and Antoine! I'm looking forward to be fast again! :-)

*** Bug 50229 has been marked as a duplicate of this bug. ***

*** Bug 51387 has been marked as a duplicate of this bug. ***

*** Bug 48734 has been marked as a duplicate of this bug. ***

*** Bug 49384 has been marked as a duplicate of this bug. ***

I tested exec in the release 1.9.3 and unfortunately there is no speed up for me!

I could reduce the problem to one single (sic!) exec-call that produces a lot of logging-output (about 10'000'000 chars in about 24'000 lines).

This exec-call takes 10 seconds with 1.7.1 and 210 seconds with 1.9.3.

On which operating system, and with which JDK are you observing that slow behavior ?

Win 7 Prof SP 1 and JDK 1.7.0_40-b43.

I created this build file to test :
<project name="doit">
<echo>ant.version=${ant.version}</echo>
 <script language="javascript"> <![CDATA[

      for (i=1; i<=1000; i++) {
        exec = doit.createTask("exec");
        exec.setExecutable("attrib");
        exec.createArg().setValue("-r");
        exec.createArg().setValue("doit.xml");
        exec.perform();
      }

    ]]> </script>

</project>

---
I ran the build file on Windows 7 with JDK 1.7 using this script :
export ANT_HOME=c:/opt/apache-ant-1.7.1
ant -f doit.xml
export ANT_HOME=c:/opt/apache-ant-1.9.2
ant -f doit.xml
export ANT_HOME=c:/opt/apache-ant-1.9.3
ant -f doit.xml
----
here is the output :

$ ./doit.sh
Buildfile: doit.xml
     [echo] ant.version=Apache Ant version 1.7.1 compiled on June 27 2008

BUILD SUCCESSFUL
Total time: 8 minutes 6 seconds
Buildfile: C:\dev\54128\doit.xml
     [echo] ant.version=Apache Ant(TM) version 1.9.2 compiled on July 8 2013

BUILD SUCCESSFUL
Total time: 14 minutes 50 seconds
Buildfile: C:\dev\54128\doit.xml
     [echo] ant.version=Apache Ant(TM) version 1.9.3 compiled on December 23 2013

BUILD SUCCESSFUL
Total time: 8 minutes 5 seconds

The test build file as you can see runs 1000 times attrib on a single file.
The performance of Ant 1.7.1 and Ant 1.9.3 in this test are the same, Ant 1.9.2 is much slower.

Is there something specific to the command that you are running which is such that it is slow under Ant 1.9.3 ? Did you set ANT_HOME to point to the installation of Ant 1.9.3 when you tested it ?

Thank you for looking into this again.

I can confirm the results of your test.

I modified it to the following:

<project name="doit" >
  <echo>ant.version=${ant.version}</echo>

  <exec executable="cmd" dir="c:\">
    <arg value="/c" />
    <arg value="test.bat" />
  </exec>
</project>

test.bat just produces a lot of output (10'000 lines with 1'000 chars each) and containts the following:
@for /L %%i IN (1 1 10000) do @echo 1234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890123456789012345678901234567890



The results:

     [echo] ant.version=Apache Ant version 1.7.1 compiled on June 27 2008
[...]
BUILD SUCCESSFUL
Total time: 1 second


     [echo] ant.version=Apache Ant(TM) version 1.9.2 compiled on July 8 2013
[...]
BUILD SUCCESSFUL
Total time: 38 seconds


     [echo] ant.version=Apache Ant(TM) version 1.9.3 compiled on December 23 2013
[...]
BUILD SUCCESSFUL
Total time: 37 seconds


Here, the performance fo 1.9.2 and 1.9.3 are the same and 1.7.1 is much faster!

See Bug 50229, which is the single exec with a lot of output use case.

I'm still stuck with Ant 1.7.1 because of this issue.

So should I reopen Bug 50229?

I've tested all 3 of the test projects on this issue and Bug 50229:
1. 'doit' with repeated calls to attrib
2. 'doit' calling a batch file that produces large amounts of output
3. 'test' that uses cat to pipe a large (40MB) file from stdin to stdout

All 3 test projects were run on:
- Mac OS X Mavericks with Java 1.7.0_51
- Windows 7 Enterprise SP1 in a VMware Fusion VM with Java 1.7.0_51

(There were obviously local adaptations for the execs).

All 3 test projects were run with the following versions of Ant:
- 1.7.1
- 1.9.2 with my patch applied
- 1.9.3
- 1.9.4beta (built from trunk)

All of the tested Ant versions had comparable (to within a second or two) execution times on all of the test projects.

(In reply to paltzern from comment #19)

> 
> The results:
> 
>      [echo] ant.version=Apache Ant version 1.7.1 compiled on June 27 2008
> [...]
> BUILD SUCCESSFUL
> Total time: 1 second
> 
> 
>      [echo] ant.version=Apache Ant(TM) version 1.9.2 compiled on July 8 2013
> [...]
> BUILD SUCCESSFUL
> Total time: 38 seconds
> 
> 
>      [echo] ant.version=Apache Ant(TM) version 1.9.3 compiled on December 23
> 2013
> [...]
> BUILD SUCCESSFUL
> Total time: 37 seconds
> 
> 
> Here, the performance fo 1.9.2 and 1.9.3 are the same and 1.7.1 is much
> faster!


The Ant 1.7.1 result here looks anomalous - in my OS X and Windows 7 environment this test takes about 20 seconds on 1.7.1 and 1.9.3.

If the result is piped to a file this goes down to about 3 seconds (limited mainly by I/O).

Writing that output file to the console in Windows (type fu.txt) takes about as long as the execution with Ant, indicating that the execution time is dominated by console output time. 

It seems implausible for the entire test to execute in 1 second, bettering the execution time of the 'type' command.

(In reply to Antoine Levy-Lambert from comment #18)
> here is the output :
> 
> $ ./doit.sh
> Buildfile: doit.xml
>      [echo] ant.version=Apache Ant version 1.7.1 compiled on June 27 2008
> 
> BUILD SUCCESSFUL
> Total time: 8 minutes 6 seconds
> Buildfile: C:\dev\54128\doit.xml
>      [echo] ant.version=Apache Ant(TM) version 1.9.2 compiled on July 8 2013
> 
> BUILD SUCCESSFUL
> Total time: 14 minutes 50 seconds
> Buildfile: C:\dev\54128\doit.xml
>      [echo] ant.version=Apache Ant(TM) version 1.9.3 compiled on December 23
> 2013
> 
> BUILD SUCCESSFUL
> Total time: 8 minutes 5 seconds

All of these times look anomalous - I get times of about 20 seconds on all versions in my Windows 7 environment, and these times indicate about 480ms per attrib execution on 1.7.1 which seems incredible.

Is it possible the loop count of the script was much higher when these timings were taken?

> It seems implausible for the entire test to execute in 1 second, bettering
> the execution time of the 'type' command.

Having said that, I can get the execution time down to about 2 seconds with Ant 1.7.1 by piping the output to a file or the NUL device.

With that approach Ant 1.7.1 is clearly faster (about 2 seconds) than 1.9.3+ (about 4 seconds) which I imagine will be the 100ms pause penalty applied in StreamPumper.waitForInput(InputStream) each time there is 0 bytes available (which is often the case after reading a line from STDIN).

Some experimentation reveals that reducing that pause time does speed up the 1.9.x execution, but if it's put too low the execution times ramp up a lot - it appears that there's a significant penalty to calling available() too much. The penalty isn't in calling available() (that takes about 10-20 microseconds on average), so it might some kind of contention.

Hi Tim,

thank you for doing more investigation on this issue!

I figured that the difference seems to be whether you run the script via Eclipse or Windows console!

I can observe the huge performance difference between ant 1.7.1 and the others only (sic!) when run with Eclipse (4.3.0).

With the Win7 console it takes as long as you state.

Any idea what could cause this strange behaviour and how to fix it?

(In reply to paltzern from comment #26)
> 
> I can observe the huge performance difference between ant 1.7.1 and the
> others only (sic!) when run with Eclipse (4.3.0).
> 
> With the Win7 console it takes as long as you state.
> 
> Any idea what could cause this strange behaviour and how to fix it?

The Eclipse console will slow down a lot if console output isn't limited and you try to output too much (which your test does).

I wonder if this issue can be re-resolved now.

In this case, the eclipse console speeds things up for 1.7.1!

Sorry, that my last comment didn't make that clear.

Here are the times for my doit-example on my machine:

        win console    eclipse console
1.7.1    42 seconds          1 second
1.9.2    43 seconds         38 seconds
1.9.3    43 seconds         37 seconds

And console output in eclipse is not limited!

Are there any new insights on this one?

A possible workaround?

Anything I can test to help you find the problem?

Tim's fix is confirmed working here.

If I had to guess I'd say paltzern's outlier time for 1.7.1 outputting to the Eclipse console (1 second compared to around 40 for every other case) is due to the fact that Tim Whittington's patch also fixed the problem of output getting dropped in a race when the process on the other side of the pipe does not consume it fast enough.

As the originator of the bug I am marking it as resolved in ant 1.9.3. Paltzern can open up another bug if he believes there is another problem.

As suggested I filed the new Bug 56487.

Any news on this issue with ANT 1.10.2 release?  Is is fix?  Do we need to apply the patch too?

Marking verified as of ant 1.9.3, several years ago now.  The fix worked.

I am trying the 1.10.2 release without applying any fix.  It happen again, very slow in exec task.

Please file a new bug then instead of spamming my email inbox with your comments on a bug that I consider to have been resolved over 4 years ago.

The issue I reported was fixed.  If you are still having problems that is a different issue.