Reporting/Debugging Slow Swift Compile Time


(Ben Asher) #1

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).

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). 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


(Mark Lacey) #2

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 <http://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

···

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@swift.org> wrote:

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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev


(Brian Gesiak) #3

Hi Ben,

I'd really like to see improvements here as well. I don't know what reports
would be useful to the Swift team, but allow me to point out
https://github.com/apple/swift/commit/18c75928639acf0ccf0e1fb6729eea75bc09cbd5,
which adds a -warn-long-function-bodies option that you may be able to use.

However, as stated in the commit message I linked to above, both
-debug-time-function-bodies and -warn-long-function-bodies are frontend
options. They are not officially supported, and may be removed at any time
without warning.

Personally, I think the Swift compiler should provide users with more
information about compilation times. In
https://bugs.swift.org/browse/SR-2741, Brian Michel (cc'ed) describes a
feature he'd like to see: structured output from the Swift compiler driver,
as an official, supported option. Your team's use case sounds very similar
to his, so I'd encourage you to chime in on that issue with your thoughts.

- Brian Gesiak

···

On Tue, Oct 4, 2016 at 5:38 PM, Ben Asher via swift-dev <swift-dev@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).

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). 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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev


(Ben Asher) #4

I didn't know about that warning, so thanks for sharing that! Having this
enabled will help somewhat, at least in terms of keeping specific
slow-to-compile functions out of our master branch.

That said, I understand Jordan's response (in SR-2741) of being "leery of
'productizing'" these flags. Developing with Swift shouldn't involve
fighting the compiler to get the best compile time, so making this more
than a debug flag does seem odd/worrisome.

I'm more interested in the best way to get a feedback loop to understand
what the known issues are and see them addressed. This has already worked
well with fixes for big slowdown issues like SR-1277 and this well known
patch:
https://github.com/apple/swift/commit/2cdd7d64e1e2add7bcfd5452d36e7f5fc6c86a03
.

···

On Wed, Oct 5, 2016 at 11:47 AM, Brian Gesiak <modocache@gmail.com> wrote:

Hi Ben,

I'd really like to see improvements here as well. I don't know what
reports would be useful to the Swift team, but allow me to point out
https://github.com/apple/swift/commit/18c75928639acf0ccf0e1fb6729eea
75bc09cbd5, which adds a -warn-long-function-bodies option that you may
be able to use.

However, as stated in the commit message I linked to above, both
-debug-time-function-bodies and -warn-long-function-bodies are frontend
options. They are not officially supported, and may be removed at any time
without warning.

Personally, I think the Swift compiler should provide users with more
information about compilation times. In https://bugs.swift.org/
browse/SR-2741, Brian Michel (cc'ed) describes a feature he'd like to
see: structured output from the Swift compiler driver, as an official,
supported option. Your team's use case sounds very similar to his, so I'd
encourage you to chime in on that issue with your thoughts.

- Brian Gesiak

On Tue, Oct 4, 2016 at 5:38 PM, Ben Asher via swift-dev < > swift-dev@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).

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). 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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben


(Ben Asher) #5

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@apple.com> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben


(Ben Asher) #6

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.

Is there any profiling/tracing you all would recommend to help find problem
areas? 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@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@apple.com> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben


(Graydon Hoare) #7

If you can collect an instruments profile of the frontend running one of the particularly-slow files, it might help localize the subsystem of the typechecker; aside from that, I'm currently putting some new counters and timers in the frontend, so am likely to have slightly more-constructive news in the next little while, but don't have that work done just yet.

For collecting an instruments profile, try something like:

  $ SWIFTBIN=/Applications/Xcode.app/Contents/Developer/Toolchains/XcodeDefault.xctoolchain/usr/bin/swift
  $ instruments -t 'Time Profiler' $SWIFTBIN -frontend -parse somefile.swift
  $ open instrumentscli0.trace

Then expand all (option-click the triangle next to 'swift' in the call-tree), select-all, copy and paste the complete call-tree into a text file and attach it here, that might give a bit of insight. On my local copy of instruments one also has to toggle the "separate by state" box of the details pane to get the full call-tree to expand, not sure why; might just be a transient bug.

-Graydon

···

On Oct 5, 2016, at 3:37 PM, Ben Asher via swift-dev <swift-dev@swift.org> 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.

Is there any profiling/tracing you all would recommend to help find problem areas? 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@gmail.com <mailto:benasher44@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@apple.com <mailto:mark.lacey@apple.com>> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@swift.org <mailto:swift-dev@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 <http://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@swift.org <mailto:swift-dev@swift.org>
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben
_______________________________________________
swift-dev mailing list
swift-dev@swift.org <mailto:swift-dev@swift.org>
https://lists.swift.org/mailman/listinfo/swift-dev


(Mark Lacey) #8

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

···

On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44@gmail.com> wrote:

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@gmail.com <mailto:benasher44@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@apple.com <mailto:mark.lacey@apple.com>> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@swift.org <mailto:swift-dev@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 <http://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@swift.org <mailto:swift-dev@swift.org>
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben


(Ben Asher) #9

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@apple.com> wrote:

On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44@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@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@apple.com> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben

--
-Ben


(Ben Asher) #10

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.

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@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@apple.com> wrote:

On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44@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@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@apple.com> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev < >>>> swift-dev@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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben

--
-Ben

--
-Ben


(Mark Lacey) #11

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

···

On Oct 7, 2016, at 2:35 PM, Ben Asher <benasher44@gmail.com> wrote:

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@gmail.com <mailto:benasher44@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@apple.com <mailto:mark.lacey@apple.com>> wrote:

On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44@gmail.com <mailto:benasher44@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@gmail.com <mailto:benasher44@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@apple.com <mailto:mark.lacey@apple.com>> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <swift-dev@swift.org <mailto:swift-dev@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 <http://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@swift.org <mailto:swift-dev@swift.org>
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben

--
-Ben

--
-Ben


(Ben Asher) #12

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@apple.com> wrote:

On Oct 7, 2016, at 2:35 PM, Ben Asher <benasher44@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@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@apple.com> wrote:

On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44@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@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@apple.com> >>>> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev < >>>>> swift-dev@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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben

--
-Ben

--
-Ben

--
-Ben


(Ben Asher) #13

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@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@apple.com> wrote:

On Oct 7, 2016, at 2:35 PM, Ben Asher <benasher44@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@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@apple.com> wrote:

On Oct 5, 2016, at 3:37 PM, Ben Asher <benasher44@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@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@apple.com> >>>>> wrote:

On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev < >>>>>> swift-dev@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@swift.org
https://lists.swift.org/mailman/listinfo/swift-dev

--
-Ben

--
-Ben

--
-Ben

--
-Ben

--
-Ben

--
-Ben