Slow run times since RC16

[hutchy2570]

First a bit of background. We have a suite of acceptance tests which use Cucumber-jvm to test a set of endpoints using rest requests. We have 42 Features, with 1302 Scenarios and 6465 steps executed per run. Of these around 75% are from Scenario Outlines with Examples tables. We started using Cucumber-jvm at 1.0.0.RC13 after previously using cuke4duke. A full run of the tests in RC13 took around 12 minutes. When we switched to RC16 this jumped to over 30 minutes, and hasn't improved with RC20.

We run cucumber-jvm from the cli using the Maven Exec plugin during the integration-test phase. Here is an example of our configuration:

          <plugin>
            <groupId>org.codehaus.mojo</groupId>
            <artifactId>exec-maven-plugin</artifactId>
            <version>1.2.1</version>
            <executions>
              <execution>
                <phase>integration-test</phase>
                <goals>
                  <goal>exec</goal>
                </goals>
                <configuration>
                  <executable>java</executable>
                  <arguments>
                    <argument>-Denv=${env}</argument>
                    <argument>-classpath</argument>
                    <classpath />
                    <argument>cucumber.cli.Main</argument>
                    <argument>${project.basedir}/target/classes/features/released</argument>
                    <argument>--glue</argument>
                    <argument>com.project.test.acceptance</argument>
                    <argument>--format</argument>
                    <argument>pretty</argument>
                    <argument>--format</argument>
                    <argument>json-pretty</argument>
                    <argument>--out</argument>
                    <argument>${project.basedir}/target/result.json</argument>
                    <argument>--tags</argument>
                    <argument>~@wip</argument>
                    <argument>--tags</argument>
                    <argument>~@broken</argument>
                    <argument>--tags</argument>
                    <argument>~@broken-${env}</argument>
                    <argument>--tags</argument>
                    <argument>~@ignore</argument>
                    <argument>--tags</argument>
                    <argument>~@deferred</argument>
                  </arguments>
                </configuration>
              </execution>
            </executions>
          </plugin>

We've done some investigation and tried runs with every release since RC13 and the change happens between RC15 and RC16.

RC13: 12 minutes
RC14: 11 minutes
RC15: 12 minutes
RC16: 32 minutes
RC20: 32 minutes

Watching the console output there doesn't seem to be any difference in the speed of individual Steps executing, but there does appear to be a significant delay before/after executing a Scenario.

These runs were performed on a Win7 x64 laptop with a Core 2 Duo T9400 with 4gb of RAM and running Java 64bit:
version "1.6.0_29"
Java(TM) SE Runtime Environment (build 1.6.0_29-b11)
Java HotSpot(TM) Client VM (build 20.4-b02, mixed mode, sharing)

[aslakhellesoy]

What cucumber-jvm modules are you using? cucumber-spring? Could this be related to the comments at the bottom of #203?

[hutchy2570]

We are using cucumber-spring with the following cucumber.xml

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:jee="http://www.springframework.org/schema/jee"
  xmlns:context="http://www.springframework.org/schema/context"
  xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
                      http://www.springframework.org/schema/jee http://www.springframework.org/schema/jee/spring-jee-3.0.xsd
                      http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd">

  <context:component-scan base-package="com.project.test.acceptance" />

  <import resource="classpath:cucumber-context.xml"/>

</beans>

cucumber-context.xml defines a number of beans that encapsulate the rest interaction (SimpleClientHttpRequestFactory & 2 RestTemplates) and a PropertyPlaceholderConfigurer. We also have a couple of beans marked @component which deal with loading fixture data from json files.

[aslakhellesoy]

Ok, the regression was probably introduced by #203 by @vladimirkl that went into 1.0.0.RC16.

I don't use Spring, and I don't know it well enough to fix this. /cc @hutchy2570 @TeDDaN, @ConradMueller @vladimirkl

[vladimirkl]

@hutchy2570, I need a good testcase that shows this regression. My tests do not show any significant delay in glue code context creation speed. Also you can see to spring log output before each scenario - this may show where it is hanging

[hutchy2570]

I can confirm the problem must be in cucumber-spring. I've tried a run with core & java at RC16 with spring at RC15 and it runs the full suite in 12 minutes.

It looks like the changes in RC16 load a new cucumber-glue.xml context before every scenario. This context performs a context:annotation-config scan every time it's loaded which introduces a slight delay before each scenario. Multiply this delay over 1300 scenarios and you get a significant slowdown.

[vladimirkl]

Ok. So may be additional post processors in context:annotation-config introduce this. And we either pay this price for all spring features available for glue code or find some other way. What if we register glue code classes once as prototype beans in single context? And we do not create child context for each scenario. @ConradMueller, what do you think?

[hutchy2570]

See the logs here https://gist.github.com/1958007

Notice the XmlBeanDefinitionReader in the RC20 log. This is what causes the delay.

[vladimirkl]

@hutchy2570 , please test performance with my pull request. I've implemented custom scope for glue code beans - so that they registered only at all features startup

[hutchy2570]

I have tested the performance with pull request #242.

A full run took 9 minutes, which is a great improvement over RC15.

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.