[SR-6983] Unexpected drop in performance of (identity-)closure the second time it is used

[jepers]

Previous ID	SR-6983
Radar	rdar://problem/40661588
Original Reporter	@jepers
Type	Improvement

Additional Detail from JIRA

Votes	1
Component/s	Compiler
Labels	Improvement, Performance
Assignee	None
Priority	Medium

md5: 19f6d1e506b16df7b9ecc2264c9326db

relates to:

• SR-7023 Missed optimization opportunity, but not missed if wrapping code in a nested func

Issue Description:

Reporting this issue as suggested by @dabrahams in this forum thread.

The following program measures the time it takes to process a hundred million random input values using an identity closure and an identity func. In the first measurement, both are equally fast (as expected). But in the second measurement (identical in code and context) the closure is slower for some reason.

import AppKit

func measureExecutionTime(label: String, subject: (Int) -> Int) {
    let operationsPerTrial = 100_000_000
    var randomIntValues = [Int](repeating: 0, count: operationsPerTrial)
    var minTime = Double.infinity
    print("\(label):")
    for _ in 0 ..< 5 {
        randomIntValues.withUnsafeMutableBytes { (ptr) -> Void in
            let r = SecRandomCopyBytes(nil, ptr.count, ptr.baseAddress!)
            precondition(r == errSecSuccess)
        }
        var checksum = Int(0)
        let t0 = CACurrentMediaTime()
        for randomInput in randomIntValues {
            let r = subject(randomInput)
            checksum ^= r
        }
        let t1 = CACurrentMediaTime()
        let time = t1 - t0
        print("  time:", time, "seconds (checksum: \(checksum))")
        minTime = min(minTime, time)
    }
    print("  minimum time:", minTime, "seconds\n")
}

let identityClosure: (Int) -> Int = { return $0 }
func identityFunc(input: Int) -> Int { return input }

// Note that both have the same execution time here:
measureExecutionTime(label: "1st use of closure", subject: identityClosure)
measureExecutionTime(label: "1st use of func", subject: identityFunc)

// Note that identityClosure is slower this time:
measureExecutionTime(label: "2nd use of closure", subject: identityClosure)
measureExecutionTime(label: "2nd use of func", subject: identityFunc)

// Why?

Compiling and running it on my MBP:

> swiftc --version
Apple Swift version 4.1 (swiftlang-902.0.38 clang-902.0.30)
Target: x86_64-apple-darwin17.4.0
> swiftc -O -static-stdlib test.swift
> ./test
1st use of closure:
  time: 0.0631774560024496 seconds (checksum: -5969152766063222341)
  time: 0.0609615579887759 seconds (checksum: 1436576802479868292)
  time: 0.0627239710011054 seconds (checksum: 7897566598316776330)
  time: 0.0592733160010539 seconds (checksum: -1676386092480912224)
  time: 0.0597947819915134 seconds (checksum: 7356946459760327795)
  minimum time: 0.0592733160010539 seconds

1st use of func:
  time: 0.0596228250069544 seconds (checksum: 6666500747078896187)
  time: 0.059224077995168 seconds (checksum: 4253268501060393296)
  time: 0.0597734379989561 seconds (checksum: 3079996028968815475)
  time: 0.059408948989585 seconds (checksum: -39057913403395343)
  time: 0.0593238050059881 seconds (checksum: -1275339559973029455)
  minimum time: 0.059224077995168 seconds

2nd use of closure:
  time: 0.180851501005236 seconds (checksum: -297275842764426349)
  time: 0.191041134006809 seconds (checksum: -2297966356982257278)
  time: 0.181297669012565 seconds (checksum: 4242728420682360232)
  time: 0.19395082097617 seconds (checksum: 4169899910790849794)
  time: 0.183614853012841 seconds (checksum: -7725848402084691842)
  minimum time: 0.180851501005236 seconds

2nd use of func:
  time: 0.0590045459975954 seconds (checksum: -1243511994543017911)
  time: 0.0606653710128739 seconds (checksum: 4379620549680557500)
  time: 0.0616895709827077 seconds (checksum: -3147320019667911741)
  time: 0.0594128520169761 seconds (checksum: 3804868237876071121)
  time: 0.0593436420022044 seconds (checksum: 138671714869980974)
  minimum time: 0.0590045459975954 seconds

(Note that “2nd use of closure” is 0.18 seconds while all the other measurements are 0.06 seconds.)

[belkadan]

cc aschwaighofer@apple.com (JIRA User)

[jepers]

Issue remains – and has gotten worse – with the default toolchain of Xcode 9.4 (9F1027a).

The "2nd use of closure" is now 10 instead of 3 times slower than the others:

› swiftc --version
Apple Swift version 4.1.2 (swiftlang-902.0.54 clang-902.0.39.2)
Target: x86_64-apple-darwin17.5.0
› swiftc -O -static-stdlib test.swift
› ./test
1st use of closure:
  time: 0.0632649020117242 seconds (checksum: 581423683991283777)
  time: 0.0617133129999274 seconds (checksum: -7306424433621360502)
  time: 0.0625146849924931 seconds (checksum: 7081978004570742532)
  time: 0.0610871280077845 seconds (checksum: -4065774701487485870)
  time: 0.0624201809987426 seconds (checksum: -2784397570979284854)
  minimum time: 0.0610871280077845 seconds

1st use of func:
  time: 0.0610684939892963 seconds (checksum: 264423982952719367)
  time: 0.0615423239942174 seconds (checksum: 2237211590060124107)
  time: 0.061124823987484 seconds (checksum: -4267020249627113289)
  time: 0.0619161030044779 seconds (checksum: 1792111283221657060)
  time: 0.063269748003222 seconds (checksum: -1589300676560776483)
  minimum time: 0.0610684939892963 seconds

2nd use of closure:
  time: 0.699463352997554 seconds (checksum: -3918483693787300236)
  time: 0.667777561000548 seconds (checksum: 1137324794268155767)
  time: 0.664340454997728 seconds (checksum: -7811258734802726978)
  time: 0.661137435992714 seconds (checksum: 1048546319275511909)
  time: 0.666032235996681 seconds (checksum: 1052028149280526971)
  minimum time: 0.661137435992714 seconds

2nd use of func:
  time: 0.0614374390133889 seconds (checksum: 6639092839694586210)
  time: 0.0611787349916995 seconds (checksum: -8533491229019487789)
  time: 0.060995906998869 seconds (checksum: -4113116250669794077)
  time: 0.0605206390027888 seconds (checksum: -4439758878194388265)
  time: 0.0613778190017911 seconds (checksum: 1964471734991009996)
  minimum time: 0.0605206390027888 seconds

So “2nd use of closure” is now 0.66 seconds. It was 0.18 seconds when I reported the issue (see compiler version in the example run in the report). The other ones are still 0.06 seconds.

BUT: When using a recent dev snapshot (2018-05-29) the "2nd use of closure" is back to 0.18 seconds again.

[belkadan]

@swift-ci create

[jepers]

Ah! The same workaround as is discussed in SR-7023 can of course be used here too, so replacing the for-in loop with a while loop as follows will make all test cases equally fast:

        let t0 = CACurrentMediaTime()
        var i = 0
        let count = randomIntValues.count
        while i < count {
            let r = subject(randomIntValues[i])
            checksum ^= r
            i = i &+ 1
        }
        let t1 = CACurrentMediaTime()

[jepers]

Issue remains in Xcode 11.3 (11C29), and the work-around (while instead of for-in) in the comment above no longer works.