Swift Type check and functions build times not generated

[stherold]

Hey there 👋

I don't get any compilation time statistics in teh HTML file. According to this post the Swift compiler flags the generated website suggests don't exist anymore:

[david-bandlab]

Same here 🙋‍♂️

[bobbyphtr]

Same here

[BalestraPatrick]

Have you tried the new flags suggested at the link to see if they work? If they do, then we welcome a contribution to change the wording and references to those now removed flags.

[hoangatuan]

@stherold What is the xcodebuild command you was using?

[stherold]

@hoangatuan that one:

xcodebuild -workspace <ws-name>.xcworkspace -scheme <scheme> -resultBundlePath "$(mktemp).xcresult" -destination "platform=iOS Simulator,name=iPhone 15 Pro,OS=latest"

and then:

xclogparser parse --workspace <ws-name>.xcworkspace --reporter html

But now with Xcode 15.3 I get yet another eror (probably related to https://github.com/MobileNativeFoundation/XCLogParser/issues/203):

Error: The line *{"stime":68549,"utim doesn't seem like a valid SLF line

[hoangatuan]

@stherold Make sure you add these flags to "Other Swift Flags" in your project build setting "-Xfrontend", "-warn-long-function-bodies=200", "-Xfrontend", "-warn-long-expression-type-checking=200"

If your workspace uses swift package manager, can insert this code to your Package.swift file

for target in package.targets {
   target.swiftSettings = target.swiftSettings ?? []
   target.swiftSettings?.append(
       .unsafeFlags([
           "-Xfrontend", "-warn-long-function-bodies=200", "-Xfrontend", "-warn-long-expression-type-checking=200",
        ])
    )
}

[hoangatuan]

@stherold For Xcode 15.3, seems like XCLogParse is breaking. While waiting for the bug to be fixed, for now you can use this script to get slow compile warnings

xcodebuild -workspace <ws-name>.xcworkspace -scheme <scheme> -destination "platform=iOS Simulator,name=iPhone 15 Pro,OS=latest" OTHER_SWIFT_FLAGS="-Xfrontend -warn-long-function-bodies=200 -Xfrontend -warn-long-expression-type-checking=200" clean build | grep .[0-9]ms | grep -v ^0.[0-9]ms | grep "^$ROOT_DIRECTORY" | sort -nr > log.txt

References from my project: https://github.com/hoangatuan/iOSDevEx/blob/main/Sources/ToolBoxCore/Commands/DetectSlowCompile/DetectSlowCompileHandler.swift#L91

[Blackjacx]

Yes that generates some output 👍 Does that mean that it would be part of the final report?

[hoangatuan]

@Blackjacx Sorry I dont understand your question "Does that mean that it would be part of the final report?".

This is just a simple script that extract Xcode build logs directly by using regex. It doesn't use XCLogParser, so it can't generate the html report

[hbanzon]

Getting this issue as well when updating to Xcode 15.3. Any ETA on the fix?

[ignindra]

Does anyone manage to make it work with any version of Xcode newer than 15.3? I'm on 15.4 (and XCLogParser 0.2.40) and I'm in the same situation as stherold's screenshot in the first post.

Was wondering whether I should downgrade below 15.3 or upgrade my Xcode.

[Iron-Ham]

I decided to look into why this is. Will update this comment as I continue investigating.

I started by generating a valid xcactivitylog output. I made that xcactivitylog human readable by executing:

gzcat /path/to/file.xcactivitylog | tr '\r' '\n' > human_readable.log

I ensured that the timing data is present and accounted for, and I even placed it directly into the existing unit tests to make sure that we're getting the outputs there as expected. All is working fine.

Tracing it back up, I found the first point of breakage:

https://github.com/MobileNativeFoundation/XCLogParser/blob/7cf8c50e1b84effcda573bbf8b26bdd0a6b4614f/Sources/XCLogParser/parser/ParserBuildSteps.swift#L197

Here, we check to see if we have a swift compilation step. If we do, we will add the log section and continue on. Note that the compile parser owns the function timing and type checking parsers. Herein lies the issue: in modern Xcode versions, we will never recognize a swift compilation step.

We identify a swift compilation step here:

https://github.com/MobileNativeFoundation/XCLogParser/blob/7cf8c50e1b84effcda573bbf8b26bdd0a6b4614f/Sources/XCLogParser/parser/BuildStep.swift#L99-L100

However, that's not how swift compilation steps are defined currently. They are not CompileSwift – but rather, SwiftCompile:

"SwiftCompile normal arm64 Compiling\ Builder.swift,\ Functions.swift,\ UIActivityIndicatorViewStyles.swift,\ UIButtonStyles.swift,\ UIFont+MutableTraits.swift,\ UIImageViewStyles.swift,\ UILabelStyles.swift,\ UIScrollViewStyles.swift,\ UIStackViewStyles.swift,\ UITextFieldStyles.swift,\ UITextViewStyles.swift,\ UIViewStyles.swift /<REDACTED> (in target 'Palette' from project '<REDACTED>')

I'm going to rebuild with this change and update. Notably, my current change is expressed as the inversion of this commit: https://github.com/MobileNativeFoundation/XCLogParser/commit/bb1dd8268bb8a34514778853a9096424746641b4 and is indeed noted here: https://github.com/MobileNativeFoundation/XCLogParser/pull/182

---

Message from debugger: Terminated due to signal 9

Killed by the OS; memory usage going nutso.

A red herring

RED HERRING: We can hold all of this in memory – and even though it's some ~12GB for my log, it's not enough to trigger a sig9. Traversing further down to see where we hit memory issues.

My gut tells me that this is due to this line:

https://github.com/MobileNativeFoundation/XCLogParser/blob/7cf8c50e1b84effcda573bbf8b26bdd0a6b4614f/Sources/XCLogParser/parser/SwiftCompilerParser.swift#L52

There are a few solutions here:

1. We can just be basic about it and iterate through the commands.
2. We can continue to perform concurrent operations, but set a batch size.

Iterative Approach

    public func findRawSwiftTimes() -> [String: Int] {
        var textsAndOccurrences: [String: Int] = [:]
        commands.forEach { element in
            let (rawFunctionTimes, commandDesc) = element
            let hasCompilerFlag = functionTimes.hasCompilerFlag(commandDesc: commandDesc)
                                  || typeCheckTimes.hasCompilerFlag(commandDesc: commandDesc)

            guard hasCompilerFlag && rawFunctionTimes.isEmpty == false else {
                return
            }
            let outputOccurrence = (textsAndOccurrences[rawFunctionTimes] ?? 0) + 1
            textsAndOccurrences[rawFunctionTimes] = outputOccurrence
        }
        return textsAndOccurrences
    }

Batched approach

public func findRawSwiftTimes() -> [String: Int] {
    let insertQueue = DispatchQueue(label: "swift_function_times_queue")
    var textsAndOccurrences: [String: Int] = [:]
    let commandCount = commands.count
    let batchSize = 1000 // For example. Realistically, this should be no more than the count of cores*3, as per the docs on `concurrentPerform`. 

    for batchStart in stride(from: 0, to: commandCount, by: batchSize) {
        let batchEnd = min(batchStart + batchSize, commandCount)
        let batch = Array(commands[batchStart..<batchEnd])

        DispatchQueue.concurrentPerform(iterations: batch.count) { index in
            let (rawFunctionTimes, commandDesc) = batch[index]

            let hasCompilerFlag = functionTimes.hasCompilerFlag(commandDesc: commandDesc)
                                  || typeCheckTimes.hasCompilerFlag(commandDesc: commandDesc)

            guard hasCompilerFlag && rawFunctionTimes.isEmpty == false else {
                return
            }
            insertQueue.sync {
                let outputOccurrence = (textsAndOccurrences[rawFunctionTimes] ?? 0) + 1
                textsAndOccurrences[rawFunctionTimes] = outputOccurrence
            }
        }
    }
    return textsAndOccurrences
}

However, these back-of-the-napkin assumptions aren't really considering how much we'd really be loading into memory. I assume that ultimately, we'd still e holding all of this in memory at some point – but we'd have a much more gradual ramp than before. 🤔

In other words: Batching may be directionally correct, but we must evacuate items that have been batched from memory before batching the next set. This means that the parser must execute its current contents, vacate them from memory, and then wait until new items are added or an EOF signal is received. This represents an interesting refactor.

---

✨ Bottleneck found

https://github.com/MobileNativeFoundation/XCLogParser/blob/7cf8c50e1b84effcda573bbf8b26bdd0a6b4614f/Sources/XCLogParser/reporter/HtmlReporter.swift#L264

I have twenty items in the slowestSwiftFiles collection. The first of these items has 672 substeps.

---

🐞 Bug Found

https://github.com/MobileNativeFoundation/XCLogParser/blob/7cf8c50e1b84effcda573bbf8b26bdd0a6b4614f/Sources/XCLogParser/reporter/HtmlReporter.swift#L210-L234

At some point, all of the swift compile steps became aggregated steps in behavior.

With a few changes (https://github.com/Iron-Ham/XCLogParser/pull/1), both the type checking & function compilation time are now working:

However, since the compiler no longer compiles one file at a time and instead batches all files, the slowest time/file chart is no longer useful unless the app is compiled with the flags instructing single file compilation.

---

Follow-ups and thoughts

I've only really taken a look at the HtmlReporter, and honestly… a lot of this feels like tasks that should be happening before they're fed into any reporter. It's probably a fair assumption that all other reporters exhibit similar behaviors.

We should probably nix slowest Swift files entirely, unless the relevant compiler flags are present to disable batch compilation.

Module time compilation is a bit wonky: it's the aggregate of its time + its dependencies – which kind of erases the value of module time tracking. i.e., if I have a module SmallModule that compiles in 800 seconds, which depends on GiganticModule which compiles in 799 seconds… well, it's not hard to see where the problem is and it's not SmallModule.

There are some real performance issues in the current implementation that can be tackled.

Namely:

• writeTargetFiles is a huge bottleneck and demands over 80GB of memory by itself.
• Maybe writeSharedResources as well?

A temporary workaround for users of `xclogparser`

Use the standard xcodebuild command you're already using to build your app but append the following:

    OTHER_SWIFT_FLAGS="-Xfrontend -debug-time-function-bodies -Xfrontend -debug-time-expression-type-checking" \
  | grep .[0-9]ms \
  | grep -v ^0.[0-9]ms \
  | sort -nr > slow_functions.txt

You now have both slow functions and slow type checks being output into a text file that you can decide what to do with. Note that they're all mixed up in there, and while I now know the format for each one, it's not immediately obvious which is which. Additionally, this will output for ALL functions and type checks. For the app I work on, that amounts to >50MB in that text file. You should probably limit this to something like 50 lines of output.

---

Hey, why is BuildStep so memory hungry anyways?

Possible Causes:

1. COW types. It's a struct. Since structs are Copy-On-Write (🐮) types, they can't nest themselves – which is sidestepped by fact that substeps is an Array<BuildStep> (arrays, even though they have value semantics are secretly referenced. Super confusing). Anyways, the relevance of this is that these are being copied around, and must have a known (or relatively known – in the case of arrays) memory allocation. Can this be resolved by making this a class and then just relying on pointer references? 🤔
2. We're holding all data in memory as we're writing it. Can we encode / write incrementally?

FlatJsonReporter incremental reporting

```swift public func report(build: Any, output: ReporterOutput, rootOutput: String) throws { guard let steps = build as? BuildStep else { throw XCLogParserError.errorCreatingReport("Type not supported \(type(of: build))") } let path = (output as! FileOutput).path let fileURL = URL(fileURLWithPath: path) if !FileManager.default.fileExists(atPath: fileURL.path) { // If the file doesn't exist, create an empty file FileManager.default.createFile(atPath: fileURL.path, contents: nil, attributes: nil) }

    let encoder = JSONEncoder()
    encoder.outputFormatting = .prettyPrinted

    do {
        // Open the file for appending
        let fileHandle = try FileHandle(forWritingTo: fileURL)

        // Write the opening array bracket
        fileHandle.write(Data("[\n".utf8))

        var isFirstItem = true
        for step in Set(steps.flatten()) {
            // Encode each step one at a time
            let jsonData = try encoder.encode(step)

            // Write a comma before each item except the first one
            if !isFirstItem {
                fileHandle.write(Data(",\n".utf8))
            }
            isFirstItem = false

            // Write the encoded step data
            fileHandle.write(jsonData)
        }

        // Write the closing array bracket
        fileHandle.write(Data("\n]".utf8))

        // Close the file
        fileHandle.closeFile()
    } catch {
        print("Error: \(error.localizedDescription)")
    }
}

</p>
</details> 

<details><summary>Incremental encoding</summary>
<p>

```swift
extension BuildStep {
    public func encodeIncrementally(to fileURL: URL) throws {
        let encoder = JSONEncoder()
        encoder.outputFormatting = .prettyPrinted

        // Create a file handle for writing
        FileManager.default.createFile(atPath: fileURL.path, contents: nil, attributes: nil)
        let fileHandle = try FileHandle(forWritingTo: fileURL)

        // Write opening brace
        fileHandle.write("{".data(using: .utf8)!)

        // Mirror reflection for iterating over properties
        let mirror = Mirror(reflecting: self)
        for (index, child) in mirror.children.enumerated() {
            if let label = child.label {
                let keyData = "\"\(label)\": ".data(using: .utf8)!
                fileHandle.write(keyData)

                if label == "subSteps" {
                    try encodeSubSteps(subSteps, with: encoder, to: fileHandle)
                } else {
                    if let value = child.value as? Encodable {
                        let encodedChildData = try encoder.encode(value)
                        fileHandle.write(encodedChildData)
                    }
                }

                if index < mirror.children.count - 1 {
                    fileHandle.write(",".data(using: .utf8)!)
                }
            }
        }

        // Write closing brace
        fileHandle.write("}".data(using: .utf8)!)

        // Close the file handle
        fileHandle.closeFile()
    }

    private func encodeSubSteps(_ subSteps: [BuildStep], with encoder: JSONEncoder, to fileHandle: FileHandle) throws {
        fileHandle.write("[".data(using: .utf8)!)
        for (index, subStep) in subSteps.enumerated() {
            try subStep.encodeIncrementally(to: fileHandle)
            if index < subSteps.count - 1 {
                fileHandle.write(",".data(using: .utf8)!)
            }
        }
        fileHandle.write("]".data(using: .utf8)!)
    }

    private func encodeIncrementally(to fileHandle: FileHandle) throws {
        let encoder = JSONEncoder()
        encoder.outputFormatting = .prettyPrinted

        // Write opening brace
        fileHandle.write("{".data(using: .utf8)!)

        // Mirror reflection for iterating over properties
        let mirror = Mirror(reflecting: self)
        for (index, child) in mirror.children.enumerated() {
            if let label = child.label {
                let keyData = "\"\(label)\": ".data(using: .utf8)!
                fileHandle.write(keyData)

                if label == "subSteps" {
                    try encodeSubSteps(subSteps, with: encoder, to: fileHandle)
                } else {
                    if let value = child.value as? Encodable {
                        let encodedChildData = try encoder.encode(value)
                        fileHandle.write(encodedChildData)
                    }
                }

                if index < mirror.children.count - 1 {
                    fileHandle.write(",".data(using: .utf8)!)
                }
            }
        }

        // Write closing brace
        fileHandle.write("}".data(using: .utf8)!)
    }
}

Incremental Encoding / writing thoughts:

• Well, I'm not breaking 12GB memory usage, so that's a plus. In some cases I stay under 1GB memory usage (!).
• It may be running for the next 10,000 years lmfao. I'm avoiding loading >150GB into memory by incrementally writing – but ultimately, that is being loaded into memory because that is the size of the file that the writer is attempting to write. I have >300,000 build steps to write.

I suppose I can kill this thread of exploration off in short order: There are a few other things to look into here; broadly, a way to think about this change isn't that we're replacing the SwiftCompile step – but rather that we're replacing the aggregated build step: We have logic in place for handling aggregation, and that does not go through the routes that I'm trying to jam it through currently - but before doing so, let's take a step back:

Are there any other places where we assume that swift compilation steps are CompileSwift / CompileSwift normal instead of SwiftCompile / SwiftCompile normal? The answer is… yes.

By changing this, we are now outputting flatJson, html, and other outputs without a memory explosion, in a reasonable file size, AND with function/type-check times.