Tests generated by the ios_unit_test target take very long time to run

[acecilia]

Hello:

I am making a sample repository for bazel, in order to see if it will fit my needs for ios development.

In order to create a test target for a swift library I am using ios_unit_test, and doing the following:

def swift_test_interface(
    name,
    srcs,
    deps,
    ):
    test_lib_name = name + "Lib"

    swift_library(
        name = test_lib_name,
        srcs = srcs,
        deps = deps,
    )

    ios_unit_test(
        name = name,
        deps = [":" + test_lib_name],
        minimum_os_version = "10.0",
    )

When running unit tests for swift libraries:

Expectation: they run in the order of ms .
Reality: they are taking usually 15 seconds to run, or even more.

You can see this in CI here:

• https://dev.azure.com/acecilia/BazelVSBuckSample/_build/results?buildId=31&view=logs&jobId=12f1170f-54f2-53f3-20dd-22fc7dff55f9&taskId=59a85588-b0ba-5043-24c4-d9e29d89c6f6&lineStart=112&lineEnd=113&colStart=1&colEnd=89: the two tests I am executing are taking 19.2 and 21.5 seconds to run.

The source code is here: https://github.com/acecilia/BazelVSBuckSample

I already tried to find a similar problem in the issues in this repository, and in the bazel github repository. The only issue that I could find that may be related to this is bazelbuild/bazel#2985 (comment).

Any idea why those tests are taking so long?

Thanks!

[keith]

If you pass --test_output=all you can see the output even though these tests pass which might help you figure out why. Note when running tests rules_apple creates a simulator for each test bundle, which causes some overhead

[acecilia]

Thanks for your hint @keith, I tried the flag. The result is as follows:

INFO: Analyzed 9 targets (0 packages loaded, 0 targets configured).
INFO: Found 7 targets and 2 test targets...
INFO: From Testing //Libraries/SwiftWithTests:SwiftWithTestsTargetTests:
==================== Test output for //Libraries/SwiftWithTests:SwiftWithTestsTargetTests:
2019-09-16 16:20:50,370 Will consider the test as test type logic_test to run.
2019-09-16 16:20:50,638 Failed to import biplist module. Will use tool /usr/libexec/PlistBuddy to handle the binary format plist.
2019-09-16 16:20:50,824 Failed to import biplist module. Will use tool /usr/libexec/PlistBuddy to handle the binary format plist.
2019-09-16 16:20:50,827 Creating a new simulator:
Name: New-iPhone Xʀ-12.4
OS: iOS 12.4
Type: iPhone Xʀ
2019-09-16 16:20:51,025 Created new simulator C1280F9E-2600-400F-AA33-11F8F3601E0F.
Test Suite 'All tests' started at 2019-09-16 18:20:51.384
Test Suite 'SwiftWithTestsTargetTests.xctest' started at 2019-09-16 18:20:51.384
Test Suite 'Tests' started at 2019-09-16 18:20:51.384
Test Case '-[Libraries_SwiftWithTests_SwiftWithTestsTargetTestsLib.Tests test]' started.
Test Case '-[Libraries_SwiftWithTests_SwiftWithTestsTargetTestsLib.Tests test]' passed (15.005 seconds).
Test Suite 'Tests' passed at 2019-09-16 18:21:06.389.
	 Executed 1 test, with 0 failures (0 unexpected) in 15.005 (15.005) seconds
Test Suite 'SwiftWithTestsTargetTests.xctest' passed at 2019-09-16 18:21:06.389.
	 Executed 1 test, with 0 failures (0 unexpected) in 15.005 (15.006) seconds
Test Suite 'All tests' passed at 2019-09-16 18:21:06.389.
	 Executed 1 test, with 0 failures (0 unexpected) in 15.005 (15.006) seconds
2019-09-16 16:21:06,394 Deleting simulator C1280F9E-2600-400F-AA33-11F8F3601E0F asynchronously.
2019-09-16 16:21:06,397 Done.

Note the time difference between timestamps in the following lines (around 15 seconds):

Test Suite 'Tests' started at 2019-09-16 18:20:51.384
Test Case '-[Libraries_SwiftWithTests_SwiftWithTestsTargetTestsLib.Tests test]' started.
Test Case '-[Libraries_SwiftWithTests_SwiftWithTestsTargetTestsLib.Tests test]' passed (15.005 seconds).
Test Suite 'Tests' passed at 2019-09-16 18:21:06.389.

The source code for that test is the following:

import XCTest
import SwiftWithTestsTarget

final class Tests: XCTestCase {
    func test() {
        XCTAssertEqual(text, "Hello, World!")
    }
}

[acecilia]

Based on airbnb/BuckSample#121 (comment) I suspect that the delay may go away if the simulator to be used is already opened before the test run.

In order to test this, I have been looking into how to tell the test runner https://github.com/google/xctestrunner (I am running latest release 0.2.10) to use an existing, already opened simulator, but without luck. The flag --ios_simulator_device is not being considered by ios_unit_test. Do you know how to do this?

[keith]

There is currently not a way to do that with the test runner that rules_apple provides. You can pass a specific device / os version by creating a ios_test_runner target, and setting that as the runner of the ios_unit_test target but it will still create a new one each time. This is an intentional decision to keep your test runs as hermetic as possible. Because of these performance issues we wrote our own test runner that uses an already running simulator.

Depending on your use case this time overhead might not be too bad. If you use Tulsi to use Bazel in Xcode it won't go through this codepath and will instead use Xcode to run the test bundles so you won't have this. In which case you'd likely only hit this on CI so if you only have a few test bundles it might be ok.

[acecilia]

Thanks @keith. Is your custom test runner open source?

[keith]

No it's not, but generally it's the same as the one in this repo, except instead of calling xctestrunner with the device / version we first create a simulator using simctl and then pass the udid with --id to xctestrunner

[acecilia]

Mmm. I just tried that, without success.

1. I cloned https://github.com/bazelbuild/rules_apple in my local machine.
2. In my WORKSPACE file I changed:

http_archive(
    name = "build_bazel_rules_apple",
    sha256 = "a045a436b642c70fb0c10ca84ff0fd2dcbd59cc89100d597a61e8374afafb366",
    url = "https://github.com/bazelbuild/rules_apple/releases/download/0.18.0/rules_apple.0.18.0.tar.gz",
)

With:

local_repository(
    name = "build_bazel_rules_apple",
    path = "./../rules_apple",
)

3. In the file https://github.com/bazelbuild/rules_apple/blob/master/apple/testing/default_runner/ios_test_runner.template.sh, in my machine I changed:

cmd=("%(testrunner_binary)s"
  "${runner_flags[@]}"
  simulator_test
  "--device_type=%(device_type)s"
  "--os_version=%(os_version)s"
  "$@")

To:

cmd=("%(testrunner_binary)s"
  "${runner_flags[@]}"
  test
  "--id=%(device_type)s"
  "$@")

4. In a BUILD file I created a ios_test_runner target as follows:

ios_test_runner(
    name = "test_runner",
    device_type = "D2B0934F-572F-4E2A-901C-E5EBC2352695",
    visibility = ["//visibility:public"],
)

5. I set the test runner in the ios_unit_test rule:

ios_unit_test(
    name = name,
    deps = [":" + test_lib_name],
    minimum_os_version = "10.0",
    runner = "//config/bazel_config:test_runner"
)

When opening the "D2B0934F-572F-4E2A-901C-E5EBC2352695" simulator and then running the tests, I can see that the tests are passing successfully with the new --id option (if I remove one character from the id the testrunner fails, so seems like the parameter is reaching the binary), but still the tests take more than 15 seconds to run.

[sergiocampama]

This doesn't look related to rules_apple, but https://github.com/google/xctestrunner does not have Issues enabled, so we'll keep it here, but the rules_apple team will likely not look into this. I'll forward this issue to the xctestrunner team internally.

[albertdai]

Hi Andrés,

Do you mind sharing the instructions or code how to reproduce the issue? I can not reproduce this issue with my local simple Swift logic test and did not found the test target //Libraries/SwiftWithTests:SwiftWithTestsTargetTests under the codebase https://github.com/acecilia/BazelVSBuckSample

[acecilia]

@albertdai You can see the length of the tests in CI here: https://dev.azure.com/acecilia/BazelVSBuckSample/_build/results?buildId=58&view=logs&jobId=12f1170f-54f2-53f3-20dd-22fc7dff55f9&taskId=e7d422da-e621-5d9c-7d76-ef2f3144435b&lineStart=63&lineEnd=63&colStart=1&colEnd=9

In https://github.com/acecilia/BazelVSBuckSample I renamed //Libraries/SwiftWithTests:SwiftWithTestsTargetTests to //Libraries/SwiftModule:SwiftModuleTests. To run the bazel tests from https://github.com/acecilia/BazelVSBuckSample in your local machine you can follow these steps:

git clone https://github.com/acecilia/BazelVSBuckSample.git
cd BazelVSBuckSample
make install_tools # will install buck and bazel in your machine
carthage bootstrap --platform ios
make test BUILDTOOL=bazel

For cleaning and running with 100% miss cache, you can do make clean BUILDTOOL=bazel.
Is this information enough?

[albertdai]

HI Andrés,

I can reproduce this issue in Xcode 10.2~10.3: the logic test execution hang ~15 seconds randomly. If you use Xcode 10.1 or Xcode 11+, the issue will go away.

It looks a bug in Apple side. So neither bazel or xctestrunner can help this issue.

[acecilia]

Awesome, @albertdai thanks for your help.

I am trying to add Xcode11 to my CI in https://github.com/acecilia/BazelVSBuckSample but I am having some problems. As soon as I do that and can compare the build times I will update this issue.

[acecilia]

@albertdai I have an update on this.
My CI run shows the following results:

• In Xcode 10.3 (https://dev.azure.com/acecilia/BazelVSBuckSample/_build/results?buildId=81&view=logs&jobId=69944193-f126-526b-b021-abb6fb4b38ee&taskId=20b10c3c-b72b-59f9-f200-e736f87771c4&lineStart=57&lineEnd=63&colStart=1&colEnd=101):

//Libraries/ObjcModule:ObjcModuleObjcTests                               PASSED in 19.1s
//Libraries/ObjcModule:ObjcModuleTests                                   PASSED in 18.0s
//Libraries/SwiftApp:SwiftAppAppTests                                    PASSED in 84.3s
//Libraries/SwiftApp:SwiftAppTests                                       PASSED in 18.3s
//Libraries/SwiftModule:SwiftModuleAppTests                              PASSED in 87.1s
//Libraries/SwiftModule:SwiftModuleTests                                 PASSED in 18.2s
//Libraries/SwiftModuleWithPrebuiltDependency:SwiftModuleWithPrebuiltDependencyTests PASSED in 28.1s

• In Xcode 11 (https://dev.azure.com/acecilia/BazelVSBuckSample/_build/results?buildId=81&view=logs&jobId=1600059a-7091-5d41-ccb9-416f6972ece0&taskId=791ceda7-ae9f-5a3a-7a1e-4da7b6a52f5d&lineStart=58&lineEnd=64&colStart=1&colEnd=100):

//Libraries/ObjcModule:ObjcModuleObjcTests                               PASSED in 2.3s
//Libraries/ObjcModule:ObjcModuleTests                                   PASSED in 8.8s
//Libraries/SwiftApp:SwiftAppAppTests                                    PASSED in 76.0s
//Libraries/SwiftApp:SwiftAppTests                                       PASSED in 3.3s
//Libraries/SwiftModule:SwiftModuleAppTests                              PASSED in 78.6s
//Libraries/SwiftModule:SwiftModuleTests                                 PASSED in 9.8s
//Libraries/SwiftModuleWithPrebuiltDependency:SwiftModuleWithPrebuiltDependencyTests PASSED in 5.0s

As you commented, using Xcode 11 gets rid of the 10-15 seconds delay we were talking about. Thank you very much!