How to tell if Spock is actually executing tests in parallel

Question

We have some API integration tests that take ~30 minutes to run a test class with 19 rows in the where: table. We're trying to speed this up using Spock's (experimental) Parellel Execution feature. We are using a simple SpockConfig.groovy file:

runner {
    parallel {
        enabled true
        fixed(4)
    }
}

This still took ~30 minutes on a GitLab runner. Is there any way to log something out so we can verify that the test is running in parallel? Or am I misunderstanding the nature of Spock's parallelization?

Answer 1

You can parallelise Spock testing on several levels, i.e. per specification (test class) or per feature (test method). The per-method setting also means that in iterated (unrolled) tests, iterations can run in parallel. Here is some proof:

import static org.spockframework.runtime.model.parallel.ExecutionMode.CONCURRENT

runner {
  parallel {
    enabled true
    // These values are the default already, specifying them is redundant
    // defaultSpecificationExecutionMode = CONCURRENT
    // defaultExecutionMode = CONCURRENT
    fixed 4
  }
}

package de.scrum_master.testing

import spock.lang.Specification

import static java.lang.System.currentTimeMillis
import static java.lang.Thread.currentThread

class ParallelExecutionTest extends Specification {
  static long startTime = currentTimeMillis()
  static volatile int execCount = 0

  def "feature-A-#count"() {
    given:
    def i = ++execCount
    printf "%5d %2d [%s] >> %s%n", currentTimeMillis() - startTime, i, currentThread().name, specificationContext.currentIteration.displayName
    sleep 1000
    printf "%5d %2d [%s] << %s%n", currentTimeMillis() - startTime, i, currentThread().name, specificationContext.currentIteration.displayName

    where:
    count << (1..8)
  }

  def "feature-B-#count"() {
    given:
    def i = ++execCount
    printf "%5d %2d [%s] >> %s%n", currentTimeMillis() - startTime, i, currentThread().name, specificationContext.currentIteration.displayName
    sleep 1000
    printf "%5d %2d [%s] << %s%n", currentTimeMillis() - startTime, i, currentThread().name, specificationContext.currentIteration.displayName

    where:
    count << (1..8)
  }
}

The output would look something like this (I used the volatile variable in order to more easily sort the log output in my editor into groups of threads running simultaneously in groups of 4:

   68  1 [ForkJoinPool-1-worker-3] >> feature-B-1
   68  2 [ForkJoinPool-1-worker-2] >> feature-A-5
   68  3 [ForkJoinPool-1-worker-1] >> feature-B-6
   68  4 [ForkJoinPool-1-worker-4] >> feature-B-2
 1177  1 [ForkJoinPool-1-worker-3] << feature-B-1
 1177  3 [ForkJoinPool-1-worker-1] << feature-B-6
 1179  4 [ForkJoinPool-1-worker-4] << feature-B-2
 1180  2 [ForkJoinPool-1-worker-2] << feature-A-5

 1191  5 [ForkJoinPool-1-worker-3] >> feature-B-3
 1199  6 [ForkJoinPool-1-worker-4] >> feature-B-4
 1200  7 [ForkJoinPool-1-worker-1] >> feature-B-5
 1204  8 [ForkJoinPool-1-worker-2] >> feature-A-6
 2199  5 [ForkJoinPool-1-worker-3] << feature-B-3
 2205  7 [ForkJoinPool-1-worker-1] << feature-B-5
 2213  6 [ForkJoinPool-1-worker-4] << feature-B-4
 2213  8 [ForkJoinPool-1-worker-2] << feature-A-6

 2203  9 [ForkJoinPool-1-worker-3] >> feature-B-7
 2207 10 [ForkJoinPool-1-worker-1] >> feature-A-1
 2217 11 [ForkJoinPool-1-worker-4] >> feature-B-8
 2222 12 [ForkJoinPool-1-worker-2] >> feature-A-8
 3205  9 [ForkJoinPool-1-worker-3] << feature-B-7
 3213 10 [ForkJoinPool-1-worker-1] << feature-A-1
 3229 12 [ForkJoinPool-1-worker-2] << feature-A-8
 3230 11 [ForkJoinPool-1-worker-4] << feature-B-8

 3208 13 [ForkJoinPool-1-worker-3] >> feature-A-2
 3216 14 [ForkJoinPool-1-worker-1] >> feature-A-3
 3234 15 [ForkJoinPool-1-worker-4] >> feature-A-4
 3237 16 [ForkJoinPool-1-worker-2] >> feature-A-7
 4214 13 [ForkJoinPool-1-worker-3] << feature-A-2
 4230 14 [ForkJoinPool-1-worker-1] << feature-A-3
 4245 15 [ForkJoinPool-1-worker-4] << feature-A-4
 4245 16 [ForkJoinPool-1-worker-2] << feature-A-7

As you can clearly see, with your own settings you can expect that multiple features and even multiple iterations in your spec run concurrently. If in your case the concurrent iterations take as long to finish as running the test sequentially, it could mean that those tests spend a lot of time using a shared resource which is synchronised or in some other way can only be used by one caller at the same time. So probably not Spock is the problem here, but the shared resource or the way you synchronise on it.