<html><head><meta http-equiv="Content-Type" content="text/html charset=utf-8"></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" class=""><br class=""><div><blockquote type="cite" class=""><div class="">On Oct 7, 2016, at 2:35 PM, Ben Asher <<a href="mailto:benasher44@gmail.com" class="">benasher44@gmail.com</a>> wrote:</div><br class="Apple-interchange-newline"><div class=""><div dir="ltr" class="">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.<div class=""><br class=""></div><div class="">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.</div></div></div></blockquote><div><br class=""></div>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.</div><div><br class=""></div><div>Out of curiosity, how many files are in your project, and how long does a clean build take (debug build, without optimizations)?</div><div><br class=""></div><div>Mark</div><div><br class=""></div><div><blockquote type="cite" class=""><div class=""><div dir="ltr" class=""><div class=""><br class=""></div><div class="">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.</div><div class=""><br class=""></div><div class="">Thanks!</div><div class=""><br class=""></div><div class="">Ben</div></div><div class="gmail_extra"><br class=""><div class="gmail_quote">On Wed, Oct 5, 2016 at 4:31 PM, Ben Asher <span dir="ltr" class=""><<a href="mailto:benasher44@gmail.com" target="_blank" class="">benasher44@gmail.com</a>></span> wrote:<br class=""><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr" class="">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.<div class=""><br class=""></div><div class="">Thanks!</div><div class=""><br class=""></div><div class="">Ben</div></div><div class="gmail_extra"><div class=""><div class="h5"><br class=""><div class="gmail_quote">On Wed, Oct 5, 2016 at 4:28 PM, Mark Lacey <span dir="ltr" class=""><<a href="mailto:mark.lacey@apple.com" target="_blank" class="">mark.lacey@apple.com</a>></span> wrote:<br class=""><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div style="word-wrap:break-word" class=""><div dir="auto" style="word-wrap:break-word" class=""><br class=""><div class=""><span class=""><blockquote type="cite" class=""><div class="">On Oct 5, 2016, at 3:37 PM, Ben Asher <<a href="mailto:benasher44@gmail.com" target="_blank" class="">benasher44@gmail.com</a>> wrote:</div><br class="m_5069588762882230325m_5627014850722318666Apple-interchange-newline"><div class=""><div dir="ltr" class="">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.</div></div></blockquote><div class=""><br class=""></div></span><div class="">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.</div><span class=""><br class=""><blockquote type="cite" class=""><div class=""><div dir="ltr" class=""><div class="">Is there any profiling/tracing you all would recommend to help find problem areas?</div></div></div></blockquote><div class=""><br class=""></div></span><div class="">If you’re looking for problem areas in your particular build, I have a couple suggestions:</div><div class=""><br class=""></div><div class="">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.</div><div class=""><br class=""></div><div class="">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.</div><div class=""><br class=""></div><div class="">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.</div><div class=""><br class=""></div><div class=""><div class="">swiftc -c main.swift two.swift -module-name test -Xfrontend -debug-time-function-bodies<br class="">0.2ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>main.swift:2:7<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>get {}<br class="">0.2ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>main.swift:2:7<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>set {}<br class="">0.0ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>main.swift:1:7<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>@objc deinit<br class="">0.3ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>main.swift:1:13<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>override init()<br class="">0.2ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>two.swift:2:14<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>get {}<br class="">0.2ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>two.swift:2:14<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>set {}<br class="">0.2ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>two.swift:2:14<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>get {}<br class="">0.2ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>two.swift:2:14<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>set {}<br class="">0.0ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>two.swift:1:14<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>@objc deinit<br class="">0.0ms<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>two.swift:1:14<span class="m_5069588762882230325m_5627014850722318666Apple-tab-span" style="white-space:pre-wrap"> </span>init()</div></div><div class=""><br class=""></div><div class="">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::solv<wbr class="">e() 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::solveForExpressio<wbr class="">n or TypeChecker::typeCheckExpressi<wbr class="">on() 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.</div><span class="m_5069588762882230325HOEnZb"><font color="#888888" class=""><div class=""><br class=""></div><div class="">Mark</div></font></span><div class=""><div class="m_5069588762882230325h5"><div class=""><br class=""></div><br class=""><blockquote type="cite" class=""><div class=""><div dir="ltr" class=""><div class=""> I don't mind building from Swift master, using someone's preferred profiling tools, etc. I'm not really sure where to start.<br class=""><div class=""><br class=""></div><div class="">Ben</div></div></div><div class="gmail_extra"><br class=""><div class="gmail_quote">On Wed, Oct 5, 2016 at 1:05 PM, Ben Asher <span dir="ltr" class=""><<a href="mailto:benasher44@gmail.com" target="_blank" class="">benasher44@gmail.com</a>></span> wrote:<br class=""><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr" class="">Apologies for not starting off with system info: macOS Sierra (10.12.0), Xcode 8.0 (from the App Store).<div class=""><br class=""></div><div class="">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.</div><div class=""><br class=""></div><div class="">Thanks!</div><div class=""><br class=""></div><div class="">Ben</div></div><div class="gmail_extra"><div class=""><div class="m_5069588762882230325m_5627014850722318666h5"><br class=""><div class="gmail_quote">On Wed, Oct 5, 2016 at 1:00 PM, Mark Lacey <span dir="ltr" class=""><<a href="mailto:mark.lacey@apple.com" target="_blank" class="">mark.lacey@apple.com</a>></span> wrote:<br class=""><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div style="word-wrap:break-word" class=""><br class=""><div class=""><span class=""><blockquote type="cite" class=""><div class="">On Oct 4, 2016, at 2:38 PM, Ben Asher via swift-dev <<a href="mailto:swift-dev@swift.org" target="_blank" class="">swift-dev@swift.org</a>> wrote:</div><br class="m_5069588762882230325m_5627014850722318666m_2386091958347163566m_1098956126652972838Apple-interchange-newline"><div class=""><div dir="ltr" class="">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-bo<wbr class="">dies) 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).</div></div></blockquote><div class=""><br class=""></div></span>Is this using a particular release of Xcode (8.0 or an 8.1 beta?), or with one of the toolchain builds from <a href="http://swift.org/" target="_blank" class="">swift.org</a>?</div><div class=""><br class=""></div><div class="">Xcode 8.1 beta 2 includes some type checker performance improvements which might have an impact here.</div><div class=""><span class=""><br class=""><blockquote type="cite" class=""><div class=""><div dir="ltr" class=""><div class=""><br class=""></div><div class="">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).</div></div></div></blockquote><div class=""><br class=""></div></span><div class="">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.</div><div class=""><br class=""></div><div class="">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.</div><span class="m_5069588762882230325m_5627014850722318666m_2386091958347163566HOEnZb"><font color="#888888" class=""><div class=""><br class=""></div><div class="">Mark</div><br class=""></font></span><blockquote type="cite" class=""><div class=""><span class=""><div dir="ltr" class=""><div class=""> 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.</div><div class=""><br class=""></div><div class="">Thanks!<br clear="all" class=""><div class=""><br class=""></div><div class="m_5069588762882230325m_5627014850722318666m_2386091958347163566m_1098956126652972838gmail_signature"><div dir="ltr" class="">Ben</div></div>
</div></div></span><span class="">
______________________________<wbr class="">_________________<br class="">swift-dev mailing list<br class=""><a href="mailto:swift-dev@swift.org" target="_blank" class="">swift-dev@swift.org</a><br class=""><a href="https://lists.swift.org/mailman/listinfo/swift-dev" target="_blank" class="">https://lists.swift.org/mailma<wbr class="">n/listinfo/swift-dev</a><br class=""></span></div></blockquote></div><br class=""></div></blockquote></div><br class=""><br clear="all" class=""><div class=""><br class=""></div></div></div><span class="m_5069588762882230325m_5627014850722318666HOEnZb"><font color="#888888" class="">-- <br class=""><div class="m_5069588762882230325m_5627014850722318666m_2386091958347163566gmail_signature" data-smartmail="gmail_signature"><div dir="ltr" class="">-Ben</div></div>
</font></span></div>
</blockquote></div><br class=""><br clear="all" class=""><div class=""><br class=""></div>-- <br class=""><div class="m_5069588762882230325m_5627014850722318666gmail_signature" data-smartmail="gmail_signature"><div dir="ltr" class="">-Ben</div></div>
</div>
</div></blockquote></div></div></div><br class=""></div></div></blockquote></div><br class=""><br clear="all" class=""><div class=""><br class=""></div></div></div><span class="HOEnZb"><font color="#888888" class="">-- <br class=""><div class="m_5069588762882230325gmail_signature" data-smartmail="gmail_signature"><div dir="ltr" class="">-Ben</div></div>
</font></span></div>
</blockquote></div><br class=""><br clear="all" class=""><div class=""><br class=""></div>-- <br class=""><div class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr" class="">-Ben</div></div>
</div>
</div></blockquote></div><br class=""></body></html>