WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.066 --> 00:00:05.386 align:middle As handy as the CLI tool is for profiling AJAX requests, 00:00:05.656 --> 00:00:08.166 align:middle its true purpose is something different: 00:00:08.836 --> 00:00:12.276 align:middle it's to allow us to profile our custom command-line scripts. 00:00:13.036 --> 00:00:14.096 align:middle Let's check out an example. 00:00:14.816 --> 00:00:18.666 align:middle I've already created a command line script that you can execute by calling: 00:00:18.836 --> 00:00:24.386 align:middle php bin/console app:update-sighting-scores What does it do? 00:00:24.976 --> 00:00:26.276 align:middle Let me show you! 00:00:26.276 --> 00:00:32.406 align:middle Each Bigfoot sighting on the site has, what we call, a "Bigfoot believability score". 00:00:33.436 --> 00:00:37.626 align:middle Right now, this shows zero for every sighting. 00:00:38.486 --> 00:00:44.406 align:middle That's because we use a highly-complex and proprietary algorithm to calculate this. 00:00:44.976 --> 00:00:49.776 align:middle It's such a heavy process that, instead of figuring it out on page-load, 00:00:50.316 --> 00:00:54.186 align:middle we store the current value in a column on each row of the table. 00:00:55.076 --> 00:01:01.776 align:middle To populate that column, we run this command once a day: it loops over all the sightings, 00:01:02.116 --> 00:01:06.736 align:middle calculates the newest "believability score" and saves it back to the database. 00:01:07.496 --> 00:01:10.406 align:middle Try it: It takes a few seconds... 00:01:11.966 --> 00:01:14.066 align:middle and when we go back to the site and refresh... 00:01:14.596 --> 00:01:20.946 align:middle we find out that this Bigfoot sighting in kind of believable - a score of 5 out of 10. 00:01:22.636 --> 00:01:23.546 align:middle The code for this lives 00:01:23.546 --> 00:01:30.606 align:middle at src/Command/UpdateSightingScoresCommand.php: You might already see a problem. 00:01:30.866 --> 00:01:31.856 align:middle But if you don't... 00:01:32.056 --> 00:01:32.776 align:middle that's ok! 00:01:33.516 --> 00:01:34.896 align:middle Let's see what Blackfire thinks. 00:01:35.566 --> 00:01:42.856 align:middle This time, run that same command, but put blackfire run at the beginning: Woh. 00:01:43.126 --> 00:01:50.926 align:middle It's a lot slower now: we're seeing evidence of how the PHP extension slows down the process... 00:01:51.136 --> 00:01:52.616 align:middle and wow... 00:01:52.616 --> 00:01:54.956 align:middle it's just getting slower, and slower. 00:01:55.516 --> 00:01:58.476 align:middle I'm going to use the magic of TV to speed things up. 00:02:00.576 --> 00:02:02.646 align:middle Ok, let's look at that profile! 00:02:06.656 --> 00:02:11.556 align:middle http://bit.ly/sf-bf-console-original Woh! 00:02:11.556 --> 00:02:14.956 align:middle Some computeChangeSet() function was called almost 500,000 times! 00:02:14.956 --> 00:02:17.476 align:middle Ah! That's taking up half of the exclusive time! 00:02:18.836 --> 00:02:23.896 align:middle Because this call is such a problem, Blackfire is hiding a lot of data, 00:02:24.656 --> 00:02:28.646 align:middle all of which is unimportant relative to what we are seeing. 00:02:29.416 --> 00:02:34.756 align:middle That's cool because the result is a super simple call graph: here's our command... 00:02:35.486 --> 00:02:37.166 align:middle here's EntityManager::flush()... 00:02:37.566 --> 00:02:40.106 align:middle and then it goes into deep Doctrine stuff. 00:02:41.576 --> 00:02:46.076 align:middle Let's check out the command and look for the EntityManager::flush() call: Yep! 00:02:46.076 --> 00:02:52.176 align:middle I flush once each time at the end of the loop, which updates that database row. 00:02:52.176 --> 00:02:56.916 align:middle If you're familiar with Doctrine, you might know the problem: 00:02:57.436 --> 00:03:00.276 align:middle you don't need to call flush() inside the loop. 00:03:00.276 --> 00:03:05.766 align:middle Instead, move this after the loop: With this change, 00:03:06.126 --> 00:03:10.626 align:middle Doctrine will try to perform all update queries at the same time... 00:03:11.376 --> 00:03:15.086 align:middle which even lets it try to optimize those queries if it can. 00:03:15.706 --> 00:03:19.016 align:middle But the big problem with our old code was something related 00:03:19.016 --> 00:03:22.556 align:middle to Doctrine's UnitOfWork::computeChangeSet(). 00:03:23.416 --> 00:03:29.856 align:middle Each time you call flush() in Doctrine, it looks at all the objects it has queried for - 00:03:30.316 --> 00:03:36.616 align:middle so all of the BigFootSighting objects - and checks every single one to see 00:03:36.616 --> 00:03:42.566 align:middle if any data has changed that needs to be sync'ed back to the database with an UPDATE query. 00:03:43.286 --> 00:03:47.626 align:middle Yep, with the old code, it was checking every property 00:03:47.626 --> 00:03:52.266 align:middle of every record for updated data on every loop. 00:03:52.976 --> 00:03:56.636 align:middle Hence...the 450,000 calls! 00:03:57.676 --> 00:04:00.056 align:middle Let's profile again with the updated code. 00:04:00.546 --> 00:04:04.196 align:middle This time it's much faster - I don't even think we need 00:04:04.196 --> 00:04:11.006 align:middle to compare the profiles: 56 seconds down to 1. 00:04:12.406 --> 00:04:15.356 align:middle Open it up: http://bit.ly/sf-bf-console2. 00:04:15.356 --> 00:04:16.406 align:middle Could we optimize this further? 00:04:16.406 --> 00:04:21.796 align:middle Maybe! But this performance enhancement already came at a cost: reduced reliability. 00:04:22.856 --> 00:04:27.616 align:middle I originally put the call to flush() inside the loop not because I didn't know better... 00:04:28.196 --> 00:04:31.456 align:middle but to make the command a little more resilient. 00:04:32.426 --> 00:04:37.856 align:middle If, for example, the command gets through half of the records and then has an error, 00:04:38.206 --> 00:04:41.866 align:middle with the new code, none of the scores will be saved. 00:04:42.996 --> 00:04:44.846 align:middle It's beyond the scope of this tutorial, 00:04:45.276 --> 00:04:49.506 align:middle but I love to make my command-line scripts super forgiving. 00:04:49.606 --> 00:04:56.256 align:middle If this were a real app, I would probably save the datetime that I last calculated the score 00:04:56.256 --> 00:05:00.796 align:middle for each record and use that to query for only the rows 00:05:00.856 --> 00:05:04.256 align:middle that have not been updated in the last 24 hours. 00:05:05.166 --> 00:05:10.616 align:middle I would also move the flush() back into the loop: Thanks to those changes, 00:05:10.976 --> 00:05:13.126 align:middle if this command failed half-way through, 00:05:13.376 --> 00:05:18.426 align:middle the first half of the records would already be updated and we could run the command again 00:05:18.426 --> 00:05:22.096 align:middle to resume with the ones that are still not updated. 00:05:22.726 --> 00:05:25.896 align:middle But wouldn't that make the command super-slow again? 00:05:25.896 --> 00:05:31.386 align:middle Yep! And with the help of Blackfire, you can test solutions that improve performance 00:05:31.546 --> 00:05:34.096 align:middle without making the command less reliable. 00:05:34.496 --> 00:05:40.236 align:middle For example, we could make the first query only return an array of integer ids. 00:05:40.756 --> 00:05:46.416 align:middle Then, inside the loop, use that id to query for the one object you need. 00:05:47.146 --> 00:05:53.726 align:middle That would mean we only have one BigFootSighting object in memory at a time instead of all 00:05:53.726 --> 00:05:59.516 align:middle of them: You can go further by calling EntityManager::clear() after flush() to, 00:05:59.516 --> 00:06:05.166 align:middle sort of, "clear" Doctrine's memory of the BigFootSighting object you just finished... 00:06:05.536 --> 00:06:11.276 align:middle so that it doesn't check it for changes when we call flush() during the next time 00:06:11.276 --> 00:06:14.966 align:middle through the loop: The point is: like with everything, 00:06:15.206 --> 00:06:17.416 align:middle make your code do what it needs to... 00:06:17.606 --> 00:06:21.446 align:middle then use Blackfire to solve the real performance issues... 00:06:21.636 --> 00:06:22.546 align:middle if you have any. 00:06:23.796 --> 00:06:28.306 align:middle Next, there's a giant screen in Blackfire that we haven't even looked at yet. 00:06:28.906 --> 00:06:30.266 align:middle What!? It's... 00:06:30.566 --> 00:06:31.366 align:middle the Timeline!