How we sped up Sylius' Behat suite with Blackfire
Feedback time is one of the most crucial factors during development and the red - green - refactor cycle. In case of Sylius, the full build used to take two and a half hour, including 55 minutes for only PHP 5.6 jobs. Waiting so long for feedback is not an option for a project of this size and with so many active contributors. As much as I am Xdebug fan, I have never really used it for profiling - the snapshots generation was slowing down the profiled script significantly and resulted in monstrous files, which weren't easy to read.
Half a year after I have first heard of blackfire.io I decided to give it a try. It resulted in a series of pull requests that speeds up Sylius test suites 6 times and reduces memory usage to one tenth. As a side-effect, we have revealed bugs that can be found only in production-like environment (e.g. displaying 404 page or Doctrine metadata inheritance and slug generation).
The previous tests execution time was unacceptable and impeded the development. The community was struggling with this issue for some time, but it was hard to find an inspiration in speeding up tests execution, because there is no other open source project that have such a big number of Behat scenarios. After optimizations, we have full build finished just 10 minutes after PR is sent (taking into account that jobs run in parallel on Travis). It will have a huge impact on development tempo and will strongly push the project forward. You can check how the previous builds look in comparison to the new ones.
Preventing bottlenecks
Running profiler for the first time
When I ran the Blackfire profiler for the first time, it took a little less than 7 minutes to test
Behat products suite. While I was looking at the profiling results,
I noticed that some parts of the application were much more time consuming than I would have expected.
First bottleneck: Logging in using web interface
The most interesting was that iAmLoggedInAsRole method, used once in literally every scenario, took a little over 30% of the execution time.
That code used to make 4 requests: getting the login form, checking credentials (done by firewall), redirecting to dashboard
and finally getting the dashboard. While using Behat/Symfony2Extension, the HttpKernel is rebooted after every request and scenario.
To solve this issue, I rewrote the method not to make any HTTP requests. With the awareness of Symfony2 ContextListener setting present token based on the one in session, it wasn't that hard as I would expect.
That change sped up our products suite by over 2 minutes and lowered memory usage by 40%.
Have a look at Blackfire profiles before and after this change and their comparison.
Second bottleneck: Reinitializng router after every request and scenario
We use router service in our Behat suite widely. As I mentioned above, the cotainer and its services are rebooted after every
request and scenario. Since router has no cache that can be persisted between different instances, the routes were loaded
from YAML files many more times than needed. The fix was quite simple - get the first instance of router and use it all the time.
Assuming that the routes aren't changed during the runtime, this update was 100% safe. Another amount of time was saved, setting our current checkpoint at about 3 minutes 30 seconds, which is half of the inital time.
Have a look at Blackfire profiles before and after this change and their comparison.
Third bottleneck: Running Doctrine without class metadata cache
At that moment, getting class metadata was taking almost half of the execution time. Metadata was loaded for over eight thousand times!
We are purging the database before every scenario to be sure that tests are executed as independent as they can be, that was responisble for
one fifth of the class metadata-related resources usage too. After setting up Doctrine metadata cache and decorating ORMPurger
with caching layer, our products suite was finishing in 1 minute 30 seconds, compared to 7 minutes at the beginning.
Have a look at Blackfire profiles before and after this change and their comparison.
Profiling results
Removing these three main bottlenecks caused insane improvement in resources usage. Take a look at the comparison profile before all the changes and after them:
Few more changes that will make your tests faster
After these tiny in code, but giant in effects changes, the other ones weren't so spectacular. I ended up with products
suite executing in 30 seconds on Travis CI, which I am really proud of. The other changes included:
- Turning off
kernel.debugsetting in test environment - Enabling OPCache
- Not executing scripts while using Composer
- Tweaking Travis cache not to upload every time
- Applying previous changes to PHP7 builds (full build under 5 minutes)
Summary
Since Sylius got these performance optimizations merged, it is unlikely to wait more than a few minutes to see feedback, like it was before. Running our full Behat suite on PHP 7 takes 2:30min for almost 500 scenarios and 5600 steps (37 steps per second!), executes 110 thousands queries, creates 30 thousands entities, boots Symfony2 Kernel over 2 thousand times and uses only 115MB memory!
Previous build (2h 33m):
Current builds (26m):
If you want to see how it was implemented, take a look at the related PRs involving #3576 (focused on Behat execution time), #3596 (improved caching logic on Travis) and #3625 (reduced memory usage a lot).