WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.176 --> 00:00:04.716 align:middle Click log in to find our super-secure login system. 00:00:05.106 --> 00:00:09.186 align:middle We not only give you a valid email address, but even the password! 00:00:09.646 --> 00:00:11.726 align:middle We're very generous to our users. 00:00:11.816 --> 00:00:17.986 align:middle You can't tell, but now that we're logged in, a new piece of code is... 00:00:18.176 --> 00:00:21.436 align:middle silently running in the background on each request. 00:00:21.926 --> 00:00:24.406 align:middle Blackfire is going to help us notice this. 00:00:25.506 --> 00:00:31.566 align:middle Before we profile this page, open up the .env file and switch back to the dev environment. 00:00:32.216 --> 00:00:37.256 align:middle What I'm about to show you is more of a debugging tool than a profiling tool. 00:00:38.176 --> 00:00:42.696 align:middle We're switching back to the dev environment both to make our life a little bit easier - 00:00:43.086 --> 00:00:48.866 align:middle no need to clear the cache after changes - and because when your code executes more slowly, 00:00:49.126 --> 00:00:53.996 align:middle Blackfire tends to prune, or remove, less stuff. 00:00:53.996 --> 00:00:56.606 align:middle That's bad for trying to find performance issues, 00:00:56.906 --> 00:00:59.786 align:middle but good if your goal is to debug something... 00:01:00.056 --> 00:01:02.106 align:middle or understand how your app is working. 00:01:02.706 --> 00:01:04.806 align:middle I'll refresh the page to make sure that it works. 00:01:06.576 --> 00:01:10.876 align:middle Yep! Our handy web debug toolbar on the bottom is back! 00:01:11.326 --> 00:01:12.266 align:middle Let's profile! 00:01:12.266 --> 00:01:21.726 align:middle I'll call this one [Recording] Homepage authenticated dev: http://bit.ly/sf-bf-timeline. 00:01:21.726 --> 00:01:24.326 align:middle Poetry. When that finishes, as usual, click to view the call graph. 00:01:26.736 --> 00:01:29.756 align:middle Okay: there's not too much interesting here... 00:01:30.146 --> 00:01:35.486 align:middle especially because the DebugClassLoader stuff is once again adding "noise" 00:01:35.486 --> 00:01:37.056 align:middle that won't be there on production. 00:01:38.246 --> 00:01:40.846 align:middle It's not clear what the critical path is... 00:01:41.526 --> 00:01:45.706 align:middle and the page, at this point, is probably fast enough for me. 00:01:46.536 --> 00:01:50.216 align:middle So let's look at something else: click the "Timeline" link. 00:01:51.526 --> 00:01:54.266 align:middle OooOOOOo. The timeline... 00:01:54.626 --> 00:01:56.576 align:middle other than just looking cool... 00:01:57.086 --> 00:01:59.026 align:middle is the place to go to... 00:01:59.306 --> 00:02:02.886 align:middle just... basically figure out how your app is working: 00:02:03.496 --> 00:02:06.036 align:middle how does the code flow through all the layers? 00:02:06.746 --> 00:02:09.016 align:middle What hidden things might be happening? 00:02:09.016 --> 00:02:14.586 align:middle For example, this page apparently has 28 SQL queries. 00:02:14.956 --> 00:02:17.076 align:middle But where are these happening? 00:02:17.426 --> 00:02:19.126 align:middle Are they all in the controller? 00:02:19.516 --> 00:02:22.906 align:middle Are some in the controller and others are in the template? 00:02:23.246 --> 00:02:26.626 align:middle Are some coming from somewhere else we didn't even think of? 00:02:27.386 --> 00:02:30.596 align:middle That's something that the call graph can't really tell us. 00:02:30.976 --> 00:02:32.206 align:middle I love the timeline... 00:02:32.206 --> 00:02:35.486 align:middle but I'll admit that the first few times I looked at this page... 00:02:35.646 --> 00:02:38.316 align:middle I didn't really understand what was going on... 00:02:38.616 --> 00:02:40.796 align:middle or how to make this useful. 00:02:41.376 --> 00:02:47.146 align:middle It looks simple enough - we can see the function calls and their child calls from left to right 00:02:47.226 --> 00:02:51.066 align:middle through the lifecycle of the request - but there's more to it. 00:02:51.666 --> 00:02:54.856 align:middle Let's start on the left: these timeline metrics. 00:02:55.336 --> 00:03:00.376 align:middle Metrics are basically a way that Blackfire groups function calls together 00:03:00.576 --> 00:03:02.286 align:middle and give them a label. 00:03:02.406 --> 00:03:07.426 align:middle For example, Blackfire knows that a specific function call means 00:03:07.596 --> 00:03:10.086 align:middle that an event is being dispatched. 00:03:10.796 --> 00:03:16.916 align:middle It finds those, labels all of them as symfony.events and give them this purple color 00:03:17.106 --> 00:03:19.226 align:middle so that they show up more clearly on the right. 00:03:19.906 --> 00:03:21.726 align:middle Here's one Symfony event right here... 00:03:22.166 --> 00:03:23.346 align:middle and there's another one. 00:03:23.916 --> 00:03:31.086 align:middle It does the same thing for SQL queries: it knows that PDOStatement::execute(), PDO::query() 00:03:31.256 --> 00:03:35.846 align:middle and several other functions mean that an SQL query is being made. 00:03:36.596 --> 00:03:41.056 align:middle It groups them together, calls them sql and labels them as yellow. 00:03:41.656 --> 00:03:43.186 align:middle It's a great idea... 00:03:43.396 --> 00:03:45.146 align:middle and is just that simple. 00:03:46.256 --> 00:03:49.236 align:middle Below this, there is another section called "Other Metrics". 00:03:49.756 --> 00:03:54.106 align:middle These are the same thing: meaningful groups of function calls. 00:03:54.746 --> 00:03:59.346 align:middle The only difference is that Blackfire does not give these a special color 00:03:59.506 --> 00:04:01.736 align:middle and they don't show up on the timeline. 00:04:02.376 --> 00:04:02.936 align:middle These are... 00:04:03.106 --> 00:04:04.716 align:middle just... raw data... 00:04:05.016 --> 00:04:06.126 align:middle that sit right here. 00:04:06.876 --> 00:04:10.206 align:middle If you're wondering why that would useful... 00:04:10.506 --> 00:04:11.636 align:middle I was too! 00:04:12.276 --> 00:04:15.876 align:middle For the purpose of the timeline, they are not useful. 00:04:16.406 --> 00:04:19.476 align:middle They'll come in handy later when we talk more about metrics. 00:04:19.876 --> 00:04:21.906 align:middle Metrics are their own big topic. 00:04:22.806 --> 00:04:26.926 align:middle Let's look at one of the timeline metrics doctrine.entities.hydrated. 00:04:27.586 --> 00:04:29.046 align:middle What does this one mean? 00:04:29.566 --> 00:04:32.776 align:middle Sometimes the title of a metric will tell you a bit more... 00:04:33.076 --> 00:04:35.676 align:middle but often the metric name is all you really have. 00:04:36.116 --> 00:04:38.406 align:middle Most metrics are self-explanatory. 00:04:39.186 --> 00:04:43.086 align:middle Depending on how well you know Doctrine, this might be obvious... 00:04:43.286 --> 00:04:50.736 align:middle or not. This metric refers to whenever one or more entities are hydrated into an object. 00:04:51.856 --> 00:04:53.396 align:middle Notice the count is 3. 00:04:53.916 --> 00:04:59.536 align:middle For this metric, it's not that there are only 3 objects being hydrated during this request, 00:05:00.046 --> 00:05:07.066 align:middle but that our code asks Doctrine to hydrate one or more objects on three occasions. 00:05:07.976 --> 00:05:11.856 align:middle So where are the 3 times that we're hydrating objects? 00:05:12.636 --> 00:05:16.116 align:middle One of the cool things is that, when you hover over a timeline metric, 00:05:16.346 --> 00:05:19.246 align:middle it adds a border to the matching boxes on the right. 00:05:19.826 --> 00:05:21.766 align:middle It's... a little subtle... 00:05:21.766 --> 00:05:23.176 align:middle but it does the trick. 00:05:24.176 --> 00:05:25.916 align:middle I wish you could double-click and... 00:05:26.056 --> 00:05:28.236 align:middle maybe zoom to the matching boxes... 00:05:28.346 --> 00:05:32.816 align:middle but it's tricky because they may be spread out over the whole request. 00:05:32.916 --> 00:05:37.106 align:middle If we hover over doctrine.entities.hydrated... 00:05:37.406 --> 00:05:39.786 align:middle hmm... I don't see those. 00:05:40.516 --> 00:05:42.446 align:middle You need to do a little bit of digging... 00:05:43.046 --> 00:05:44.196 align:middle I'll hover back over. 00:05:44.536 --> 00:05:45.216 align:middle There they are. 00:05:45.626 --> 00:05:49.496 align:middle It turns out that the 3 calls are not all in the same place: 00:05:49.886 --> 00:05:53.506 align:middle they're coming from three very different parts of our code. 00:05:54.186 --> 00:05:56.096 align:middle The first is part of the firewall... 00:05:56.526 --> 00:05:59.096 align:middle probably querying for the logged in user... 00:05:59.096 --> 00:06:02.706 align:middle and the other two are down in some template rendering... 00:06:03.446 --> 00:06:08.096 align:middle along with a few similarly-colored doctrine.dql.parsed items. 00:06:08.196 --> 00:06:11.966 align:middle I want to look at what's happening inside of this template... 00:06:12.416 --> 00:06:15.216 align:middle but a lot of these things are really small. 00:06:16.206 --> 00:06:18.536 align:middle On top, we can see the entire timeline. 00:06:21.036 --> 00:06:24.766 align:middle Click where we want to start, move over, and let go! 00:06:25.206 --> 00:06:28.226 align:middle Zoom! Much easier to see! 00:06:28.836 --> 00:06:34.436 align:middle In this spot, Doctrine parses its DQL, it makes an SQL query here... 00:06:34.796 --> 00:06:36.536 align:middle and a different query a bit later. 00:06:37.236 --> 00:06:42.566 align:middle So as far as getting insight into what's really going on in your application, 00:06:42.566 --> 00:06:44.796 align:middle you can't get much better than this. 00:06:45.256 --> 00:06:48.916 align:middle You can even see our N+1 problem visually: 00:06:49.716 --> 00:06:54.296 align:middle it makes a query to count the comments little-by-little as the template renders. 00:06:55.576 --> 00:06:57.226 align:middle Hit the "Home" icon to zoom back out. 00:06:57.976 --> 00:06:58.656 align:middle This is cool... 00:06:58.866 --> 00:07:03.896 align:middle but I mentioned that, as soon as we logged in, there was some new code 00:07:03.896 --> 00:07:05.586 align:middle that was now running in the background. 00:07:06.696 --> 00:07:11.016 align:middle Next, let's look a bit closer at the timeline to discover what that is 00:07:11.276 --> 00:07:13.716 align:middle and a hidden performance problem.