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

hassila · 2024-09-18T12:20:54Z

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

The text was updated successfully, but these errors were encountered:

jhansbo · 2024-09-18T14:33:35Z

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 · 2024-09-18T14:34:17Z

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 · 2024-09-18T15:00:11Z

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

grynspan · 2024-09-18T18:46:43Z

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

grynspan · 2024-09-18T18:47:26Z

@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 · 2024-09-18T19:39:04Z

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

hassila · 2024-09-18T19:41:07Z

Here it is again @grynspan

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

grynspan · 2024-09-18T20:07:20Z

Oops, missed it. Thanks!

grynspan · 2024-09-18T20:15:49Z

    +                                     ! : 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 · 2024-09-18T20:16:01Z

Duplicate of #659

jhansbo · 2024-09-19T13:53:47Z

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

grynspan · 2024-09-19T21:00:03Z

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

jhansbo · 2024-10-11T09:48:28Z

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

jhansbo · 2024-10-11T09:53:13Z

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 · 2024-10-11T09:55:56Z

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 · 2024-10-11T09:56:51Z

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 · 2024-10-11T09:57:24Z

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.

hassila added the bug Something isn't working label Sep 18, 2024

grynspan added the performance Performance issues label Sep 18, 2024

grynspan marked this as a duplicate of #659 Sep 18, 2024

grynspan closed this as not planned Won't fix, can't repro, duplicate, stale Sep 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

hassila commented Sep 18, 2024

jhansbo commented Sep 18, 2024 •

edited

Loading

jhansbo commented Sep 18, 2024

jhansbo commented Sep 18, 2024

grynspan commented Sep 18, 2024

grynspan commented Sep 18, 2024

hassila commented Sep 18, 2024

hassila commented Sep 18, 2024

grynspan commented Sep 18, 2024

grynspan commented Sep 18, 2024

grynspan commented Sep 18, 2024

jhansbo commented Sep 19, 2024

grynspan commented Sep 19, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024 •

edited

Loading

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

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

Comments

hassila commented Sep 18, 2024

Description

Release mode (swift test -c release):

Debug (swift test):

Expected behavior

Actual behavior

Steps to reproduce

swift-testing version/commit hash

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

jhansbo commented Sep 18, 2024 • edited Loading

jhansbo commented Sep 18, 2024

jhansbo commented Sep 18, 2024

grynspan commented Sep 18, 2024

grynspan commented Sep 18, 2024

hassila commented Sep 18, 2024

hassila commented Sep 18, 2024

grynspan commented Sep 18, 2024

grynspan commented Sep 18, 2024

grynspan commented Sep 18, 2024

jhansbo commented Sep 19, 2024

grynspan commented Sep 19, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024

jhansbo commented Oct 11, 2024 • edited Loading

Release mode (`swift test -c release`):

Debug (`swift test`):

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

jhansbo commented Sep 18, 2024 •

edited

Loading

jhansbo commented Oct 11, 2024 •

edited

Loading