Unit Tests Run Incredibly Slow

[Rspoon3]

Description

I noticed in a project of mine that using the TestClock was causing tests to become incredibly slow. I made a very simple demo app and was able to reproduce the problem. After that I thought I would try running the tests that came with the library. The same thing occurs. Tests are taking seconds to run (sometimes close to a minute) as well as failing.

I am testing on Xcode 15.4 (15F31d) with an iPhone 14 (17.4) simulator. I can also reproduce on the 17.5 and 16.4 simulators.

Logging Error: Failed to initialize logging system. Log messages may be missing. If this issue persists, try setting IDEPreferLogStreaming=YES in the active scheme actions environment variables.
Test Suite 'All tests' started at 2024-05-16 08:14:49.643.
Test Suite 'ClocksTests.xctest' started at 2024-05-16 08:14:49.643.
Test Suite 'ImmediateClockTests' started at 2024-05-16 08:14:49.644.
Test Case '-[ClocksTests.ImmediateClockTests testCooperativeCancellation]' started.
Test Case '-[ClocksTests.ImmediateClockTests testCooperativeCancellation]' passed (0.001 seconds).
Test Case '-[ClocksTests.ImmediateClockTests testNow]' started.
Test Case '-[ClocksTests.ImmediateClockTests testNow]' passed (0.113 seconds).
Test Case '-[ClocksTests.ImmediateClockTests testTimer]' started.
Test Case '-[ClocksTests.ImmediateClockTests testTimer]' passed (36.022 seconds).
Test Suite 'ImmediateClockTests' passed at 2024-05-16 08:15:25.782.
	 Executed 3 tests, with 0 failures (0 unexpected) in 36.136 (36.139) seconds
Test Suite 'TestClockTests' started at 2024-05-16 08:15:25.783.
Test Case '-[ClocksTests.TestClockTests testAdvance]' started.
Test Case '-[ClocksTests.TestClockTests testAdvance]' passed (6.591 seconds).
Test Case '-[ClocksTests.TestClockTests testAdvanceWithReentrantUnitsOfWork]' started.
Test Case '-[ClocksTests.TestClockTests testAdvanceWithReentrantUnitsOfWork]' passed (12.760 seconds).
Test Case '-[ClocksTests.TestClockTests testCancellationRemovesScheduledItem]' started.
Test Case '-[ClocksTests.TestClockTests testCancellationRemovesScheduledItem]' passed (1.260 seconds).
Test Case '-[ClocksTests.TestClockTests testCheckScheduledWork]' started.
Test Case '-[ClocksTests.TestClockTests testCheckScheduledWork]' passed (6.489 seconds).
Test Case '-[ClocksTests.TestClockTests testCooperativeCancellation]' started.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:164: error: -[ClocksTests.TestClockTests testCooperativeCancellation] : Expected all sleeps to finish, but some are still suspending after 0.5 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 0.5 seconds.
Test Case '-[ClocksTests.TestClockTests testCooperativeCancellation]' failed (4.361 seconds).
Test Case '-[ClocksTests.TestClockTests testNow]' started.
Test Case '-[ClocksTests.TestClockTests testNow]' passed (0.635 seconds).
Test Case '-[ClocksTests.TestClockTests testRunMultipleUnitsOfWork]' started.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:106: error: -[ClocksTests.TestClockTests testRunMultipleUnitsOfWork] : Expected all sleeps to finish, but some are still suspending after 1.0 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 1.0 seconds.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:108: error: -[ClocksTests.TestClockTests testRunMultipleUnitsOfWork] : XCTAssertEqual failed: ("1") is not equal to ("10")
Test Case '-[ClocksTests.TestClockTests testRunMultipleUnitsOfWork]' failed (1.599 seconds).
Test Case '-[ClocksTests.TestClockTests testRunSorting]' started.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:212: error: -[ClocksTests.TestClockTests testRunSorting] : Expected all sleeps to finish, but some are still suspending after 0.5 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 0.5 seconds.
/Users/richardwitherspoon/Documents/swift-clocks/Sources/Clocks/TestClock.swift:232: error: -[ClocksTests.TestClockTests testRunSorting] : failed: caught error: "CancellationError()"
Test Case '-[ClocksTests.TestClockTests testRunSorting]' failed (6.458 seconds).
Test Case '-[ClocksTests.TestClockTests testRun]' started.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:59: error: -[ClocksTests.TestClockTests testRun] : Expected all sleeps to finish, but some are still suspending after 0.5 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 0.5 seconds.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:61: error: -[ClocksTests.TestClockTests testRun] : XCTAssertEqual failed: ("false") is not equal to ("true")
Test Case '-[ClocksTests.TestClockTests testRun]' failed (5.838 seconds).
Test Case '-[ClocksTests.TestClockTests testRunWithReentrantUnitsOfWork]' started.
/Users/richardwitherspoon/Documents/swift-clocks/Tests/ClocksTests/TestClocksTests.swift:127: error: -[ClocksTests.TestClockTests testRunWithReentrantUnitsOfWork] : Expected all sleeps to finish, but some are still suspending after 0.5 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 0.5 seconds.
/Users/richardwitherspoon/Documents/swift-clocks/Sources/Clocks/TestClock.swift:232: error: -[ClocksTests.TestClockTests testRunWithReentrantUnitsOfWork] : failed: caught error: "CancellationError()"
Test Case '-[ClocksTests.TestClockTests testRunWithReentrantUnitsOfWork]' failed (3.619 seconds).
Test Case '-[ClocksTests.TestClockTests testRunWithTimeout]' started.
XCTExpectFailure: matcher accepted Assertion Failure at TestClocksTests.swift:88: Expected all sleeps to finish, but some are still suspending after 1.0 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 1.0 seconds.
TestClocksTests.swift:88: Expected failure in -[ClocksTests.TestClockTests testRunWithTimeout]: Expected all sleeps to finish, but some are still suspending after 1.0 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 1.0 seconds.
XCTExpectFailure: matcher accepted Assertion Failure at TestClocksTests.swift:90: Expected all sleeps to finish, but some are still suspending after 1.0 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 1.0 seconds.
TestClocksTests.swift:90: Expected failure in -[ClocksTests.TestClockTests testRunWithTimeout]: Expected all sleeps to finish, but some are still suspending after 1.0 seconds.

There are sleeps suspending. This could mean you are not advancing the test clock far enough for your feature to execute its logic, or there could be a bug in your feature's logic.

You can also increase the timeout of 'run' to be greater than 1.0 seconds.
Test Case '-[ClocksTests.TestClockTests testRunWithTimeout]' passed (8.530 seconds).
Test Case '-[ClocksTests.TestClockTests testSleepUntilExactlyNow]' started.
Test Case '-[ClocksTests.TestClockTests testSleepUntilExactlyNow]' passed (1.695 seconds).
Test Suite 'TestClockTests' failed at 2024-05-16 08:16:25.643.
	 Executed 12 tests, with 9 failures (2 unexpected) in 59.836 (59.859) seconds
Test Suite 'UnimplementedClockTests' started at 2024-05-16 08:16:25.644.
Test Case '-[ClocksTests.UnimplementedClockTests testCooperativeCancellation]' started.
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:62: Unimplemented: Clock.now
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:62: Unimplemented: Clock.sleep
UnimplementedClockTests.swift:62: Expected failure in -[ClocksTests.UnimplementedClockTests testCooperativeCancellation]: Unimplemented: Clock.now
UnimplementedClockTests.swift:62: Expected failure in -[ClocksTests.UnimplementedClockTests testCooperativeCancellation]: Unimplemented: Clock.sleep
Test Case '-[ClocksTests.UnimplementedClockTests testCooperativeCancellation]' passed (0.015 seconds).
Test Case '-[ClocksTests.UnimplementedClockTests testNow]' started.
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:46: Unimplemented: Clock.now
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:46: Unimplemented: Clock.sleep
UnimplementedClockTests.swift:46: Expected failure in -[ClocksTests.UnimplementedClockTests testNow]: Unimplemented: Clock.now
UnimplementedClockTests.swift:46: Expected failure in -[ClocksTests.UnimplementedClockTests testNow]: Unimplemented: Clock.sleep
Test Case '-[ClocksTests.UnimplementedClockTests testNow]' passed (0.210 seconds).
Test Case '-[ClocksTests.UnimplementedClockTests testUnimplementedClock_WithName]' started.
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:32: Unimplemented: ContinuousClock.now
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:32: Unimplemented: ContinuousClock.sleep
UnimplementedClockTests.swift:32: Expected failure in -[ClocksTests.UnimplementedClockTests testUnimplementedClock_WithName]: Unimplemented: ContinuousClock.now
UnimplementedClockTests.swift:32: Expected failure in -[ClocksTests.UnimplementedClockTests testUnimplementedClock_WithName]: Unimplemented: ContinuousClock.sleep
Test Case '-[ClocksTests.UnimplementedClockTests testUnimplementedClock_WithName]' passed (9.477 seconds).
Test Case '-[ClocksTests.UnimplementedClockTests testUnimplementedClock]' started.
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:18: Unimplemented: Clock.now
XCTExpectFailure: matcher accepted Assertion Failure at UnimplementedClockTests.swift:18: Unimplemented: Clock.sleep
UnimplementedClockTests.swift:18: Expected failure in -[ClocksTests.UnimplementedClockTests testUnimplementedClock]: Unimplemented: Clock.now
UnimplementedClockTests.swift:18: Expected failure in -[ClocksTests.UnimplementedClockTests testUnimplementedClock]: Unimplemented: Clock.sleep
Test Case '-[ClocksTests.UnimplementedClockTests testUnimplementedClock]' passed (0.423 seconds).
Test Suite 'UnimplementedClockTests' passed at 2024-05-16 08:16:35.773.
	 Executed 4 tests, with 0 failures (0 unexpected) in 10.125 (10.129) seconds
Test Suite 'ClocksTests.xctest' failed at 2024-05-16 08:16:35.774.
	 Executed 19 tests, with 9 failures (2 unexpected) in 106.096 (106.131) seconds
Test Suite 'All tests' failed at 2024-05-16 08:16:35.775.
	 Executed 19 tests, with 9 failures (2 unexpected) in 106.096 (106.132) seconds
Program ended with exit code: 1

Checklist

• If possible, I've reproduced the issue using the main branch of this package.
• This issue hasn't been addressed in an existing GitHub issue or discussion.

Expected behavior

Tests should run in a fraction of a second.

Actual behavior

Tests are taking seconds to run (sometimes close to a minute) as well as failing.

Steps to reproduce

1. Download Xcode 15.4
2. Select an iPhone 16.4, 17.4 or 17.5 simulator
3. Run the libraries unit tests

swift-clocks version information

2c74776

Destination operating system

iOS 16 and 17

Xcode version information

Xcode 15.4 (15F31d)

Swift Compiler version information

Apple Swift version 5.10 (swiftlang-5.10.0.13 clang-1500.3.9.4)

[mbrandonw]

Hi @Rspoon3, I can't seem to reproduce this:

Test Suite 'All tests' passed at 2024-05-16 07:46:00.646.
	 Executed 19 tests, with 0 failures (0 unexpected) in 3.577 (3.589) seconds

I've run it a dozen times and never seen it go above 5 seconds. I don't doubt that you are seeing strange times, but I'm not sure how it could be caused by this library and don't think there's much we could do to fix it.

Now one difference in my set up is that I am still on Xcode 15.3. I'm downloading 15.4 now, but perhaps that could be the problem. Also I believe iOS simulators still run with a cooperative thread pool of just a single thread, and so perhaps that is also problematic. Do the tests run faster on macOS?

[mbrandonw]

I was able to download Xcode 15.4 and the test suite definitely runs a bit slower. I had one run of about 30 seconds, but on average I'm seeing closer to 5-8 seconds. Running tests on macOS seems to be about the same.

It's seeming pretty clear that this not really an issue with the library, but perhaps a regression in Xcode, so I am going to convert it to a discussion. Let's continue the conversation over there!

[Rspoon3]

On macOS they're much faster. I can execute all 19 tests in 4.36 seconds.

I was running some other tests earlier today that don't have clocks associated with them, but that do use `Task.megaYield. Those tests were noticeably slower as well. The slow downs might have something to do with that.