Attached basic test case that shows issue.

Steps:

• Load welcomeICEfaces.jsf
• PhaseListener logging shows the time taken in the render response (8 - 12 sec)

Support Case #11826

ICEfaces 3.2.0 jar file

Times after tomcat restart:

curl http://localhost:8080/ 0.01s user 0.01s system 78% cpu 0.023 total

curl http://localhost:8080/Case11826Example3/ 0.01s user 0.01s system 1% cpu 1.088 total
Time taken by phase id --> RESTORE_VIEW 1 in MS. 94
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 767

curl http://localhost:8080/Case11826Example3/ 0.01s user 0.01s system 43% cpu 0.042 total
Time taken by phase id --> RESTORE_VIEW 1 in MS. 1
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 17

with ICEfaces 3.2:

curl http://localhost:8080/ 0.01s user 0.01s system 79% cpu 0.022 total

curl http://localhost:8080/Case11826Example3/ 0.01s user 0.01s system 1% cpu 1.605 total

Time taken by phase id --> RESTORE_VIEW 1 in MS. 90
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1233

SEVERE: Error Rendering View[/index.xhtml]
java.lang.IllegalStateException: Component ID vaneyub2-retrieve-update has already been found in the view.

curl http://localhost:8080/Case11826Example3/ 0.01s user 0.01s system 26% cpu 0.068 total

Time taken by phase id --> RESTORE_VIEW 1 in MS. 2
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 29

SEVERE: Error Rendering View[/index.xhtml]
java.lang.IllegalStateException: Component ID vaneyub4-retrieve-update has already been found in the view.

So it is not possible to compare the earlier performance due to the Exception, however the time for the new .jar is less, which is opposite to the performance indicated by the customer.

This issue may be specific to when the server is running on a windows host. If two running .war files are included for time comparison, this could be tested further.

Attached two war files that use 3.2.0 and 3.2.0 EE jars. The error may have been caused by using a mix of EE and Open Source jars.

From your testing, do you still believe this is a bug? For instance, when you tested without the .jar mixture, did you still see the problem?

I'm actually not sure if this is a bug or expected behavior due to some changes/enhancements. If this is the expected behavior then it would be good to know why so this information can be passed onto the customer.

I just tested both sets of jars/wars with the following results:

ICEfaces 3.2.0:

Time taken by phase id --> RESTORE_VIEW 1 in MS. 267
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1236

ICEfaces EE 3.2.0:

Time taken by phase id --> RESTORE_VIEW 1 in MS. 253
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 9108

I first tested with the 3.2.0 jars. Shut down the server. Changed the libraries to EE 3.2.0(all jars are from the same release bundle). Cleaned and Built the war. Started up the server/deployed the war.

Just tried this on my Windows machine. Used a clean browser and Tomcat7 instance each time I tested (tested twice for each ICEfaces version).

ICEfaces 3.2.0 EE (Test One)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 109
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 4183

ICEfaces 3.2.0 (Test One)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 140
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 655

ICEfaces 3.2.0 EE (Test Two)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 109
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 3557

ICEfaces 3.2.0 (Test Two)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 156
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 749

This is definitely consistent with the customer-reported issue. It should be tested on MacOS or linux to see if there is an operating system dependency. (It looks likely at this point that the test I performed on MacOS X was not valid due to .jar conflict or otherwise corrupted application.)

Mac OS X 10.7.5
Tomcat 7.0.23
Chrome 26.0.1410.43

In-between runs I shutdown / clearing of tomcat, browsed to about:blank and did a "Clear Browser Data" in Chrome.
My computer uses an SSD instead of a hard drive.

ICEfaces 3.2.0 (Test 1)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 111
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1114

ICEfaces 3.2.0 (Test 2)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 95
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 872

ICEfaces 3.2.0 (Test 3)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 41
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1541

—

ICEfaces 3.2.0 EE (Test 1)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 43
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 2219

ICEfaces 3.2.0 EE (Test 2)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 66
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1015

ICEfaces 3.2.0 EE (Test 3)
Time taken by phase id --> RESTORE_VIEW 1 in MS. 64
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1604

Mircea, is there part of resource ordering that might lead to a large amount of disk activity?

I do not believe there is. Resource ordering is reading a few resource-dependency.xml files that is all. They are already available in the classpath.

Test 1

trunk non-EE - loaded first
Time taken by phase id --> RESTORE_VIEW 1 in MS. 92
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 3515

trunk EE - loaded second
Time taken by phase id --> RESTORE_VIEW 1 in MS. 74
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 2225
----------
Test 2

trunk EE - loaded first
Time taken by phase id --> RESTORE_VIEW 1 in MS. 69
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 2554

trunk non-EE - loaded second
Time taken by phase id --> RESTORE_VIEW 1 in MS. 63
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1905
----------
Test 3

trunk non-EE - loaded first
Time taken by phase id --> RESTORE_VIEW 1 in MS. 70
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 2091

trunk EE - loaded second
Time taken by phase id --> RESTORE_VIEW 1 in MS. 68
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1871
----------
Test 4

trunk EE - loaded first
Time taken by phase id --> RESTORE_VIEW 1 in MS. 69
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 2190

trunk non-EE - loaded second
Time taken by phase id --> RESTORE_VIEW 1 in MS. 84
Time taken by phase id --> RENDER_RESPONSE 6 in MS. 1953
-----------

As you can see from the results above there is no difference for the execution time between the EE and non-EE versions. The only thing that seems to matter is the order in which the applications are accessed. Every time the application accessed first will run ~150ms slower then the second one. Most probably difference is due to classloading, the second app class loader does not need to load so many classes and resources anymore.

The application server was restarted before each test was executed.

Also ran YourKit profiler with both applications and could not detect any significant differences between them. The profiling results show that the majority of CPU time is used for loading the resources (the mandatory ones).