Version 2.0.3 has significant performance issues

[bsrz]

Upgrading to 2.0.3 causes code generation to take something like 10x more time.

[art-divin]

👋 Hello @bsrz ,

thank you for raising the awareness about the performance issue.

Could you please provide a little more context, what is the exact issue - to be able to understand and investigate, because I cannot think of anything from the top of my head - which template format do you use, swift compiler version etc.

Please provide as many details as possible,

Thank you 👍🏻

[bsrz]

@art-divin apologies, I should have included more information.

Here's an example, we generate a ton of tests:

$ sourcery --version
2.0.2

$ time bundle exec fastlane generate_all_tests
[✔] 🚀
+---------------------------+---------+-------------------------------------------------------------+
|                                           Used plugins                                            |
+---------------------------+---------+-------------------------------------------------------------+
| Plugin                    | Version | Action                                                      |
+---------------------------+---------+-------------------------------------------------------------+
| fastlane-plugin-appcenter | 2.1.0   | appcenter_codepush_release_react, appcenter_fetch_devices,  |
|                           |         | appcenter_fetch_version_number, appcenter_upload            |
+---------------------------+---------+-------------------------------------------------------------+

[11:37:47]: -------------------------------------------------------------
[11:37:47]: --- Step: Switch to ios generate_accessibility_tests lane ---
[11:37:47]: -------------------------------------------------------------
[11:37:47]: Cruising over to lane 'ios generate_accessibility_tests' 🚖
[11:37:58]: Cruising back to lane 'ios generate_all_tests' 🚘
[11:37:58]: ------------------------------------------------------------
[11:37:58]: --- Step: Switch to ios generate_designsystem_tests lane ---
[11:37:58]: ------------------------------------------------------------
[11:37:58]: Cruising over to lane 'ios generate_designsystem_tests' 🚖
[11:38:01]: Cruising back to lane 'ios generate_all_tests' 🚘
[11:38:01]: --------------------------------------------------------
[11:38:01]: --- Step: Switch to ios generate_snapshot_tests lane ---
[11:38:01]: --------------------------------------------------------
[11:38:01]: Cruising over to lane 'ios generate_snapshot_tests' 🚖
[11:38:13]: Cruising back to lane 'ios generate_all_tests' 🚘
[11:38:13]: ----------------------------------------------------------
[11:38:13]: --- Step: Switch to ios generate_styleguide_tests lane ---
[11:38:13]: ----------------------------------------------------------
[11:38:13]: Cruising over to lane 'ios generate_styleguide_tests' 🚖
[11:38:13]: Cruising back to lane 'ios generate_all_tests' 🚘

+------+-------------------------------------------------+-------------+
|                           fastlane summary                           |
+------+-------------------------------------------------+-------------+
| Step | Action                                          | Time (in s) |
+------+-------------------------------------------------+-------------+
| 1    | default_platform                                | 0           |
| 6    | Switch to ios generate_accessibility_tests lane | 0           |
| 7    | Switch to ios generate_designsystem_tests lane  | 0           |
| 8    | Switch to ios generate_snapshot_tests lane      | 0           |
| 9    | Switch to ios generate_styleguide_tests lane    | 0           |
+------+-------------------------------------------------+-------------+

[11:38:13]: fastlane.tools finished successfully 🎉
bundle exec fastlane generate_all_tests  32.57s user 5.10s system 132% cpu 28.337 total

With 2.0.2 it takes about 33 seconds.

Upgrading to 2.0.3:

$ sourcery --version
2.0.3

$ time bundle exec fastlane generate_all_tests
[✔] 🚀
+---------------------------+---------+-------------------------------------------------------------+
|                                           Used plugins                                            |
+---------------------------+---------+-------------------------------------------------------------+
| Plugin                    | Version | Action                                                      |
+---------------------------+---------+-------------------------------------------------------------+
| fastlane-plugin-appcenter | 2.1.0   | appcenter_codepush_release_react, appcenter_fetch_devices,  |
|                           |         | appcenter_fetch_version_number, appcenter_upload            |
+---------------------------+---------+-------------------------------------------------------------+

[11:41:33]: -------------------------------------------------------------
[11:41:33]: --- Step: Switch to ios generate_accessibility_tests lane ---
[11:41:33]: -------------------------------------------------------------
[11:41:33]: Cruising over to lane 'ios generate_accessibility_tests' 🚖
[11:47:00]: Cruising back to lane 'ios generate_all_tests' 🚘
[11:47:00]: ------------------------------------------------------------
[11:47:00]: --- Step: Switch to ios generate_designsystem_tests lane ---
[11:47:00]: ------------------------------------------------------------
[11:47:00]: Cruising over to lane 'ios generate_designsystem_tests' 🚖
[11:47:38]: Cruising back to lane 'ios generate_all_tests' 🚘
[11:47:38]: --------------------------------------------------------
[11:47:38]: --- Step: Switch to ios generate_snapshot_tests lane ---
[11:47:38]: --------------------------------------------------------
[11:47:38]: Cruising over to lane 'ios generate_snapshot_tests' 🚖
[11:53:57]: Cruising back to lane 'ios generate_all_tests' 🚘
[11:53:57]: ----------------------------------------------------------
[11:53:57]: --- Step: Switch to ios generate_styleguide_tests lane ---
[11:53:57]: ----------------------------------------------------------
[11:53:57]: Cruising over to lane 'ios generate_styleguide_tests' 🚖
[11:54:06]: Cruising back to lane 'ios generate_all_tests' 🚘

+------+-------------------------------------------------+-------------+
|                           fastlane summary                           |
+------+-------------------------------------------------+-------------+
| Step | Action                                          | Time (in s) |
+------+-------------------------------------------------+-------------+
| 1    | default_platform                                | 0           |
| 5    | Switch to ios generate_accessibility_tests lane | 0           |
| 6    | Switch to ios generate_designsystem_tests lane  | 0           |
| 7    | Switch to ios generate_snapshot_tests lane      | 0           |
| 8    | Switch to ios generate_styleguide_tests lane    | 0           |
+------+-------------------------------------------------+-------------+

[11:54:06]: fastlane.tools just saved you 13 minutes! 🎉
bundle exec fastlane generate_all_tests  654.49s user 54.57s system 93% cpu 12:34.93 total

With 2.0.3 it takes about 13mins.

I'm attaching the templates we are using: templates.zip

[art-divin]

Thank you for providing the info!

There were many bug fixes done and additional features implemented in 2.0.3, so it is quite hard to pin-point, ones that I can think about are #1172 #1179 #1169 #1186 but I can be mistaken here.

[art-divin]

@krzysztofzablocki excuse me for pinging, do you have any idea where to dig here?

I might suggest the following:

1. add a way to debug generated code compilation time
2. output that log in a readable format

But apart from that, any other options?

[krzysztofzablocki]

Can we get numbers with benchmark flag (--logBenchmarks)? That way we'll get info which phases/templates are costly

[krzysztofzablocki]

I run through some numbers in one of my larger projects and it seems to be swifttemplate related issue, for me 2.0.2 vs 2.0.3 looks like this:

Cached scan: 1.08s vs 1.07s Cached swiftemplate: 0.24s vs 18.7s

Basically looks like one of the changes to Swift templates broke caching so they rebuild each time, which is very expensive since it's actually compiling them

[art-divin]

Nice, thank you for checking, I might already have enough material to investigate 🕵🏻

Would be nice to have a unit test for this so I would be able to investigate and fix, otherwise it is a bit over my head, those templates at this point still 👀

[krzysztofzablocki]

@art-divin all of SwiftTemplate logic should be isolated to SwiftTemplate.swift file, in the render method there is some logic to resolve cache or build clean so I assume something changed related to that

[bsrz]

@art-divin any updates on this?

[art-divin]

Hey @bsrz ,

thank you for asking 👍🏻

I am quite busy at the moment, but I am processing this issue in the back of my head anyway.

I'll update you once I'll fix this (my favourite type of bug 🐞 ).

[art-divin]

Update

I have dug into SwiftTemplate.swift file, and indeed, the way cacheKey was calculated before #1163 was that includedFiles collection was empty, whereas after #1163, that collection always contains file paths.

 var cacheKey: String? {
        var contents = code

        // For every included file, make sure that the path and modification date are included in the key
-       let files = includedFiles.map({ $0.absolute() }).sorted(by: { $0.string < $1.string })
+       let files = (includedFiles + buildDir.allPaths).map({ $0.absolute() }).sorted(by: { $0.string < $1.string })
        for file in files {
            let modificationDate = file.modifiedDate?.timeIntervalSinceReferenceDate ?? 0
            contents += "\n// \(file.string)-\(modificationDate)"
        }

        return contents.sha256()
    }

@k-o-d-e-n do you have any insight on why did you need to change files collection in this method? What did you intend to accomplish and what was not working with the original version?

Thank you 🙏🏻

[art-divin]

Update

Because of the aforementioned change in the logic of calculating cacheKey hash, the following issue occurs:

1. buildDir path includes all files in .build folder, and thus, cacheKey depends on the build folder contents
2. buildDir contains files like master.swiftdeps, .swiftsourceinfo, main.swift.o, DWARF/SwiftTemplate, build.db, context.bin, which change every time a build is performed (I suppose timestamp is used in these files in one way or another).
3. Due to this change, hash of the key does not match and "previous" cache get deleted instead of being reused

Possible solutions

1. Revert the logic to the original, probably losing functionality @k-o-d-e-n relied upon for his SPM support integration
2. Ignore master.swiftdeps and other dynamic files from the contents of buildDir folder.
3. Ignore all files except under SwiftTemplate/2.0.3/Sources folder, i.e. ignore all files under .build folder

I lean towards the second option, because it should still support what was expected before, both providing good cache and SPM support, albeit I am unsure why exactly this change was required.

I have tried Solution # 2 and it works with caching.

@krzysztofzablocki do you have any idea which solution is the best option to move forward?

Thanks 🙏🏻

[k-o-d-e-n]

I use external dependencies to build a template. After changing the code in the project, the next time you run Sourcery, so it is necessary that the project is rebuilt. If it has such a serious impact on performance, then this change could be removed. But your code snippet already uses the modification date instead of the file content, this should probably solve the problem. Yes, and of course it was necessary to exclude .build folder.

Thank you and sorry for this trouble.

[art-divin]

Thank you for your response, @k-o-d-e-n !

Great that you have provided an insight.

If it has such a serious impact on performance, then this change could be removed. But your code snippet already uses the modification date instead of the file content, this should probably solve the problem.

In fact, it does not. I probably took a Sourcery 2.0.2 version of that logic, and I tried both approaches - only solution was to exactly exclude the dynamic pieces from .build folder.

I suspect that due to dynamism it is indeed better to ignore .build folder contents for cacheKey calculation.

Thank you and sorry for this trouble.

Not an issue at all, thank you for your contribution! 🤝

[art-divin]

I use external dependencies to build a template. After changing the code in the project, the next time you run Sourcery, so it is necessary that the project is rebuilt.

As far as I can see, you can leverage from using --cacheDisabled flag. Including folders according to new logic is unfortunately unstable, i.e. brings inconsistent results between runs, sometimes hash is the same, sometimes it is not the same.

So I would need to revert this change and advise to use --cacheDisabled flag because it would provide exactly the same behaviour as it is now in version 2.0.3.

[bsrz]

@art-divin appreciate all the help and work on this! 🙌