Test case? Measurements?

I am using 6.7 M3 JavaSE download option. For example, the same build I can run at 6.5, console and 6.7.

6.5: BUILD SUCCESSFUL (total time: 2 minutes 47 seconds)
console: Total time: 2 minutes 58 seconds
6.7: BUILD SUCCESSFUL (total time: 9 minutes 36 seconds)

Any ant script I run, I can see it is really slower. All this times I sent, I just closed and reopened the IDE and run
the most large task I have. Thew console in 6.7 is slower, the things are printed slowly, in 6.5 it is hard to read what
is printed. What kind of info you need?

Regards

Running on JDK 6 / Ubuntu I can reproduce a modest slowdown (roughly 42 -> 49 seconds) between 6.5 and 090406-dev
running nbbuild/build.xml#build-platform second and subsequent times (i.e. everything compiled and up to date). Possibly
due to output window colorizing.

Created attachment 79679 [details]
Output text from build

Looks like an unusually verbose build. Might be able to see contrast more clearly (e.g. for use by a profiler) when
changing Ant logging level to Verbose or Debug.

Created attachment 79683 [details]
Execution log using ant degub mode

Created attachment 79684 [details]
Execution log using ant quit mode

There is no relevant difference between ant tasks execution times in any mode, even in Normal, Debug or Quiet

If it's still slow in "Quiet" mode then your problem is likely different from what I reproduced, and we would certainly
need a complete, self-contained test case to reproduce - or a profiler snapshot (ideally with 6.5 times subtracted).

> There is no relevant difference between ant tasks execution times in any mode, even in Normal, Debug or Quiet.

All of these take same amount of time? Reassigning to performance for some measurements. Output would be innocent in
this case.

> All of these take same amount of time? Reassigning to performance for some measurements. Output would be innocent in
> this case.

Yes, all builds take something close to 10 minutes in 6.7, and less than 3 minutes for 6.5 and console ant execution.

I compared performance of OW in 6.5.1 and trunk version and I do not see any significant difference. Also I checked
perf. difference when colorized output is used and it was OK too (100k color lines written to OW took 2.8s instead of 2.6s).

Just to be clear, I am sure the problem is not about OW coloring. I have the same times even when running ant with
different debug levels. I will send an test case as soon as I can create one, since my project is really huge.

Obviously we would prefer not to get a 50Mb ZIP of your whole project (even assuming there is nothing proprietary in it
and you could do so). It is possible that there is some particular task that your build script runs which is much slower
in 6.7 for some reason, and identifying it could lead to a small and easily analyzed test case. A profiler may help
identify this task.

Also be sure to check running heap usage - if different _default_ max heap settings cause 6.7 to run close to max heap,
and your build involves some steps which reference a lot of heap at once, NB will spend a lot of time in GC. A healthy
JVM process will evenly consume its available heap, collect at least half of it, then start over; this characteristic
"saw" pattern can be seen in Visual VM or similar tools.

XDoclet tasks run slowly and any task except javac that generates .class files is also slow.

BTW, on my machine, builds also run 5 times slower (from 8 min to 40 min).

@misterm: could you attach a small example project that we can look at to clearly see the difference between 6.5 and 6.7?

I have an "small" sample where we can see this difference, but this sample have 20 mb... Do you have any idea where can
I attach it since here is not possible?

I attached test case [1]. To test it, you will need the JBoss too, both 3.2.X or 4.2.X should work.
To test it, go to genesis-all-3.1/samples/useradmin and build using clean-webstart target for build.xml build file. The
build should be different for 6.5 and 6.7, here I have difference larger than one minute.
The basic difference about this sample and our project is that we have a lot of files to be weaved, as you can see at
attached log files. As misterm says, xdoclet targets seen to be the problem.

Regards
[1] http://performance.netbeans.org/files/documents/66/2464/genesis-all-3.1.zip

Created attachment 80380 [details]
Ant slowness demo

Steps to reproduce:

- Extract ant_slowness.zip;
- Use Resolve References to point to ant.jar in your NB checkout;
- Run ant-slowness in NB 6.5 and 6.7.

Our results:
Windows XP - 43 sec vs 1:47min
Ubuntu 8.04 - 3 sec vs 21 sec

It seems using ClassLoader.getResourceAsStream(String) from an Ant task is as slow as a turtle :-)

BTW project.properties in demo should have:

javac.classpath=${ant.core.lib}

I can reproduce a slowdown with this project. It seems a somewhat pathological case but valid. No idea yet what the
difference between 6.5 and 6.7 would be here.


BTW the task is also wrong:

      final FileSet fileSet = new FileSet();
      fileSet.setDir(parent);
      path.addFileset(fileSet);

should be

      path.createPathElement().setLocation(parent);

Notice running it from the command line with the Ant release bundled with NetBeans main produces no slowdown.

Also, don't take the test case so literally; several tasks that generate files have more or less the same pattern: read 
several resources from the classpath and spits a couple of thousands of files. These include XDoclet tasks, weaving 
tasks from AOP frameworks, retroweaving tools etc.

I have to take the test case literally - it's the only one I have. I can see that, for example, cl.getResource(name) is
slower in 6.7 than in 6.5. If something else is slower as well, then I need a separate test case.

Sorry for the confusion. What I mean is all the tasks types I mentioned read thousands of resources and spits thousands 
of files. So that's how I got to this task.

I have a project with all these kinds of tasks, so I am just telling all of them are affected because they follow this 
pattern.

The only difference is they don't read files they have just generated; instead, they read files generated from previous 
tasks.

Have not managed to get any useful information from the Profiler; reports self times, but for a quick method called
>2000x this is pretty skewed. Taking random thread dumps seems to work much better; most of them look like this:

        at java.io.UnixFileSystem.canonicalize0(Native Method)
        at java.io.UnixFileSystem.canonicalize(UnixFileSystem.java:157)
        at java.io.File.getCanonicalPath(File.java:531)
        at java.io.FilePermission$1.run(FilePermission.java:218)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.io.FilePermission.init(FilePermission.java:212)
        at java.io.FilePermission.<init>(FilePermission.java:264)
        at sun.net.www.protocol.file.FileURLConnection.getPermission(FileURLConnection.java:198)
        at sun.net.www.protocol.jar.JarURLConnection.getPermission(JarURLConnection.java:79)
        at sun.misc.URLClassPath.check(URLClassPath.java:398)
        at sun.misc.URLClassPath$Loader.findResource(URLClassPath.java:456)
        at sun.misc.URLClassPath.findResource(URLClassPath.java:142)
        at java.net.URLClassLoader$2.run(URLClassLoader.java:362)
        at java.security.AccessController.doPrivileged(Native Method)
        at java.net.URLClassLoader.findResource(URLClassLoader.java:359)
        at java.lang.ClassLoader.getResource(ClassLoader.java:977)
        at org.apache.tools.ant.module.bridge.AntBridge$AllPermissionURLClassLoader.getResource(AntBridge.java:582)
        at org.apache.tools.ant.AntClassLoader.getResource(AntClassLoader.java:920)
        at br.com.summa.netbeans.ant.test.FileGenerator.execute(FileGenerator.java:52)

The only logical answer for that is that, somehow, in NB 6.7, there is a lot more visible to AntClassLoader than in the 
other environments (NB 6.5 and command line). That's why it takes so much longers.

The only logical answer for that is that, somehow, in NB 6.7, there is a lot more visible to AntClassLoader than in the 
other environments (NB 6.5 and command line). That's why it takes so much longer.

In fact there is a little bit _less_ in 6.7, since platform*/lib/*.jar are no longer visible.

My current guess is that some changes in JAR handling in 6.5 were partially reverted to the "natural" state in 6.7, and
the JRE's jar: protocol handler is just slow when a security manager is present.

Obscure bug in URLClassLoader, as it turns out. core-main #48a20db39cca

Integrated into 'main-golden', will be available in build *200904201507* on http://bits.netbeans.org/dev/nightly/ (upload may still be in progress)
Changeset: http://hg.netbeans.org/main-golden/rev/48a20db39cca
User: Jesse Glick <jglick@netbeans.org>
Log: #162158: performance problem in URLClassLoader when passing jar:...!/ URLs.

Now... 'BUILD SUCCESSFUL (total time: 2 minutes 27 seconds)'
:-D

v. 200904220201