WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.066 --> 00:00:04.806 align:middle At this point, I'm pretty happy with the show page that we've been profiling. 00:00:05.546 --> 00:00:11.646 align:middle So let's look at something different: let's profile the homepage at https://localhost:8000/. 00:00:12.946 --> 00:00:16.466 align:middle Ok, this page has a list of all of the sightings... 00:00:16.526 --> 00:00:22.036 align:middle and on the right, that shows some SymfonyCasts repository info from GitHub. 00:00:22.716 --> 00:00:23.616 align:middle Let's refresh... 00:00:23.806 --> 00:00:26.846 align:middle though... that's not really needed - and profile! 00:00:26.846 --> 00:00:31.446 align:middle I'll call this one: [Recording] Original homepage - 00:00:31.446 --> 00:00:36.076 align:middle https://bit.ly/sf-bf-homepage-original. 00:00:36.076 --> 00:00:38.356 align:middle Ok! 165 milliseconds! 00:00:38.356 --> 00:00:41.666 align:middle Let's view the call graph. 00:00:41.666 --> 00:00:42.676 align:middle Well... this looks familiar! 00:00:43.266 --> 00:00:51.446 align:middle We have the same number 1 exclusive-time function as before: UnitOfWork::createEntity(). 00:00:52.326 --> 00:00:56.966 align:middle In that situation, it meant that we were querying for too many items 00:00:57.116 --> 00:01:00.346 align:middle and so Doctrine was hydrating too many objects. 00:01:01.156 --> 00:01:02.386 align:middle Is it the same problem now? 00:01:02.386 --> 00:01:04.106 align:middle And if so, why? 00:01:04.716 --> 00:01:05.836 align:middle Can we optimize it? 00:01:06.776 --> 00:01:09.996 align:middle Time to put on our profiling detective hats. 00:01:10.376 --> 00:01:13.216 align:middle Let's follow the hot path! 00:01:13.216 --> 00:01:17.396 align:middle We enter MainController::homepage() and render a template... 00:01:17.816 --> 00:01:20.466 align:middle so the problem is coming from our template. 00:01:20.966 --> 00:01:21.716 align:middle Interesting. 00:01:22.526 --> 00:01:26.196 align:middle Next _sightings.html.twig is rendered... 00:01:26.576 --> 00:01:32.536 align:middle and then something called twig_length_filter executes loadOneToManyCollection, 00:01:32.816 --> 00:01:33.756 align:middle which is from Doctrine. 00:01:34.756 --> 00:01:42.206 align:middle Let's do some digging in that template: templates/main/_sightings.html.twig. 00:01:43.176 --> 00:01:46.706 align:middle We saw that it was referencing something called twig_length_filter. 00:01:47.216 --> 00:01:48.866 align:middle Search the template for length. 00:01:50.066 --> 00:01:54.516 align:middle Ah: sighting.comments|length. 00:01:54.516 --> 00:01:59.086 align:middle Look back on the site: one of the things it does is prints the number 00:01:59.086 --> 00:02:00.966 align:middle of comments for each article. 00:02:01.746 --> 00:02:06.106 align:middle The length filter counts how many items are in sighting.comments, 00:02:06.376 --> 00:02:11.916 align:middle which is a database relationship from the big_foot_sighting table to the comment table. 00:02:11.916 --> 00:02:18.466 align:middle If you're not familiar with Doctrine, when you call sighting.comments, at that moment, 00:02:18.666 --> 00:02:24.106 align:middle Doctrine queries for all of the comments for that specific BigFootSighting record. 00:02:25.306 --> 00:02:29.786 align:middle I'll open up src/Entity/BigFootSighting.php. 00:02:29.936 --> 00:02:35.706 align:middle Yep, we're accessing the comments property, which is a OneToMany relationship to Comment. 00:02:36.886 --> 00:02:43.386 align:middle The point is: for each BigFootSighting that we are rendering, Doctrine is making an extra query 00:02:43.386 --> 00:02:46.206 align:middle to fetch all the comments for that sighting. 00:02:47.106 --> 00:02:50.986 align:middle This is basically the classic N+1 problem. 00:02:51.846 --> 00:02:59.296 align:middle If we want to print 25 BigFootSighting rows, in addition to the 1 query to fetch the 25 rows, 00:02:59.546 --> 00:03:06.096 align:middle the system will also make 25 additional queries to fetch the comments for each sighting. 00:03:06.616 --> 00:03:09.246 align:middle That's 25 + 1 queries. 00:03:10.346 --> 00:03:13.066 align:middle You can see this in the SQL queries in Blackfire: 00:03:13.456 --> 00:03:19.576 align:middle we have one query from big_foot_sighting - the query above is related to the pagination logic - 00:03:20.016 --> 00:03:23.156 align:middle then 25 queries from the comment table. 00:03:24.506 --> 00:03:30.046 align:middle Okay, we have identified the problem: we are not only making a lot of queries... 00:03:30.186 --> 00:03:34.466 align:middle but those queries are also fetching all the comment data... 00:03:34.716 --> 00:03:35.706 align:middle just to count them. 00:03:36.396 --> 00:03:37.356 align:middle Silliness! 00:03:37.916 --> 00:03:40.246 align:middle One simple solution might be... 00:03:40.446 --> 00:03:45.476 align:middle just to tell Doctrine to make a COUNT query instead of fetching all the data. 00:03:46.646 --> 00:03:50.086 align:middle We would still have 25 extra queries... 00:03:50.186 --> 00:03:52.536 align:middle but they would be much faster. 00:03:53.496 --> 00:03:55.826 align:middle In Doctrine, we can do this really easily. 00:03:56.676 --> 00:04:02.786 align:middle If you access a relationship - like the comments property - and only count it, 00:04:03.036 --> 00:04:08.056 align:middle we can ask Doctrine to do a COUNT query instead of loading all the comment data. 00:04:09.226 --> 00:04:14.536 align:middle How? Above the comments property, add fetch="EXTRA_LAZY". 00:04:15.906 --> 00:04:22.146 align:middle Before we try this, don't forget that we're in the prod environment: run cache:clear: 00:04:24.176 --> 00:04:28.996 align:middle And cache:warmup: Ok, let's see if this helps! 00:04:29.826 --> 00:04:32.596 align:middle Spin over, refresh the page and... 00:04:32.906 --> 00:04:39.876 align:middle profile! I'll call this one: [Recording] homepage EXTRA_LAZY - 00:04:39.876 --> 00:04:44.856 align:middle https://bit.ly/sf-bf-extra-lazy. 00:04:44.856 --> 00:04:50.266 align:middle I'll close the other tab and view the call graph. 00:04:50.266 --> 00:04:50.916 align:middle Was this better? 00:04:50.916 --> 00:04:53.496 align:middle Well, createEntity isn't the biggest problem anymore... 00:04:53.496 --> 00:04:55.016 align:middle so that's a good sign! 00:04:56.166 --> 00:04:59.436 align:middle Let's compare to be sure: go from the original homepage... 00:04:59.436 --> 00:05:04.746 align:middle to the most recent profile: https://bit.ly/sf-bf-extra-lazy-compare. 00:05:04.746 --> 00:05:04.896 align:middle And... wow! 00:05:04.896 --> 00:05:08.046 align:middle Yea, this is a huge win in every category! 00:05:08.566 --> 00:05:10.186 align:middle So, was this a good change? 00:05:10.646 --> 00:05:14.156 align:middle Absolutely: this was an awesome change. 00:05:14.736 --> 00:05:17.466 align:middle But, even though the queries are much faster... 00:05:17.776 --> 00:05:20.746 align:middle we're still making the same number of queries. 00:05:21.296 --> 00:05:23.376 align:middle Is that something we care about? 00:05:23.586 --> 00:05:24.446 align:middle I don't know? 00:05:24.816 --> 00:05:27.566 align:middle But that's the great thing about profiling with Blackfire: 00:05:27.946 --> 00:05:30.956 align:middle you don't need to absolutely optimize everything. 00:05:31.636 --> 00:05:37.136 align:middle If you're not sure if something is a problem, you can deploy and check it on production to see 00:05:37.136 --> 00:05:41.316 align:middle if it's really slowing things down under realistic conditions. 00:05:41.746 --> 00:05:47.766 align:middle Especially because sometimes improving performance comes at a cost of extra complexity. 00:05:49.076 --> 00:05:52.166 align:middle Next, let's see if we can reduce the number of queries. 00:05:52.686 --> 00:05:53.846 align:middle Will it help performance? 00:05:54.236 --> 00:05:57.746 align:middle If so, is it enough for the added complexity?