WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.036 --> 00:00:03.166 align:middle Head back to the Blackfire dashboard... 00:00:03.326 --> 00:00:07.876 align:middle and click into the latest profile - the one with our COUNT query improvement - 00:00:11.176 --> 00:00:14.166 align:middle https://bit.ly/sfcast-bf-profile2. 00:00:14.166 --> 00:00:15.986 align:middle The critical path is now much less clear... 00:00:15.986 --> 00:00:17.556 align:middle there are kind of two critical paths... 00:00:17.556 --> 00:00:19.996 align:middle but neither end in a node with a red background... 00:00:20.246 --> 00:00:22.086 align:middle which would indicate an obvious issue. 00:00:22.636 --> 00:00:27.606 align:middle This might mean that there aren't any more easy performance "wins" on this page... 00:00:27.926 --> 00:00:30.206 align:middle it might be fast enough! 00:00:30.206 --> 00:00:34.096 align:middle The response time from the profile was 270 milliseconds. 00:00:34.636 --> 00:00:37.706 align:middle If you're not satisfied with that, remember two things. 00:00:37.706 --> 00:00:41.866 align:middle First, we're profiling Symfony in its dev environment. 00:00:42.316 --> 00:00:44.516 align:middle Switching to prod would be faster... 00:00:44.796 --> 00:00:45.936 align:middle we'll do that soon. 00:00:46.396 --> 00:00:51.856 align:middle And second, the time you see in a profile will never be quite as fast as the real thing, 00:00:52.226 --> 00:00:54.356 align:middle because when the probe is activated - 00:00:54.476 --> 00:00:59.186 align:middle the PHP extension that does all the profiling - it slows things down. 00:00:59.266 --> 00:01:02.616 align:middle So don't obsess over any absolute numbers. 00:01:02.956 --> 00:01:06.576 align:middle Instead, focus on finding ways to improve each number. 00:01:07.216 --> 00:01:12.386 align:middle The function that takes up the most exclusive time is from something called DebugClassLoader. 00:01:13.346 --> 00:01:18.006 align:middle Ah. Our local Symfony app is currently running in its dev environment, 00:01:18.416 --> 00:01:22.716 align:middle which adds a lot of debugging tools, like the web debug toolbar. 00:01:23.516 --> 00:01:25.556 align:middle That stuff also slows things down... 00:01:25.906 --> 00:01:31.216 align:middle which makes profiling less useful: the profiler is cluttered up with function calls 00:01:31.396 --> 00:01:33.826 align:middle that won't really be there in production. 00:01:34.656 --> 00:01:38.756 align:middle That extra noise makes finding the true performance issues harder. 00:01:38.886 --> 00:01:42.516 align:middle So, let's switch our app to the prod environment while profiling. 00:01:43.396 --> 00:01:50.406 align:middle Open up .env, find the APP_ENV variable, and change it to prod. 00:01:50.406 --> 00:01:53.356 align:middle That will make things more realistic... 00:01:53.616 --> 00:01:55.816 align:middle but it also means that after... 00:01:55.816 --> 00:02:00.316 align:middle pretty much any change to our code, we will need to clear & warm the cache. 00:02:00.886 --> 00:02:09.226 align:middle No big deal: at your terminal, run: php bin/console cache:clear and then: 00:02:09.226 --> 00:02:15.326 align:middle php bin/console cache:warmup Ok, let's profile again! 00:02:16.326 --> 00:02:17.296 align:middle I'll refresh... 00:02:17.476 --> 00:02:19.956 align:middle just to make sure the page is working and... 00:02:20.136 --> 00:02:27.436 align:middle profile! I'll call this one [Recording] Show page in prod mode. 00:02:28.226 --> 00:02:32.836 align:middle Cool! 106 milliseconds is a huge improvement! 00:02:33.796 --> 00:02:36.186 align:middle Click to open the call graph: 00:02:36.186 --> 00:02:42.966 align:middle https://bit.ly/sf-bf-profile3 Now the function list and the call graph look a bit more useful. 00:02:42.966 --> 00:02:44.916 align:middle There's no super problematic, red-background node on the graph... 00:02:44.916 --> 00:02:50.066 align:middle but the function that takes up the most exclusive time - PDOStatement::execute() - 00:02:50.326 --> 00:02:54.106 align:middle at least makes sense: that's executing database queries. 00:02:55.086 --> 00:02:58.966 align:middle Back on our site, you may have noticed that each time we've profiled, 00:02:59.216 --> 00:03:01.546 align:middle a little exclamation icon showed up. 00:03:01.546 --> 00:03:06.776 align:middle If you clicked that, it would take you to a "Recommendations" section of the profile. 00:03:07.546 --> 00:03:13.456 align:middle The exclamation point was telling us that we're failing one or more Blackfire recommendations. 00:03:13.906 --> 00:03:15.526 align:middle I dig this feature. 00:03:16.606 --> 00:03:21.786 align:middle Because Blackfire is written for PHP, it has special knowledge of how queries are made, 00:03:22.026 --> 00:03:26.596 align:middle how Composer works, Symfony, Magento and so many other things. 00:03:27.486 --> 00:03:31.586 align:middle The Blackfire team has used that knowledge to add a bunch of things 00:03:31.586 --> 00:03:33.696 align:middle that they call "recommendations". 00:03:34.046 --> 00:03:35.776 align:middle I call them "sanity checks". 00:03:35.776 --> 00:03:40.636 align:middle For example, Blackfire counted our queries and said: Hey! 00:03:40.636 --> 00:03:44.986 align:middle FYI - you've got a bunch of queries on this page... 00:03:45.206 --> 00:03:47.596 align:middle maybe you should try to have less than 10. 00:03:48.476 --> 00:03:51.266 align:middle Yea, our 43 queries is pretty high. 00:03:52.056 --> 00:03:56.806 align:middle Does that mean we should immediately run into our code and fix it? 00:03:56.806 --> 00:04:00.006 align:middle Nah. It's just a good thing to keep on your radar. 00:04:00.946 --> 00:04:05.516 align:middle There's also a recommendation that Doctrine annotation metadata should be cached 00:04:05.516 --> 00:04:06.166 align:middle in production. 00:04:06.166 --> 00:04:07.516 align:middle Honestly... 00:04:07.666 --> 00:04:11.466 align:middle I'm not sure why that's there - Symfony apps come 00:04:11.466 --> 00:04:17.326 align:middle with a config/packages/prod/doctrine.yaml file that takes care of caching these 00:04:17.326 --> 00:04:19.036 align:middle when you're in the prod environment. 00:04:19.716 --> 00:04:21.736 align:middle When I tried to reproduce this later... 00:04:21.856 --> 00:04:22.606 align:middle it went away. 00:04:22.606 --> 00:04:24.296 align:middle So let's ignore it for now. 00:04:24.296 --> 00:04:27.796 align:middle If it comes back later when we deploy to production, 00:04:27.986 --> 00:04:30.556 align:middle then I will want to look into it further. 00:04:31.556 --> 00:04:37.186 align:middle The last recommendation is awesome: The Composer autoloader class map should be dumped 00:04:37.186 --> 00:04:38.966 align:middle in production By the way. 00:04:39.116 --> 00:04:42.636 align:middle if you don't know what something means, the cute question mark can help. 00:04:43.776 --> 00:04:45.106 align:middle Look back at the function list: 00:04:47.536 --> 00:04:52.456 align:middle the second highest function was something related to Composer's autoload system. 00:04:52.906 --> 00:04:55.576 align:middle Blackfire nailed that this is an issue. 00:04:56.566 --> 00:05:01.636 align:middle You may already know this, but when you deploy, you're supposed to run a special command - 00:05:01.836 --> 00:05:07.306 align:middle or add a special option - that tells Composer to dump an optimized autoload file. 00:05:08.006 --> 00:05:11.046 align:middle Blackfire is telling us that we forgot to do this locally. 00:05:11.806 --> 00:05:16.096 align:middle Let's fix this: it will help clean up even more stuff on the profile. 00:05:17.616 --> 00:05:25.876 align:middle At your terminal, run: composer dump-autoload -- optimize Perfect! 00:05:27.936 --> 00:05:29.056 align:middle Refresh the page... 00:05:30.166 --> 00:05:30.936 align:middle it works... 00:05:31.096 --> 00:05:34.506 align:middle and create another profile - I'll call this: 00:05:34.696 --> 00:05:38.136 align:middle [Recording] Show page after optimized autoloader. 00:05:41.006 --> 00:05:42.466 align:middle Click to view the call graph: 00:05:42.466 --> 00:05:46.876 align:middle https://bit.ly/sf-bf-profile4 and close the old one. 00:05:46.876 --> 00:05:49.796 align:middle It's not significantly faster, but we've removed 00:05:49.796 --> 00:05:53.066 align:middle at least one heavy-looking function call from our list. 00:05:53.546 --> 00:05:56.446 align:middle That will help us focus on any real problems. 00:05:57.176 --> 00:05:58.656 align:middle Check out the recommendations now. 00:05:59.776 --> 00:06:02.956 align:middle Yea! The Composer one is gone. 00:06:04.026 --> 00:06:08.646 align:middle Later, we'll learn how to add custom assertions - which are basically a way 00:06:08.646 --> 00:06:11.446 align:middle to write your own custom recommendations. 00:06:12.346 --> 00:06:17.946 align:middle Next, let's look deeper at what's going on with this PDOStatement::execute stuff. 00:06:17.946 --> 00:06:19.666 align:middle Is our page fast enough? 00:06:19.666 --> 00:06:23.336 align:middle Or can we discover some further, hidden optimizations?