[Wtr-general] Extreme slowdown moving from 1.4.1 to 1.5.1.1127

[Bret Pettichord]

Pat Mac wrote:
>
> Hi All, I've read through the archives I could find relating to 
> performance issues related to 1.5 but I didn't see any concrete 
> solutions or reasons why the slowdown is occurring. Running an 
> existing script using the profiler my execution time goes from 170 
> seconds to 425 seconds. Looking at the profiler output I notice the 
> following:
>
> WIN32OLE#each is the top consumer in both profiles. In 1.5 it's taking 
> 70.15 seconds vs 59.19 in 1.4. Not a huge jump, but noticeable when 
> running 100+ cases.
>
> WIN32OLE#invoke is the number 2 consumer in both profiles taking 64.85 
> seconds in 1.5 but only 25.69 seconds in 1.4. This is obviously quite 
> significant.
>
> Beyond the top two, the next highest in 1.4 is Logger#add taking just 
> over 12 seconds. However, in 1.5 I see seven additional methods taking 
> 20 seconds or longer. The biggest hogs are Watir::Element#type at 
> 62.64 seconds, Class#new at 42.49 seconds, 
> Watir::Element#assert_exists at 41.68 seconds and Array#include? at 
> 39.47 seconds.
>
> I'm at a loss here. I'm running these tests on the same machine with 
> the same version of Ruby. I originally wanted to upgrade for the 
> click_no_wait functionality and modal dialog functionality but I can't 
> take this kind of a performance hit. Is there something obvious I'm 
> missing? I did notice the slowdown appears to be significant on pages 
> with lots of controls. At this point I'm probably going to backport 
> the click_no_wait and modal dialog functionality to 1.4.1 unless 
> anyone has an idea of what I'm doing wrong here.
>
Pat,

Thank you for your detailed report.

You raise many valid issues in your email. But first, i must ask about 
your numbers. You say your suite takes 140 seconds with 1.4 but 425 
seconds with 1.5. Is this elapsed time or cpu time?

Pat, you probably know this, but let me elaborate for the benefit of 
those reading on. Elapsed time is "human time" and is what is reported 
by test-unit. CPU time only counts time where the CPU is running 
Watir/Ruby code. I have found that most of the elapsed time running 
tests is taken up waiting for pages to load. Yet this time is not logged 
by the profiler.

I have periodically tuned both Watir and my test suites to improve 
performance. For example, Watir 1.4 includes performance improvements to 
both CPU time and elapsed time, although your figures suggest the CPU 
time improvements have been offset by other additions. One of the Watir 
performance improvements was simply to reduce some of the polling 
intervals. These actually had a fairly dramatic impact on the time it 
took to run our unit test suite. By polling for page load completion 
more frequently, we are likely to shave time off the elapsed wait time, 
but we do increase the CPU time because of the increased number of calls 
that are made while we are waiting. Users will see this as an 
improvement although it will lead the profiler to report that various 
calls consume more CPU time.

Some simple things you can do to improve your tests performance is to 
use fast mode, and to look into using TextField.value= instead of 
TextField.set.

I'm willing to look more closely into the facts you present, but my 
experience has been that this is not the best place to start. An 
additional complication for discussing this matter is that we are 
comparing our experiences running different, non-public test suites. 
What we really need is a public test suite for a non-trivial 
application. Hmm. Maybe we should look at the Instiki test suite...

Bret