[SR-11312] Type-checker takes a long time on first SIMD init calls

AliSoftware commented 5 years ago


Previous ID	SR-11312
Radar	None
Original Reporter	@AliSoftware
Type	Bug

Environment

Swift 5.0.1 (Xcode 10.2.1) and Swift 5.1 (Xcode 11b4)

Additional Detail from JIRA

| | | |------------------|-----------------| |Votes | 0 | |Component/s | Compiler | |Labels | Bug | |Assignee | None | |Priority | Medium | md5: bef33b731cca360caa4ab12a6f7f2937

Issue Description:

Given the following code (whole code from file named GLK+SIMD.swift), the first let line1 takes \~ 70-100ms to type-check – while the remaining line2-4 take \~ 0.12ms.

This even seems to have worsen between Swift 5.0.1 and 5.1

Demo code

import simd
import GLKit

extension simd_float4x4 {
    init(_ matrix: GLKMatrix4) {
        let line1 = float4(matrix.m00, matrix.m01, matrix.m02, matrix.m03)
        let line2 = float4(matrix.m10, matrix.m11, matrix.m12, matrix.m13)
        let line3 = float4(matrix.m20, matrix.m21, matrix.m22, matrix.m23)
        let line4 = float4(matrix.m30, matrix.m31, matrix.m32, matrix.m33)

        self.init(
            line1,
            line2,
            line3,
            line4
        )
    }
}

Results

Swift 5.0.1

$ DEVELOPER_DIR=/Applications/Xcode-10.2.1.app swift --version 
Apple Swift version 5.0.1 (swiftlang-1001.0.82.4 clang-1001.0.46.5)
Target: x86_64-apple-darwin18.7.0

$ DEVELOPER_DIR=/Applications/Xcode-10.2.1.app swiftc -Xfrontend -debug-time-expression-type-checking GLK+SIMD.swift 
78.81ms GLK+SIMD.swift:6:32
0.14ms  GLK+SIMD.swift:7:32
0.11ms  GLK+SIMD.swift:8:32
0.12ms  GLK+SIMD.swift:9:32
0.07ms  GLK+SIMD.swift:11:14
...

Swift 5.1

$ DEVELOPER_DIR=/Applications/Xcode-11b4.app swift --version
Apple Swift version 5.1 (swiftlang-1100.0.257.2 clang-1100.0.31.3)
Target: x86_64-apple-darwin18.7.0

$ DEVELOPER_DIR=/Applications/Xcode-11b4.app swiftc -Xfrontend -debug-time-expression-type-checking GLK+SIMD.swift
100.25ms    GLK+SIMD.swift:6:32
0.15ms  GLK+SIMD.swift:7:32
0.12ms  GLK+SIMD.swift:8:32
0.14ms  GLK+SIMD.swift:9:32
0.10ms  GLK+SIMD.swift:11:14
...

Switching to use the init( x:y:z:w: ) instead of init( _:_:_:_: ) doesn't seem to help.

What's strange is that the long type-checker time affects the first line but not the following ones that have the exact same structure (or is it some caching in action?)

Workaround by rearranging the code

The only workaround I found to reduce the type-checking time to way more reasonable values is to build a reference to the init function first, and then use it:

import simd
import GLKit

extension simd_float4x4 {
    init(_ matrix: GLKMatrix4) {
        let makef4 = SIMD4<Float>.init(x:y:z:w:) as (Float, Float, Float, Float) -> SIMD4<Float>
        let line1 = makef4(matrix.m00, matrix.m01, matrix.m02, matrix.m03)
        let line2 = makef4(matrix.m10, matrix.m11, matrix.m12, matrix.m13)
        let line3 = makef4(matrix.m20, matrix.m21, matrix.m22, matrix.m23)
        let line4 = makef4(matrix.m30, matrix.m31, matrix.m32, matrix.m33)

        self.init(line1, line2, line3, line4)
    }
}

Swift 5.0.1

$ DEVELOPER_DIR=/Applications/Xcode-10.2.1.app swiftc -Xfrontend -debug-time-expression-type-checking GLK+SIMD.swift
1.65ms  GLK+SIMD.swift:6:50
0.21ms  GLK+SIMD.swift:7:21
0.08ms  GLK+SIMD.swift:8:21
0.07ms  GLK+SIMD.swift:9:21
0.08ms  GLK+SIMD.swift:10:21
0.13ms  GLK+SIMD.swift:12:14
...

Swift 5.1

$ DEVELOPER_DIR=/Applications/Xcode-11b4.app swiftc -Xfrontend -debug-time-expression-type-checking GLK+SIMD.swift
21.24ms GLK+SIMD.swift:6:50
0.20ms  GLK+SIMD.swift:7:21
0.08ms  GLK+SIMD.swift:8:21
0.07ms  GLK+SIMD.swift:9:21
0.07ms  GLK+SIMD.swift:10:21
0.10ms  GLK+SIMD.swift:12:14
...

It seems it led to a lot better timings on Swift 5.0.1 (resolution of init reduced to 1.65ms), but is still at 20ms on Swift 5.1 (despite all the hints we give to the type-checker in the code) so there might be some regression there too.

Footnote: It's worse (150ms) in the context of a bigger Xcode project

The initial code I posted at the top of this issue sometimes took >150ms when built in the context or our big project in Xcode 10.2.1 – triggering our -Xfrontend -warn-long-expression-type-checking=150 warning.
I haven't found any extension float4 or extension SIMD4 in our own codebase that would declare more init overloads and could explain the additional time it took in the context of our big project. We have external dependencies though so maybe they were the ones defining additional overloads, but Cmd-Clicking the float4.init didn't show any overload other than the official one (the same that I've now extracted in makef4)

But even once extracted to only compile that single from our big project directly using swiftc from the Terminal, the time taken by the type-checker seems curiously long.

belkadan commented 5 years ago

I am a little curious why your rearrangement helped in any significant way, since most of the time spent in the first expression is probably not actually about the expression itself, but about loading information about SIMD4 from the standard library. cc @xedin

xedin commented 5 years ago

I don't believe that this is related to expression type-checker because all of the expressions would exhibit the same performance since there is no cross expression caching.

AliSoftware commented 5 years ago

@xedin do you need me to provide additional debug output then, like try with some other frontend flag that would show deeper drill-down of timings and better highlight where the bottleneck would be?

xedin commented 5 years ago

@slavapestov Since you have been working in that area, any ideas how to narrow this down?

slavapestov commented 5 years ago

I'll take a closer look soon, but trying out -trace-stats-events together with -stats-output-dir might be interesting.

swiftlang / swift