WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.106 --> 00:00:04.456 align:middle One of the big spots on the timeline is the RequestEvent. 00:00:05.236 --> 00:00:10.876 align:middle It's purple because this is an event: the first event that Symfony dispatches. 00:00:11.186 --> 00:00:13.506 align:middle It happens before the controller is called... 00:00:13.766 --> 00:00:15.916 align:middle which is pretty obvious in this view. 00:00:16.716 --> 00:00:19.356 align:middle Let's zoom in: by double-clicking the square. 00:00:19.946 --> 00:00:20.646 align:middle Beautiful! 00:00:21.616 --> 00:00:23.516 align:middle What happens inside this event? 00:00:24.056 --> 00:00:24.936 align:middle Apparently... 00:00:24.936 --> 00:00:26.606 align:middle the routing layer happens! 00:00:26.946 --> 00:00:28.416 align:middle That's RouterListener. 00:00:29.166 --> 00:00:33.846 align:middle You can also see Firewall: this is where authentication takes place. 00:00:34.526 --> 00:00:36.836 align:middle Security is a complex system... 00:00:36.836 --> 00:00:41.476 align:middle so being able to see a bit about what happens inside of it is pretty cool. 00:00:41.986 --> 00:00:43.006 align:middle At some point... 00:00:43.006 --> 00:00:47.906 align:middle it calls a method on EntityRepository and we can see the query 00:00:47.906 --> 00:00:50.256 align:middle for the User object that we're logged in as. 00:00:50.646 --> 00:00:51.106 align:middle Pretty cool. 00:00:52.316 --> 00:00:58.046 align:middle There's one more big chunk under RequestEvent: something called AgreeToTermsSubscriber... 00:00:58.476 --> 00:01:00.586 align:middle which is taking 30 milliseconds. 00:01:01.036 --> 00:01:08.466 align:middle Let's open that class and see what it does: src/EventSubscriber/AgreeToTermsSubscriber.php. 00:01:08.466 --> 00:01:13.596 align:middle Ah yes. Every now and then, we update the "terms of service" on our site. 00:01:14.056 --> 00:01:18.896 align:middle When we do that, our lovely lawyers have told us that we need 00:01:18.896 --> 00:01:22.076 align:middle to require people to agree to the updated terms. 00:01:22.676 --> 00:01:26.876 align:middle This class handles that: it gets the authenticated user and, 00:01:27.226 --> 00:01:29.996 align:middle if they're not logged in, it does nothing. 00:01:30.776 --> 00:01:37.336 align:middle But if they are logged in, then it renders a twig template with an "agree to the terms" form. 00:01:38.076 --> 00:01:44.026 align:middle Eventually, if the terms have been updated since the last time this User agreed to them, 00:01:44.456 --> 00:01:49.736 align:middle it sets that form as the response instead of rendering the real page. 00:01:50.516 --> 00:01:51.866 align:middle We haven't seen this form yet... 00:01:52.106 --> 00:01:54.426 align:middle and... it's not really that important. 00:01:54.926 --> 00:02:01.536 align:middle Because we rarely update our terms, 99.99% of the requests 00:02:01.536 --> 00:02:04.146 align:middle to the site will not display the form. 00:02:05.146 --> 00:02:08.796 align:middle So... the fact that this is taking 30 milliseconds... 00:02:09.026 --> 00:02:12.156 align:middle even though it will almost never do anything... 00:02:12.296 --> 00:02:13.806 align:middle is kind of a lot! 00:02:14.866 --> 00:02:16.606 align:middle Oh, and see this blue background? 00:02:16.966 --> 00:02:19.536 align:middle I love this: it's the memory footprint. 00:02:20.336 --> 00:02:25.796 align:middle If we trace over this call - this is about when the AgreeToTermsSubscriber happens - 00:02:26.196 --> 00:02:29.026 align:middle the memory starts at 3.44 megabytes... 00:02:30.036 --> 00:02:32.966 align:middle and finishes around 4.46. 00:02:33.406 --> 00:02:38.536 align:middle That's 1 megabyte of memory - kinda high for such a rarely-used function. 00:02:39.666 --> 00:02:43.346 align:middle The point is: this method doesn't take that long to run. 00:02:43.746 --> 00:02:49.296 align:middle And so, it may not have shown up as a performance critical path on the call graph. 00:02:49.956 --> 00:02:54.176 align:middle But thanks to the timeline, this invisible layer jumped out at us. 00:02:55.156 --> 00:02:57.826 align:middle And... I think it is taking a bit too long. 00:02:58.976 --> 00:03:02.986 align:middle Back in the code, the mistake I made is pretty embarrassing. 00:03:03.486 --> 00:03:08.016 align:middle I'm using some pretend logic to see whether or not we need to render the form. 00:03:08.696 --> 00:03:11.616 align:middle But... I put the check too late! 00:03:11.976 --> 00:03:14.266 align:middle We're doing all the work of rendering the form... 00:03:14.536 --> 00:03:16.116 align:middle even if we don't use it. 00:03:16.886 --> 00:03:21.876 align:middle Let's move that code all the way to the top. 00:03:21.876 --> 00:03:26.696 align:middle Ah, too far - it needs to be after the fake $latestTermsDate variable. 00:03:27.406 --> 00:03:28.056 align:middle That looks better. 00:03:29.166 --> 00:03:29.776 align:middle Let's try it! 00:03:31.706 --> 00:03:33.036 align:middle I'll refresh the page. 00:03:35.806 --> 00:03:42.246 align:middle Profile again and call it [Recording] Homepage authenticated fixed subscriber: 00:03:42.246 --> 00:03:55.736 align:middle http://bit.ly/sf-bf-timeline-fix Let's jump straight to view the Timeline... 00:03:55.736 --> 00:03:57.706 align:middle double-click RequestEvent and this time... 00:03:57.706 --> 00:03:59.696 align:middle AgreeToTermsSubscriber is gone! 00:04:00.026 --> 00:04:02.356 align:middle We can see RouterListener and Firewall... 00:04:02.546 --> 00:04:04.976 align:middle but not AgreeToTermsSubscriber. 00:04:05.746 --> 00:04:09.656 align:middle That's not because our app isn't calling it anymore: it is. 00:04:09.966 --> 00:04:15.016 align:middle It's because Blackfire hides function calls that take almost no resources. 00:04:15.776 --> 00:04:16.776 align:middle That's great. 00:04:17.566 --> 00:04:21.626 align:middle Next, we know that we can write code inside a function that is slow. 00:04:22.016 --> 00:04:25.676 align:middle But did you know that sometimes even the instantiation 00:04:25.676 --> 00:04:28.016 align:middle of an object can eat a lot of resources? 00:04:28.936 --> 00:04:32.836 align:middle Let's see how that looks in Blackfire and leverage a Symfony feature - 00:04:33.086 --> 00:04:36.956 align:middle service subscribers - to make instantiation lighter.