SymfonyCasts stands united with the people of Ukraine
gstreamer0.10-ffmpeg
gstreamer0.10-plugins-good packages.
At this point, I'm pretty happy with the show page that we've been profiling. So let's look at something different: let's profile the homepage at https://localhost:8000/.
Ok, this page has a list of all of the sightings... and on the right, that shows some SymfonyCasts repository info from GitHub. Let's refresh... though... that's not really needed - and profile! I'll call this one: [Recording] Original homepage - https://bit.ly/sf-bf-homepage-original.
Ok! 165 milliseconds! Let's view the call graph. Well... this looks familiar! We have the same number 1 exclusive-time function as before: UnitOfWork::createEntity(). In that situation, it meant that we were querying for too many items and so Doctrine was hydrating too many objects. Is it the same problem now? And if so, why? Can we optimize it?
Time to put on our profiling detective hats. Let's follow the hot path! We enter MainController::homepage() and render a template... so the problem is coming from our template. Interesting. Next _sightings.html.twig is rendered... and then something called twig_length_filter executes loadOneToManyCollection(), which is from Doctrine. Let's do some digging in that template: templates/main/_sightings.html.twig.
We saw that it was referencing something called twig_length_filter. Search the template for length. Ah: sighting.comments|length:
| {% for sighting in sightings %} | |
| <tr> | |
| ... lines 3 - 10 | |
| <td> | |
| <a class="text-white table-content text-center" href="{{ path('app_sighting_show', {id: sighting.id}) }}">{{ sighting.comments|length }}</a> | |
| </td> | |
| </tr> | |
| {% endfor %} |
Look back on the site: one of the things it does is prints the number of comments for each article. The length filter counts how many items are in sighting.comments, which is a database relationship from the big_foot_sighting table to the comment table.
If you're not familiar with Doctrine, when you call sighting.comments, at that moment, Doctrine queries for all of the comments for that specific BigFootSighting record. I'll open up src/Entity/BigFootSighting.php. Yep, we're accessing the comments property, which is a OneToMany relationship to Comment:
| ... lines 1 - 11 | |
| class BigFootSighting | |
| { | |
| ... lines 14 - 56 | |
| /** | |
| * @ORM\OneToMany(targetEntity="App\Entity\Comment", mappedBy="bigFootSighting") | |
| * @ORM\OrderBy({"createdAt"="DESC"}) | |
| */ | |
| private $comments; | |
| ... lines 62 - 205 | |
| } |
The point is: for each BigFootSighting that we are rendering, Doctrine is making an extra query to fetch all the comments for that sighting. This is basically the classic N+1 problem. If we want to print 25 BigFootSighting rows, in addition to the 1 query to fetch the 25 rows, the system will also make 25 additional queries to fetch the comments for each sighting. That's 25 + 1 queries.
You can see this in the SQL queries in Blackfire: we have one query from big_foot_sighting - the query above is related to the pagination logic - then 25 queries from the comment table.
fetch="EXTRA_LAZY"Okay, we have identified the problem: we are not only making a lot of queries... but those queries are also fetching all the comment data... just to count them. Silliness!
One simple solution might be... just to tell Doctrine to make a COUNT query instead of fetching all the data. We would still have 25 extra queries... but they would be much faster.
In Doctrine, we can do this really easily. If you access a relationship - like the comments property - and only count it, we can ask Doctrine to do a COUNT query instead of loading all the comment data. How? Above the comments property, add fetch="EXTRA_LAZY":
| ... lines 1 - 11 | |
| class BigFootSighting | |
| { | |
| ... lines 14 - 56 | |
| /** | |
| * @ORM\OneToMany(targetEntity="App\Entity\Comment", mappedBy="bigFootSighting", fetch="EXTRA_LAZY") | |
| ... line 59 | |
| */ | |
| private $comments; | |
| ... lines 62 - 205 | |
| } |
Before we try this, don't forget that we're in the prod environment: run cache:clear:
php bin/console cache:clear
And cache:warmup:
php bin/console cache:warmup
Ok, let's see if this helps! Spin over, refresh the page and... profile! I'll call this one: [Recording] homepage EXTRA_LAZY - https://bit.ly/sf-bf-extra-lazy. I'll close the other tab and view the call graph.
Was this better? Well, createEntity() isn't the biggest problem anymore... so that's a good sign! Let's compare to be sure: go from the original homepage... to the most recent profile: https://bit.ly/sf-bf-extra-lazy-compare.
And... wow! Yea, this is a huge win in every category! So, was this a good change? Absolutely: this was an awesome change.
But, even though the queries are much faster... we're still making the same number of queries. Is that something we care about? I don't know? But that's the great thing about profiling with Blackfire: you don't need to absolutely optimize everything. If you're not sure if something is a problem, you can deploy and check it on production to see if it's really slowing things down under realistic conditions. Especially because sometimes improving performance comes at a cost of extra complexity.
Next, let's see if we can reduce the number of queries. Will it help performance? If so, is it enough for the added complexity?
"Houston: no signs of life"
Start the conversation!
// composer.json
{
"require": {
"php": "^7.1.3",
"ext-ctype": "*",
"ext-iconv": "*",
"blackfire/php-sdk": "^1.20", // v1.20.0
"composer/package-versions-deprecated": "^1.11", // 1.11.99
"doctrine/annotations": "^1.0", // v1.8.0
"doctrine/doctrine-bundle": "^1.6.10|^2.0", // 1.11.2
"doctrine/doctrine-migrations-bundle": "^1.3|^2.0", // v2.0.0
"doctrine/orm": "^2.5.11", // v2.6.4
"phpdocumentor/reflection-docblock": "^3.0|^4.0", // 4.3.2
"sensio/framework-extra-bundle": "^5.4", // v5.5.1
"symfony/console": "4.3.*", // v4.3.10
"symfony/dotenv": "4.3.*", // v4.3.10
"symfony/flex": "^1.9", // v1.18.7
"symfony/form": "4.3.*", // v4.3.10
"symfony/framework-bundle": "4.3.*", // v4.3.9
"symfony/http-client": "4.3.*", // v4.3.10
"symfony/property-access": "4.3.*", // v4.3.10
"symfony/property-info": "4.3.*", // v4.3.10
"symfony/security-bundle": "4.3.*", // v4.3.10
"symfony/serializer": "4.3.*", // v4.3.10
"symfony/twig-bundle": "4.3.*", // v4.3.10
"symfony/validator": "4.3.*", // v4.3.10
"symfony/webpack-encore-bundle": "^1.6", // v1.7.2
"symfony/yaml": "4.3.*", // v4.3.10
"twig/extensions": "^1.5" // v1.5.4
},
"require-dev": {
"doctrine/doctrine-fixtures-bundle": "^3.2", // 3.2.2
"easycorp/easy-log-handler": "^1.0.7", // v1.0.9
"fzaninotto/faker": "^1.8", // v1.8.0
"symfony/browser-kit": "4.3.*", // v4.3.10
"symfony/css-selector": "4.3.*", // v4.3.10
"symfony/debug-bundle": "4.3.*", // v4.3.10
"symfony/maker-bundle": "^1.13", // v1.14.3
"symfony/monolog-bundle": "^3.0", // v3.5.0
"symfony/phpunit-bridge": "^5.0", // v5.0.3
"symfony/stopwatch": "4.3.*", // v4.3.10
"symfony/var-dumper": "4.3.*", // v4.3.10
"symfony/web-profiler-bundle": "4.3.*" // v4.3.10
}
}