Build log on the CLI lags behind actual build operations

[finagolfin]

Is it reproducible with SwiftPM command-line tools: swift build, swift test, swift package etc?

• Confirmed reproduction steps with SwiftPM CLI. The description text must include reproduction steps with either of command-line SwiftPM commands, swift build, swift test, swift package etc.

Description

I've been building repos with some files that compile slowly lately and the SwiftPM console output never lists the actual file that's slow. I looked into this in the source this weekend, and the issue is that LLBuildProgressTracker only prints to the console when a task is finished, but puts out messages like Compiling SwiftSyntax Tokens.swift once that compilation is over, ie misleading that the operation is still ongoing.

Looking at the source of Build/LLBuildProgressTracker.swift and running a few builds after modifying that file, it gets output from two sources, the Swift compiler and llbuild, which handles linking executables and building C and C++. The Swift compiler signals when it starts and finishes an operation, but llbuild only appears to do so when finished. However, SwiftPM ignores when the Swift compiler starts an operation, and only prints "Compiling..." and so on when the operation is finished.

I was able to improve this with this small patch, to print the same output when the Swift compiler starts, rather than when it finishes, removing a now unnecessary dictionary in the process:

diff --git a/Sources/Build/LLBuildProgressTracker.swift b/Sources/Build/LLBuildProgressTracker.swift
index 9f79f6f93..c319bce0d 100644
--- a/Sources/Build/LLBuildProgressTracker.swift
+++ b/Sources/Build/LLBuildProgressTracker.swift
@@ -502,7 +502,6 @@ final class LLBuildProgressTracker: LLBuildBuildSystemDelegate, SwiftCompilerOut
 private struct CommandTaskTracker {
     private(set) var totalCount = 0
     private(set) var finishedCount = 0
-    private var swiftTaskProgressTexts: [Int: String] = [:]
 
     /// The last task text before the task list was emptied.
     private(set) var latestFinishedText: String?
@@ -533,17 +532,12 @@ private struct CommandTaskTracker {
         switch message.kind {
         case .began(let info):
             if let text = progressText(of: message, targetName: targetName) {
-                self.swiftTaskProgressTexts[info.pid] = text
                 self.onTaskProgressUpdateText?(text, targetName)
+                self.latestFinishedText = text
             }
 
             self.totalCount += 1
         case .finished(let info):
-            if let progressText = swiftTaskProgressTexts[info.pid] {
-                self.latestFinishedText = progressText
-                self.swiftTaskProgressTexts[info.pid] = nil
-            }
-
             self.finishedCount += 1
         case .unparsableOutput, .abnormal, .signalled, .skipped:
             break

Trying this modified Sep. 4 trunk snapshot of SwiftPM with the same slow package builds shows that it correctly identifies the slow Swift compilation now.

However, slow C++ builds are still not identified correctly, as that would require llbuild to notify when a build operation started, not when it finished, as the Swift compiler already does.

@hartbit, you added this in #2064 several years ago, let me know what you think of this timing tweak.

@neonichu and @dmbryson from the llbuild side, perhaps either of you has an opinion.

Expected behavior

If you're going to say an action is ongoing, you should trigger the console output at the start of the action, not the finish. Obviously, this doesn't matter most of the time when it flies by so fast that nobody looks at the output, but for the times you need it, it should report the right output.

Actual behavior

Say some build action Linking giant-exe is really slow. Rather than SwiftPM saying that is what is doing, it will show the previously completed action output Write Objects.LinkFileList until that slow linking is done.

Steps to reproduce

swift build for any repo with some slow build operation, such as swift-foundation-icu

Swift Package Manager version/commit hash

swift-DEVELOPMENT-SNAPSHOT-2024-09-04-a

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

All Swift versions I've tried on linux and Android

[rauhul]

You may want to try #7897. I also got annoyed by the progress tracker but took a more aggressive approach than described here.

I'm having a little trouble finding time to complete the feature. If you're interested, I'm open to collaborating on it.

[finagolfin]

Thanks, that looks fantastic! It appears you already addressed this issue in that WIP pull.

I'm having a little trouble finding time to complete the feature. If you're interested, I'm open to collaborating on it.

I will build it locally and can give feedback and tweaks, but I doubt much more than that.

Did you investigate if llbuild can be made to signal on starting build commands also, not just when they're finished? I notice you're stuck with that same problem for llbuild output, but your seemingly much more detailed build output may not need that info as much.

[dschaefer2]

While waiting for this bigger feature, I'm going to add finish logs with timings to the verbose mode. I'll get that up on Monday. It was helping me understand Windows builds last week.