WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.176 --> 00:00:06.666 align:middle When you open the browser extension to create a profile, it has a few options that we've been... 00:00:06.716 --> 00:00:08.206 align:middle ignoring so far. 00:00:08.856 --> 00:00:14.346 align:middle For example, "debugging mode" will tell Blackfire to disable pruning - 00:00:14.696 --> 00:00:19.126 align:middle that's when it removes data for functions that don't take a lot of resources - 00:00:19.456 --> 00:00:25.316 align:middle and also to disable anonymization - that's when it hides exact details used 00:00:25.316 --> 00:00:28.426 align:middle in SQL queries and HTTP requests. 00:00:29.326 --> 00:00:32.426 align:middle Debugging mode is nice if something weird is going on.. 00:00:32.666 --> 00:00:36.756 align:middle and you want to fully see what's happening inside a request. 00:00:37.526 --> 00:00:41.316 align:middle Another superpower of Blackfire is called distributed profiling... 00:00:41.736 --> 00:00:43.456 align:middle which you either won't care about... 00:00:43.706 --> 00:00:46.826 align:middle or it's the most awesome thing ever. 00:00:47.666 --> 00:00:52.086 align:middle Imagine you have a micro-service architecture where, when you load the page, 00:00:52.426 --> 00:00:56.896 align:middle it makes a few HTTP requests to some microservices. 00:00:57.566 --> 00:01:01.006 align:middle If you have Blackfire installed on all of your microservices, 00:01:01.356 --> 00:01:07.886 align:middle Blackfire will automatically create profiles for every request made to every app. 00:01:08.866 --> 00:01:12.586 align:middle The final result is a profile with sub-profiles 00:01:12.826 --> 00:01:16.916 align:middle that show you how the entire infrastructure is working together. 00:01:17.126 --> 00:01:18.506 align:middle It's... pretty incredible. 00:01:19.026 --> 00:01:24.516 align:middle But, if you want to disable it and only profile this main app, you can do that with this option. 00:01:25.406 --> 00:01:27.746 align:middle The last option is to "disable aggregation". 00:01:28.316 --> 00:01:34.166 align:middle That's a fancy way of telling Blackfire that you want to make & profile just one request, 00:01:34.386 --> 00:01:37.716 align:middle instead of making 10 requests and averaging the results. 00:01:38.436 --> 00:01:42.336 align:middle But what I really want to look at is this "Profile all requests" link. 00:01:43.046 --> 00:01:43.786 align:middle Hit "Record"... 00:01:44.216 --> 00:01:45.156 align:middle then refresh. 00:01:46.506 --> 00:01:47.516 align:middle Woh! Cool! 00:01:47.976 --> 00:01:50.016 align:middle It already made 2 requests! 00:01:50.516 --> 00:01:52.426 align:middle And if I scroll down a little bit... 00:01:52.666 --> 00:01:54.206 align:middle there's a third! 00:01:54.956 --> 00:01:56.266 align:middle Let's stop right there. 00:01:57.146 --> 00:01:59.316 align:middle That jumps us to our Blackfire dashboard. 00:02:00.176 --> 00:02:04.796 align:middle These last three profiles were just created: one for the homepage 00:02:05.006 --> 00:02:09.366 align:middle and two others: these are both AJAX calls! 00:02:09.896 --> 00:02:12.186 align:middle Surprise! Without even thinking about it, 00:02:12.366 --> 00:02:16.356 align:middle we discovered a few extra requests that are part of that page. 00:02:17.116 --> 00:02:20.416 align:middle This first one - /api/github-organization - 00:02:20.606 --> 00:02:24.756 align:middle is what loads this GitHub repository info on the right. 00:02:25.326 --> 00:02:28.766 align:middle This makes an API call for the most popular repositories 00:02:28.916 --> 00:02:31.346 align:middle under the Symfonycasts organization... 00:02:31.536 --> 00:02:33.396 align:middle which is kind of silly... 00:02:33.516 --> 00:02:38.416 align:middle but it was a great way to show how network requests look in Blackfire. 00:02:38.996 --> 00:02:40.236 align:middle We'll see that in a minute. 00:02:40.836 --> 00:02:43.706 align:middle This other request - for /_sightings - 00:02:44.016 --> 00:02:48.416 align:middle is an AJAX call that powers the forever scroll on the page. 00:02:49.026 --> 00:02:49.936 align:middle Basically... 00:02:49.936 --> 00:02:53.426 align:middle I like using "profile all requests" in 3 situations. 00:02:53.996 --> 00:02:57.756 align:middle One, to get an idea of what's all happening on a page. 00:02:58.236 --> 00:03:00.836 align:middle Two, to profile AJAX requests... 00:03:01.246 --> 00:03:04.146 align:middle though I'll show you another way to do that soon. 00:03:04.576 --> 00:03:11.546 align:middle And three, to profile form submits: fill out the form, hit "Record", then submit. 00:03:12.856 --> 00:03:13.616 align:middle Let's look closer 00:03:13.616 --> 00:03:21.496 align:middle at the /api/github-organization AJAX profile: https://bit.ly/sf-bf-github-org. 00:03:21.496 --> 00:03:25.286 align:middle As I mentioned, this makes a network request to the GitHub API to load repository information. 00:03:26.026 --> 00:03:26.816 align:middle The profile... 00:03:26.816 --> 00:03:28.766 align:middle is almost comical! 00:03:29.326 --> 00:03:37.186 align:middle Out of the 438 millisecond wall time - 82% of it is from curl_multi_select() - 00:03:37.526 --> 00:03:40.236 align:middle that's the time spent making any API calls. 00:03:40.716 --> 00:03:45.946 align:middle It's kind of fun to look at this in the CPU dimension, which is only 74 milliseconds. 00:03:46.826 --> 00:03:49.796 align:middle curl_multi_exec() is still the biggest offender... 00:03:49.936 --> 00:03:53.346 align:middle but it's a lot less obvious what the critical path is. 00:03:54.246 --> 00:03:58.996 align:middle Compare that with the I/O wait dimension, which includes network time. 00:04:00.136 --> 00:04:03.656 align:middle The critical path is ridiculously obvious here. 00:04:04.366 --> 00:04:08.386 align:middle This is an extreme example of how different dimensions can be more 00:04:08.386 --> 00:04:10.876 align:middle or less useful depending on the situation. 00:04:11.626 --> 00:04:13.816 align:middle One of the interesting things is that... 00:04:13.896 --> 00:04:16.426 align:middle this is not the full call graph. 00:04:17.236 --> 00:04:22.356 align:middle According to this, the code goes straight from handleRaw() - which is the first call 00:04:22.356 --> 00:04:24.916 align:middle into the Symfony Framework - to our controller. 00:04:25.966 --> 00:04:30.006 align:middle In reality, there are many more function calls in between. 00:04:30.816 --> 00:04:32.636 align:middle Switch back to the CPU dimension. 00:04:33.406 --> 00:04:35.866 align:middle Yep! This shows more nodes. 00:04:36.496 --> 00:04:40.446 align:middle This is the result of that "pruning" I mentioned a few minutes ago. 00:04:41.106 --> 00:04:45.496 align:middle Blackfire removes function calls that don't consume any significant resources 00:04:45.706 --> 00:04:50.326 align:middle so that the critical path - from a performance standpoint - is more obvious. 00:04:50.896 --> 00:04:57.676 align:middle The call graph also automatically hides or shows some info based on what you're zoomed in on. 00:04:57.676 --> 00:05:01.186 align:middle In this situation, the critical path is obvious. 00:05:01.756 --> 00:05:04.176 align:middle You can also see the network requests on top. 00:05:04.906 --> 00:05:10.656 align:middle There are actually two: one that returns 1.5 kilobytes and another that returns 5. 00:05:11.966 --> 00:05:14.386 align:middle This shows the network time too... 00:05:14.516 --> 00:05:18.976 align:middle but at least if you're using the Symfony HTTP client like I am, 00:05:19.316 --> 00:05:23.106 align:middle these numbers aren't right - they're far too small... 00:05:23.766 --> 00:05:27.946 align:middle I think that's due to the asynchronous nature of Symfony's HTTP Client. 00:05:28.636 --> 00:05:33.706 align:middle That's ok - because the overall cost is showing up correctly in all the other dimensions. 00:05:34.506 --> 00:05:36.296 align:middle So how do we fix this? 00:05:36.526 --> 00:05:38.246 align:middle Should we add some caching? 00:05:38.476 --> 00:05:42.706 align:middle Or somehow try to make only one API call instead of two? 00:05:43.366 --> 00:05:47.266 align:middle We're actually going to revisit and fix this problem later. 00:05:47.756 --> 00:05:51.716 align:middle For now, I wanted you to be aware of the "Profile All" feature. 00:05:52.736 --> 00:05:58.416 align:middle Next, let's check out the Blackfire command-line tool, which has two superpowers... 00:05:58.926 --> 00:06:02.126 align:middle one of which has nothing to do with the command line.