[swift-dev] Reporting/Debugging Slow Swift Compile Time

[Ben Asher]

I've opened a few jira tickets:

- https://bugs.swift.org/browse/SR-2901 for this bug (has some numbers on
the impact in our project)
- https://bugs.swift.org/browse/SR-2902 for adding the expression type
checker timer, since it's looking like I won't have time to get to in the
next 2 weeks

I've also opened a PR to increase the number of decimal places logged by
-debug-time-function-bodies from 1 to 3, which was useful to determine the
impact of the bug in SR-2901 (i.e. functions that less than 0.1ms to parse,
but are parsed many times), here: https://github.com/apple/swift/pull/5200.

Thanks again!

Ben

On Sat, Oct 8, 2016 at 10:34 AM, Ben Asher <benasher44 at gmail.com> wrote:

> Okay great I'll open one soon! And just to clarify, that 2521 number is
> counting the generated setters and getters (there are fewer number of
> actual lines of "let" and "var" property code).
>
> In the main target, there are 607 .swift files (guess we can deduce that
> those properties are parsed once per file in the target) and 2012 .m files.
> The build times I mentioned earlier (~7min) were debug builds after
> cleaning only for the main target (not including test targets). Building
> the main target after a clean requires building some framework and
> extension targets (iOS extensions), but those are built pretty quickly and
> are small.
>
> Ben
>
> On Sat, Oct 8, 2016 at 12:04 AM, Mark Lacey <mark.lacey at apple.com> wrote:
>
>>
>> On Oct 7, 2016, at 2:35 PM, Ben Asher <benasher44 at gmail.com> wrote:
>>
>> Hello again! I wanted to follow up with some more numbers and feedback. I
>> wasn't able to easily compile a single file from our project from the CLI.
>> I started putting together a command with all of the necessary framework
>> includes, flags, etc., but I moved on because it was taking awhile,
>> becoming a mess, and figured the other suggestions might yield results
>> quicker.
>>
>> Moving on, I took a second look at the -debug-time-function-bodies output
>> as Mark suggested, and I found that we have 2521 properties that are parsed
>> 607 times each. If we got that down to the ideal case of parsing each one
>> of those properties once, that would save us ~1.5 million "parses". So, is
>> there a ticket already for this issue? I didn't see one when I searched,
>> but it does sound like it's known.
>>
>>
>> The fact that we type check the bodies of synthesized accessors multiple
>> times is something a handful of people are aware of, but I’m not aware of
>> any JIRA bug for it so it would be great to open one if you get a chance.
>>
>> Out of curiosity, how many files are in your project, and how long does a
>> clean build take (debug build, without optimizations)?
>>
>> Mark
>>
>>
>> I do plan on at least taking a look at adding the suggested timers, but
>> that will likely take me into next week or longer depending on what else I
>> have going on.
>>
>> Thanks!
>>
>> Ben
>>
>> On Wed, Oct 5, 2016 at 4:31 PM, Ben Asher <benasher44 at gmail.com> wrote:
>>
>>> Ah this is all super helpful. I'll do some more profiling and try to get
>>> back with some data in the next several days.
>>>
>>> Thanks!
>>>
>>> Ben
>>>
>>> On Wed, Oct 5, 2016 at 4:28 PM, Mark Lacey <mark.lacey at apple.com> wrote:
>>>
>>>>
>>>> On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44 at gmail.com> wrote:
>>>>
>>>> I just tried with both Xcode 8.1 beta 2 and Xcode 8.0, and 8.1b2 seems
>>>> maybe 15s faster (to build our main huge target): 7m28s compared to 7m43s.
>>>> It's some improvement, but I'm not exactly sure what kind of improvement
>>>> was expected.
>>>>
>>>>
>>>> The kind of benefit you might expect really depends on the specific
>>>> code you’ve written. The changes I have in mind attempt to speed up the
>>>> expression type checker (the thing that does the work of inferring types
>>>> for a given expression, and the case where there is an explicit type the
>>>> expression needs to type-check to, ensuring that it does). These
>>>> expressions include things like array literals and dictionary literals,
>>>> where we sometimes take a long time to type check.
>>>>
>>>> Is there any profiling/tracing you all would recommend to help find
>>>> problem areas?
>>>>
>>>>
>>>> If you’re looking for problem areas in your particular build, I have a
>>>> couple suggestions:
>>>>
>>>> 1. Take a look at the output of -debug-time-function-bodies to see if
>>>> the same function is getting type checked multiple times, and determine
>>>> what the cumulative time for those functions is.
>>>>
>>>> For example below is the output I see for a simple test case. Note that
>>>> the getter/setter that are generated from a property on line 2 of two.swift
>>>> are type checked twice. Although in this case we type check the individual
>>>> functions very quickly, if you have enough of this kind of redundant type
>>>> checking happening, it can add up. This *particular* case is a known bug
>>>> that we hope to address - the synthesized getters/setters for properties
>>>> are type checked in each file they are referenced in.
>>>>
>>>> There may be other cases like this that we’re not already aware of, so
>>>> it’s always good to open a bug if you find something like this.
>>>>
>>>> swiftc -c main.swift two.swift -module-name test -Xfrontend
>>>> -debug-time-function-bodies
>>>> 0.2ms main.swift:2:7 get {}
>>>> 0.2ms main.swift:2:7 set {}
>>>> 0.0ms main.swift:1:7 @objc deinit
>>>> 0.3ms main.swift:1:13 override init()
>>>> 0.2ms two.swift:2:14 get {}
>>>> 0.2ms two.swift:2:14 set {}
>>>> 0.2ms two.swift:2:14 get {}
>>>> 0.2ms two.swift:2:14 set {}
>>>> 0.0ms two.swift:1:14 @objc deinit
>>>> 0.0ms two.swift:1:14 init()
>>>>
>>>> 2. Add a timer for expression type checking and see if that helps
>>>> narrow down whether there is time being spent type checking expressions
>>>> that isn’t accounted for in -debug-time-function-bodies. There are a few
>>>> places that might make sense for this, but I suspect ConstraintSystem::solve()
>>>> might be the best. This is ultimately called from a variety of places, and
>>>> would provide the most insight into where time is being spent in the
>>>> expression type checking. It’s possible something higher up the stack, like
>>>> TypeChecker::solveForExpression or TypeChecker::typeCheckExpression()
>>>> might make more sense as well. You can model this on how
>>>> -debug-time-function-bodies is currently implemented, e.g. look
>>>> at swift::performTypeChecking for some help on getting started. I’ll
>>>> probably try to add this timer myself in the next few weeks if you don’t
>>>> manage to beat me to it.
>>>>
>>>> Mark
>>>>
>>>>
>>>> I don't mind building from Swift master, using someone's preferred
>>>> profiling tools, etc. I'm not really sure where to start.
>>>>
>>>> Ben
>>>>
>>>> On Wed, Oct 5, 2016 at 1:05 PM, Ben Asher <benasher44 at gmail.com> wrote:
>>>>
>>>>> Apologies for not starting off with system info: macOS Sierra
>>>>> (10.12.0), Xcode 8.0 (from the App Store).
>>>>>
>>>>> I'll try with Xcode 8.1 beta this afternoon and report back. Ill also
>>>>> open a ticket for improving -debug-time-function-bodies if I can confirm
>>>>> anything.
>>>>>
>>>>> Thanks!
>>>>>
>>>>> Ben
>>>>>
>>>>> On Wed, Oct 5, 2016 at 1:00 PM, Mark Lacey <mark.lacey at apple.com>
>>>>> wrote:
>>>>>
>>>>>>
>>>>>> On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <
>>>>>> swift-dev at swift.org> wrote:
>>>>>>
>>>>>> Hello! I work with a large project (~900 .swift files and more .m
>>>>>> files). We have a nightly job that compiles the app and calls out function
>>>>>> bodies (using -debug-time-function-bodies) that are slower than
>>>>>> 100ms to compile. Since upgrading to Swift 3, the number of trouble
>>>>>> function bodies has one from > 150 to < 20, so we're really happy about
>>>>>> that! The only issue though is that build time overall increased by ~1 min
>>>>>> (amount of time to build all targets before automatically merging to master
>>>>>> in our integration build).
>>>>>>
>>>>>>
>>>>>> Is this using a particular release of Xcode (8.0 or an 8.1 beta?), or
>>>>>> with one of the toolchain builds from swift.org?
>>>>>>
>>>>>> Xcode 8.1 beta 2 includes some type checker performance improvements
>>>>>> which might have an impact here.
>>>>>>
>>>>>>
>>>>>> To dig into this further, we've started a new nightly job that builds
>>>>>> the app using the -debug-time-compilation flag, and using that we've found
>>>>>> that some files take as long as 2-3 seconds to compile. But, there's no
>>>>>> targeted output to help us get this down via the
>>>>>> -debug-time-function-bodies flag (i.e. no function bodies that we can
>>>>>> refactor to get compile times much faster).
>>>>>>
>>>>>>
>>>>>> One thing to look out for here is that I believe there are some cases
>>>>>> where -debug-time-function-bodies isn’t reporting type checking time. From
>>>>>> my (potentially faulty) recollection, things like let bindings with
>>>>>> literals or closures on the right hand side do not show up in the
>>>>>> -debug-time-function-bodies output, and depending on the specifics of the
>>>>>> expression these can sometimes take a long time to type check. When these
>>>>>> appear within the body of another type declaration they can end up getting
>>>>>> type checked multiple times during a full project build, and that time can
>>>>>> add up.
>>>>>>
>>>>>> I don’t believe there is a bug open for improving
>>>>>> -debug-time-function-bodies to help diagnose this, but opening a bug would
>>>>>> be appreciated if you can confirm that this is the case, and of course
>>>>>> patches to fix it are definitely welcome as well.
>>>>>>
>>>>>> Mark
>>>>>>
>>>>>> We can see that most of the time is spent in "Type checking /
>>>>>> Semantic analysis" for these problem files, but we don't currently have any
>>>>>> way of knowing what that means. It feels like we've exhausted the available
>>>>>> options at this point (unless there are other flags I'm missing) in terms
>>>>>> of existing actionable debugging/profiling/reporting, so now our question
>>>>>> is this: what kind of reports would Swift maintainers be interested in
>>>>>> seeing in terms of output from profiling tools, etc. to help debug/diagnose
>>>>>> these slow compile issues? We're willing to devote time to tooling to help
>>>>>> generate such reports and file bugs.
>>>>>>
>>>>>> Thanks!
>>>>>>
>>>>>> Ben
>>>>>> _______________________________________________
>>>>>> swift-dev mailing list
>>>>>> swift-dev at swift.org
>>>>>> https://lists.swift.org/mailman/listinfo/swift-dev
>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>> --
>>>>> -Ben
>>>>>
>>>>
>>>>
>>>>
>>>> --
>>>> -Ben
>>>>
>>>>
>>>>
>>>
>>>
>>> --
>>> -Ben
>>>
>>
>>
>>
>> --
>> -Ben
>>
>>
>>
>
>
> --
> -Ben
>



-- 
-Ben
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.swift.org/pipermail/swift-dev/attachments/20161009/ed24e1f6/attachment.html>