[SR-2741] Provide Structured Output Of debug-time-function-bodies

[swift-ci]

Previous ID	SR-2741
Radar	None
Original Reporter	brianmichel (JIRA User)
Type	New Feature

Additional Detail from JIRA

Votes	0
Component/s	Compiler
Labels	New Feature
Assignee	None
Priority	Medium

md5: 2b0d14b89fce57f3a471a2e44343479a

Issue Description:

Right now when a user runs the Swift compiler with the debug-time-function-bodies parameter the important output yielded by this parameter is dumped inline with the rest of the build information similar to the following:

CompileSwift normal armv7 /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift
    cd /Users/brianmichel/Development/Personal/Sketchy
    /Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/swift -frontend -c /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/AppDelegate.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/PaletteColorView.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/DrawingViewController.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CameraManager.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/Drawing.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/ViewController.swift -primary-file /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/StillUIImageProcessor.swift /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSessionProcessor.swift -target armv7-apple-ios9.2 -enable-objc-interop -sdk /Applications/Xcode.app/Contents/Developer/Platforms/iPhoneOS.platform/Developer/SDKs/iPhoneOS10.0.sdk -I /Users/brianmichel/Development/Personal/Sketchy/build/Debug-iphoneos -F /Users/brianmichel/Development/Personal/Sketchy/build/Debug-iphoneos -enable-testing -g -debug-time-function-bodies -serialize-debugging-options -Xcc -I/Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/swift-overrides.hmap -Xcc -iquote -Xcc /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Sketchy-generated-files.hmap -Xcc -I/Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Sketchy-own-target-headers.hmap -Xcc -I/Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Sketchy-all-target-headers.hmap -Xcc -iquote -Xcc /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Sketchy-project-headers.hmap -Xcc -I/Users/brianmichel/Development/Personal/Sketchy/build/Debug-iphoneos/include -Xcc -I/Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/DerivedSources/armv7 -Xcc -I/Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/DerivedSources -Xcc -DDEBUG=1 -Xcc -working-directory/Users/brianmichel/Development/Personal/Sketchy -emit-module-doc-path /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Objects-normal/armv7/CaptureSession~partial.swiftdoc -Onone -module-name Sketchy -emit-module-path /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Objects-normal/armv7/CaptureSession~partial.swiftmodule -serialize-diagnostics-path /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Objects-normal/armv7/CaptureSession.dia -emit-dependencies-path /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Objects-normal/armv7/CaptureSession.d -emit-reference-dependencies-path /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Objects-normal/armv7/CaptureSession.swiftdeps -o /Users/brianmichel/Development/Personal/Sketchy/build/Sketchy.build/Debug-iphoneos/Sketchy.build/Objects-normal/armv7/CaptureSession.o -embed-bitcode-marker
0.1ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:17:21  final get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:18:21  final get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:20:21  final get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:22:21  final get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:23:21  final get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:25:21  get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:25:21  set {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:27:21  get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:27:21  set {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:29:21  get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:29:21  set {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:31:14  @objc get {}
0.0ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:31:14  @objc set {}
0.1ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:33:47  @objc get {}
0.7ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:37:47  get {}
12.2ms  /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:41:59  @objc get {}
0.3ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:45:14  @objc override init()
2.6ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:52:15  open func addProcessor(_ processor: CaptureSessionProcessor!)
0.2ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:56:15  open func removeProcessor(_ processor: CaptureSessionProcessor!)
0.8ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:66:47  (closure)
1.4ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:60:15  open func switchCameraInput(_ position: CaptureDevicePosition!) -> Bool!
2.1ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:82:106 (closure)
2.5ms   /Users/brianmichel/Development/Personal/Sketchy/Sketchy/Classes/CaptureSession.swift:80:15  @objc open func captureStillImage()

This means that in order to extract the information relevant to compile time complexity, each end user must craft some sort of output parsing logic to extract the relevant logs while not breaking them at the same time.

I'd like if the Swift compiler was able to accept an option to output the debug-time-function-bodies into a structured data format like XML to make it easy to both locate and parse this data in a machine friendly ways (like for continuous integration environments)

[modocache]

/cc @belkadan. Maybe we could hook this up to the serialized diagnostics consumer...? I'd be interested in taking this task on, so if you have any tips I'd love to hear them. 🙂

[belkadan]

I'm leery of "productizing" -debug-time-function-bodies in any way because it's already not a true story. Import and decl-checking costs that come up for the first time during a particular function get ascribed to that function. SILGen, optimization, and LLVM costs are ignored entirely. Decl-checking costs that are not within a particular function are also ignored.

The only useful purpose of -debug-time-function-bodies is to see if the type checker is spinning on a particular function.

[swift-ci]

Comment by Brian Michel (JIRA)

@belkadan yeah I totally understand this is a debug option (it's even in the name!), but I guess I'm unsure what else to do to keep an eye on Swift compile times in larger applications across an entire team of engineers. Granted, we've already somewhat built tooling around this here, https://github.com/tumblr/SwiftCompilationPerformanceReporter, it'd be nice to see this as a first class feature.

I would understand that if the larger conversation should be around how to not get into these slow compile paths, or totally eliminating these kinds of possibilities elsewhere in the compiler, but those seems like very long term conversations. I'm also not sure how widespread this problem actually is. We at Tumblr have certainly experienced this, but maybe we're a one off.

Would love to hear more of your thoughts on the matter.

[modocache]

I've seen a fair amount of "how to figure out what's slowing down your Swift compile times" blog posts:

• https://thatthinginswift.com/debug-long-compile-times-swift/

• http://irace.me/swift-profiling

I think providing structured output to analyze compilation times would help brianmichel (JIRA User) and many others. Maybe -debug-time-function-bodies isn't the best data to format. In that case, perhaps we can provide formatting for a different format (-driver-time-compilation?), or add options for other interesting profile data.

I would understand that if the larger conversation should be around how to not get into these slow compile paths, or totally eliminating these kinds of possibilities elsewhere in the compiler, but those seems like very long term conversations.

I agree. I also think these tools would help end users discover situations that lead to slow compilation times, so that they can submit Swift reports for those situations.