Runtime performance regression compared to XCTest with a factor of 5-10x for certain tests

[hassila]

Description

We've recently ported one of our packages to the new testing infrastructure, and it has been overall smooth - we can see one significant performance regression on the actual runtime of the test and have narrowed it down to the use of #expect in two places - I will provide the test code and timing results and sample of the runtime here, but we can work on providing a reduced case if this does not give enough hints on what the underlying problem can be.

The timing measurements we see are:

Release mode (swift test -c release):

XCTest:

Test Case '-[PricingTests.ArbitrageTests testBlackScholesForArbitrage]' passed (3.371 seconds).

New Testing:

􁁛  Test blackScholesForArbitrage() passed after 37.032 seconds.

Debug (swift test):

XCTest:

Test Case '-[PricingTests.ArbitrageTests testBlackScholesForArbitrage]' passed (30.888 seconds).

New Testing:

􁁛  Test blackScholesForArbitrage() passed after 164.550 seconds.

New Testing (with commenting out two #expect in the loops in the sample code provided below):

􁁛  Test blackScholesForArbitrage() passed after 98.767 seconds.

So basically we see a 10x runtime difference in release mode with XCtest winning over the new test framework - and a factor 6 in debug mode. Commenting out the two #expects in the sample below (best guess based on the sample) gave a significant improvement from 164 ---> 98 seconds runtime.

Attaching sample:

Sample.txt

Here is the test code in question for the new testing framework (no changes in the test itself, just using the new framework):

 @Test func blackScholesForArbitrage() throws {
    let allowedDeviation = 5.0e-11
    let sampleSize = 1_000_000

    for _ in 0...sampleSize {
      let S = Double.random(in: 0...1_000)
      let X = Double.random(in: 0...1_000)
      let σ = Double.random(in: 0...2.0)
      let r = Double.random(in: 0...2.0)
      let q = Double.random(in: 0...2.0)
      let t = Double.random(in: 0...10.0)
      let putCallParity = S * .exp(-q * t) - .exp(-r * t) * X
      let sampleDividends: [Pricing.Dividend] = []
      var bsValues: [Pricing.Results] = []
      let commonParams = Pricing.Parameters.Common(
        exerciseType: .european,
        spotPrice: Pricing.SideValues(bid: S, ask: S),
        financingRate: r,
        yield: q,
        timeToMaturity: t,
        dividends: sampleDividends
      )

      let specifics = [
        Pricing.Parameters.Specific(
          marketPrice: Pricing.SideValues(bid: 5.0, ask: 21.0), volatility: σ
        ),
        Pricing.Parameters.Specific(
          marketPrice: Pricing.SideValues(bid: 5.0, ask: 21.0), volatility: σ
        ),
      ]

      let referenceData = [
        Pricing.Parameters.InstrumentReferenceData(instrumentType: .call, strikePrice: X),
        Pricing.Parameters.InstrumentReferenceData(instrumentType: .put, strikePrice: X),
      ]
      let pricingContext = Pricing.Context(
        commonParameters: commonParams,
        reference: referenceData,
        parameters: specifics,
        theoreticalValues: [.fair, .delta, .vega, .rho, .vanna, .gamma]
      )
      BlackScholes.calculate(context: pricingContext, results: &bsValues)
      let call = bsValues[0].fair ?? 0.0
      let put = bsValues[1].fair ?? 0.0

      for (index, result) in bsValues.enumerated() {
        let boundaries = ArbitrageBoundaries.validFairValue(
          commonParameters: commonParams,
          reference: referenceData[index]
        )
        if let fairResult = result.fair {
//          #expect(
//            (boundaries?.contains(fairResult)) != false,
//            "fair value \(fairResult) is not within \(String(describing: boundaries))"
//          )
        } else {
          #expect(result.fair != nil, "No fair result returned")
        }
      }

      #expect(abs(call - put - putCallParity) < allowedDeviation, "\(call) \(put)")
    }

    for _ in 0...sampleSize {
      let S = Double.random(in: 0...1_000)
      let X = Double.random(in: 0...1_000)
      let σ = Double.random(in: 0...2.0)
      let r = Double.random(in: 0...2.0)
      let q = Double.random(in: 0...2.0)
      let t = Double.random(in: 0...10.0)
      let timeToDiv = Double.random(in: 0...t)
      let dividendSize = Double.random(in: 0...S)
      let pvOfDiv = dividendSize * .exp(-r * timeToDiv)
      let putCallParity = (S - pvOfDiv) * .exp(-q * t) - .exp(-r * t) * X
      let sampleDividends: [Pricing.Dividend] = [
        Pricing.Dividend(amount: dividendSize, timeTo: timeToDiv)
      ]
      var bsValues: [Pricing.Results] = []
      let commonParams = Pricing.Parameters.Common(
        exerciseType: .european,
        spotPrice: Pricing.SideValues(bid: S, ask: S),
        financingRate: r,
        yield: q,
        timeToMaturity: t,
        dividends: sampleDividends
      )

      let specifics = [
        Pricing.Parameters.Specific(
          marketPrice: Pricing.SideValues(bid: 5.0, ask: 21.0), volatility: σ
        ),
        Pricing.Parameters.Specific(
          marketPrice: Pricing.SideValues(bid: 5.0, ask: 21.0), volatility: σ
        ),
      ]

      let referenceData = [
        Pricing.Parameters.InstrumentReferenceData(instrumentType: .call, strikePrice: X),
        Pricing.Parameters.InstrumentReferenceData(instrumentType: .put, strikePrice: X),
      ]
      let pricingContext = Pricing.Context(
        commonParameters: commonParams,
        reference: referenceData,
        parameters: specifics,
        theoreticalValues: [.fair]
      )
      BlackScholes.calculate(context: pricingContext, results: &bsValues)
      let call = bsValues[0].fair ?? 0.0
      let put = bsValues[1].fair ?? 0.0

      for (index, result) in bsValues.enumerated() {
        let boundaries = ArbitrageBoundaries.validFairValue(
          commonParameters: commonParams,
          reference: referenceData[index]
        )
        if let fairResult = result.fair {
//          #expect(
//            (boundaries?.contains(fairResult)) != false,
//            "fair value \(fairResult) is not within \(String(describing: boundaries))"
//          )
        } else {
          #expect(result.fair != nil, "No fair result returned")
        }
      }

      #expect(abs(call - put - putCallParity) < allowedDeviation, "\(call) \(put)")
    }
  }

Expected behavior

We expected approximately the same runtime with the new testing framework.

Actual behavior

We saw a 5-10x test runtime regression for certain tests.

Steps to reproduce

No response

swift-testing version/commit hash

Built in with 6.0 release toolchain with Xcode 16

Swift & OS version (output of swift --version ; uname -a)

swift-driver version: 1.115 Apple Swift version 6.0 (swiftlang-6.0.0.9.10 clang-1600.0.26.2)
Target: arm64-apple-macosx15.0
Darwin ice.local 24.0.0 Darwin Kernel Version 24.0.0: Mon Aug 12 20:51:54 PDT 2024; root:xnu-11215.1.10~2/RELEASE_ARM64_T6000 arm64

[jhansbo]

I have added a simple and self-contained package, while not displaying the same dramatic difference, still is slower by a factor 2.

MyTests.zip

jhansbo@niemann ~/S/MyTests> swift test --filter testInverseNormalUnivariateCDFLoop Fetching https://github.com/apple/swift-numerics from cache Fetched https://github.com/apple/swift-numerics from cache (0.38s) Computing version for https://github.com/apple/swift-numerics Computed https://github.com/apple/swift-numerics at 1.0.2 (0.03s) Creating working copy for https://github.com/apple/swift-numerics Working copy of https://github.com/apple/swift-numerics resolved at 1.0.2 Building for debugging... [35/35] Linking NormalDistributionPackageTests Build complete! (10.98s) Test Suite 'Selected tests' started at 2024-09-18 16:33:04.048. Test Suite 'NormalDistributionPackageTests.xctest' started at 2024-09-18 16:33:04.049. Test Suite 'NormalDistributionTests' started at 2024-09-18 16:33:04.049. Test Case '-[NormalDistributionTests.NormalDistributionTests testInverseNormalUnivariateCDFLoop]' started. Test Case '-[NormalDistributionTests.NormalDistributionTests testInverseNormalUnivariateCDFLoop]' passed (1.522 seconds). Test Suite 'NormalDistributionTests' passed at 2024-09-18 16:33:05.571. Executed 1 test, with 0 failures (0 unexpected) in 1.522 (1.522) seconds Test Suite 'NormalDistributionPackageTests.xctest' passed at 2024-09-18 16:33:05.571. Executed 1 test, with 0 failures (0 unexpected) in 1.522 (1.522) seconds Test Suite 'Selected tests' passed at 2024-09-18 16:33:05.571. Executed 1 test, with 0 failures (0 unexpected) in 1.522 (1.523) seconds 􀟈 Test run started. 􀄵 Testing Library Version: 94 (arm64e-apple-macos13.0) 􁁛 Test run with 0 tests passed after 0.001 seconds. jhansbo@niemann ~/S/MyTests> swift test --filter inverseNormalUnivariateCDFLoop Building for debugging... [1/1] Write swift-version--58304C5D6DBC2206.txt Build complete! (0.16s) Test Suite 'Selected tests' started at 2024-09-18 16:33:21.317. Test Suite 'NormalDistributionPackageTests.xctest' started at 2024-09-18 16:33:21.318. Test Suite 'NormalDistributionPackageTests.xctest' passed at 2024-09-18 16:33:21.318. Executed 0 tests, with 0 failures (0 unexpected) in 0.000 (0.000) seconds Test Suite 'Selected tests' passed at 2024-09-18 16:33:21.318. Executed 0 tests, with 0 failures (0 unexpected) in 0.000 (0.001) seconds 􀟈 Test run started. 􀄵 Testing Library Version: 94 (arm64e-apple-macos13.0) 􀟈 Test inverseNormalUnivariateCDFLoop() started. 􁁛 Test inverseNormalUnivariateCDFLoop() passed after 3.046 seconds. 􁁛 Test run with 1 test passed after 3.046 seconds.

[jhansbo]

jhansbo@niemann ~/S/MyTests> swift --version swift-driver version: 1.115 Apple Swift version 6.0 (swiftlang-6.0.0.9.10 clang-1600.0.26.2) Target: arm64-apple-macosx14.0

[jhansbo]

MyTests.zip Adding a modified package for which you can run the tests in Xcode as well.

[grynspan]

I would bet a peanut this is fixed by #659.

[grynspan]

@hassila Are you able to capture a spindump or sample while the test runs slowly? If so, could you share it with us? (@jhansbo you too while you're here.)

[hassila]

@grynspan i did, it is attached in the original description in the middle... :-)

[hassila]

Here it is again @grynspan

https://github.com/user-attachments/files/17043776/Sample.txt

[grynspan]

Oops, missed it. Thanks!

[grynspan]

    +                                     ! : 1164 __checkValue(_:expression:expressionWithCapturedRuntimeValues:mismatchedErrorDescription:difference:mismatchedExitConditionDescription:comments:isRequired:sourceLocation:)  (in Testing) + 2316  [0x103e5a90c]
    +                                     ! : | 1142 specialized static Event.post(_:for:testCase:instant:configuration:)  (in Testing) + 424  [0x103e50880]
    +                                     ! : | + 1132 Test.id.getter  (in Testing) + 320  [0x103efd134]
    +                                     ! : | + ! 554 TypeInfo.fullyQualifiedNameComponents.getter  (in Testing) + 608  [0x103e836ec]

Yup!

[grynspan]

Duplicate of #659

[jhansbo]

Is it possible to verify this with Xcode Beta 2, 16B5014f?!

[grynspan]

Xcode 16.1 Beta 2 does not include the fix, however it's expected to be available in an upcoming Xcode beta.

[jhansbo]

Looks much better in Xcode 16.1 Beta 3! Thanks for that!

[jhansbo]

jhansbo@niemann ~/D/MyTests [1]> swift test --filter testInverseNormalUnivariateCDFLoop Building for debugging... [9/9] Linking NormalDistributionPackageTests Build complete! (8.86s) Test Suite 'Selected tests' started at 2024-10-11 11:53:00.675. Test Suite 'NormalDistributionPackageTests.xctest' started at 2024-10-11 11:53:00.676. Test Suite 'NormalDistributionTests' started at 2024-10-11 11:53:00.676. Test Case '-[NormalDistributionTests.NormalDistributionTests testInverseNormalUnivariateCDFLoop]' started. Test Case '-[NormalDistributionTests.NormalDistributionTests testInverseNormalUnivariateCDFLoop]' passed (1.462 seconds). Test Suite 'NormalDistributionTests' passed at 2024-10-11 11:53:02.139. Executed 1 test, with 0 failures (0 unexpected) in 1.462 (1.462) seconds Test Suite 'NormalDistributionPackageTests.xctest' passed at 2024-10-11 11:53:02.139. Executed 1 test, with 0 failures (0 unexpected) in 1.462 (1.462) seconds Test Suite 'Selected tests' passed at 2024-10-11 11:53:02.139. Executed 1 test, with 0 failures (0 unexpected) in 1.462 (1.463) seconds 􀟈 Test run started. 􀄵 Testing Library Version: 102 (arm64e-apple-macos13.0) 􁁛 Test run with 0 tests passed after 0.001 seconds.

[jhansbo]

jhansbo@niemann ~/D/MyTests> swift test --filter inverseNormalUnivariateCDFLoop Building for debugging... [1/1] Write swift-version-15FB3B08D7648C17.txt Build complete! (0.14s) Test Suite 'Selected tests' started at 2024-10-11 11:55:45.135. Test Suite 'NormalDistributionPackageTests.xctest' started at 2024-10-11 11:55:45.136. Test Suite 'NormalDistributionPackageTests.xctest' passed at 2024-10-11 11:55:45.136. Executed 0 tests, with 0 failures (0 unexpected) in 0.000 (0.000) seconds Test Suite 'Selected tests' passed at 2024-10-11 11:55:45.136. Executed 0 tests, with 0 failures (0 unexpected) in 0.000 (0.001) seconds 􀟈 Test run started. 􀄵 Testing Library Version: 102 (arm64e-apple-macos13.0) 􀟈 Test inverseNormalUnivariateCDFLoop() started. 􁁛 Test inverseNormalUnivariateCDFLoop() passed after 1.666 seconds. 􁁛 Test run with 1 test passed after 1.666 seconds.

[jhansbo]

jhansbo@niemann ~/D/MyTests> swift test --filter inverseNormalUnivariateCDFLoop -c release Building for production... [17/17] Linking NormalDistributionPackageTests Build complete! (11.27s) Test Suite 'Selected tests' started at 2024-10-11 11:56:21.700. Test Suite 'NormalDistributionPackageTests.xctest' started at 2024-10-11 11:56:21.702. Test Suite 'NormalDistributionPackageTests.xctest' passed at 2024-10-11 11:56:21.702. Executed 0 tests, with 0 failures (0 unexpected) in 0.000 (0.000) seconds Test Suite 'Selected tests' passed at 2024-10-11 11:56:21.702. Executed 0 tests, with 0 failures (0 unexpected) in 0.000 (0.001) seconds 􀟈 Test run started. 􀄵 Testing Library Version: 102 (arm64e-apple-macos13.0) 􀟈 Test inverseNormalUnivariateCDFLoop() started. 􁁛 Test inverseNormalUnivariateCDFLoop() passed after 0.602 seconds. 􁁛 Test run with 1 test passed after 0.603 seconds. jhansbo@niemann ~/D/MyTests> swift test --filter testInverseNormalUnivariateCDFLoop -c release Building for production... [1/1] Write swift-version-15FB3B08D7648C17.txt Build complete! (0.17s) Test Suite 'Selected tests' started at 2024-10-11 11:56:40.703. Test Suite 'NormalDistributionPackageTests.xctest' started at 2024-10-11 11:56:40.704. Test Suite 'NormalDistributionTests' started at 2024-10-11 11:56:40.704. Test Case '-[NormalDistributionTests.NormalDistributionTests testInverseNormalUnivariateCDFLoop]' started. Test Case '-[NormalDistributionTests.NormalDistributionTests testInverseNormalUnivariateCDFLoop]' passed (0.420 seconds). Test Suite 'NormalDistributionTests' passed at 2024-10-11 11:56:41.125. Executed 1 test, with 0 failures (0 unexpected) in 0.420 (0.420) seconds Test Suite 'NormalDistributionPackageTests.xctest' passed at 2024-10-11 11:56:41.125. Executed 1 test, with 0 failures (0 unexpected) in 0.420 (0.421) seconds Test Suite 'Selected tests' passed at 2024-10-11 11:56:41.125. Executed 1 test, with 0 failures (0 unexpected) in 0.420 (0.422) seconds 􀟈 Test run started. 􀄵 Testing Library Version: 102 (arm64e-apple-macos13.0) 􁁛 Test run with 0 tests passed after 0.001 seconds.

[jhansbo]

So while it's really a lot faster it's still slightly slower than XCTest. As far as I can see roughly 40% slower in MyTest for release and 20% for debug builds.