WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.186 --> 00:00:07.306 align:middle Once we determine that we want to create a probe dynamically in our code, we really want to do 00:00:07.306 --> 00:00:14.236 align:middle that as early as possible so that Blackfire can "instrument" as much of our code as possible. 00:00:14.236 --> 00:00:18.886 align:middle In Symfony, we can do that with an event subscriber... 00:00:19.146 --> 00:00:21.886 align:middle which we will generate to be super lazy. 00:00:21.886 --> 00:00:27.006 align:middle First, in .env, make sure that you're back in the dev environment. 00:00:27.006 --> 00:00:29.986 align:middle Then, find your terminal and run: 00:00:29.986 --> 00:00:37.666 align:middle php bin/console make:subscriber Call it BlackfireAutoProfileSubscriber... 00:00:39.306 --> 00:00:42.676 align:middle and we want to listen to RequestEvent: 00:00:44.876 --> 00:00:51.206 align:middle Go check out the code src/EventSubscriber /BlackfireAutoProfileSubscriber.php. 00:00:51.206 --> 00:00:56.986 align:middle So, when this RequestEvent happens - which Symfony dispatches super early 00:00:56.986 --> 00:01:01.586 align:middle when handling a request, we want to create & enable the probe. 00:01:02.576 --> 00:01:09.036 align:middle Copy all of the $shouldProfile code, remove it from the controller and paste it here. 00:01:09.036 --> 00:01:15.006 align:middle Now add $request = $event->getRequest(). 00:01:16.706 --> 00:01:20.916 align:middle To make this only profile the GitHub organization AJAX call - 00:01:21.176 --> 00:01:27.496 align:middle whose URL is /api/github-organization - set $shouldProfile equal 00:01:27.496 --> 00:01:34.926 align:middle to $request->getPathInfo() === '/api/github-organization'. 00:01:35.876 --> 00:01:41.616 align:middle In a real app, I would add more code to make sure $shouldProfile is only true 00:01:41.726 --> 00:01:45.376 align:middle on the very specific requests we want to profile. 00:01:46.236 --> 00:01:52.896 align:middle Now I'll re-type the t on Client and select the correct Client class so that PhpStorm adds 00:01:52.896 --> 00:01:55.716 align:middle that use statement to the top of the class for me. 00:01:55.716 --> 00:01:57.346 align:middle Thanks PhpStorm! 00:01:57.876 --> 00:02:01.376 align:middle But before we try this, I want to code for one edge case: 00:02:01.946 --> 00:02:06.546 align:middle if not $event->isMasterRequest(), then return. 00:02:07.646 --> 00:02:12.846 align:middle It might not be important in your app, but Symfony has a "sub-request" system... 00:02:13.336 --> 00:02:20.716 align:middle and the short explanation is that we don't want to profile those: they are not real requests... 00:02:21.016 --> 00:02:23.566 align:middle and would make a big mess of things. 00:02:24.606 --> 00:02:26.376 align:middle Ok, let's try this! 00:02:26.846 --> 00:02:27.896 align:middle I'll close a tab... 00:02:28.206 --> 00:02:29.926 align:middle then refresh the homepage... 00:02:30.396 --> 00:02:33.036 align:middle which causes the AJAX request to be made. 00:02:33.806 --> 00:02:34.966 align:middle You can see it's slow. 00:02:35.806 --> 00:02:39.776 align:middle Now reload the list of profiles on Blackfire... 00:02:39.776 --> 00:02:40.376 align:middle there it is! 00:02:40.876 --> 00:02:44.556 align:middle Open it up. 00:02:44.616 --> 00:02:48.316 align:middle And... oh wow, oh weird! 00:02:48.826 --> 00:02:52.236 align:middle 281 microseconds. 00:02:53.016 --> 00:02:57.146 align:middle Give this a name: [Recording] Auto from subscriber: 00:02:57.146 --> 00:03:01.686 align:middle http://bit.ly/sf-bf-broken-auto-profile This profile is... 00:03:01.686 --> 00:03:08.326 align:middle broken. That's 281 microseconds - so .281 milliseconds. 00:03:08.786 --> 00:03:14.236 align:middle And the entire profile is just the Probe::enable() call itself! 00:03:14.236 --> 00:03:14.806 align:middle What happened!? 00:03:15.476 --> 00:03:23.816 align:middle Well... remember: the $probe object automatically calls close() on itself as soon 00:03:23.816 --> 00:03:26.536 align:middle as that variable is garbage collected... 00:03:26.796 --> 00:03:30.286 align:middle which happens at the end of the subscriber method. 00:03:31.226 --> 00:03:31.916 align:middle That means.... 00:03:32.176 --> 00:03:35.326 align:middle we profiled exactly one line of code. 00:03:36.386 --> 00:03:40.246 align:middle The solution is to call $probe->close() manually... 00:03:40.566 --> 00:03:45.426 align:middle which - more importantly - will require us to store the Probe object in a way 00:03:45.636 --> 00:03:48.986 align:middle where PHP won't garbage collect it too early. 00:03:49.896 --> 00:03:57.986 align:middle So here's the goal: call $probe->close() as late as possible during the request lifecycle. 00:03:57.986 --> 00:04:00.616 align:middle We can do this by listening to a different event: 00:04:01.636 --> 00:04:07.916 align:middle when TerminateEvent::class is dispatched - that's very late in Symfony - 00:04:08.316 --> 00:04:10.986 align:middle call the onTerminateEvent() method. 00:04:12.076 --> 00:04:15.196 align:middle I'll hit an Alt + Enter shortcut to create that method... 00:04:16.116 --> 00:04:19.526 align:middle then add the argument TerminateEvent $event. 00:04:20.876 --> 00:04:26.976 align:middle To be able to call $probe->close(), we need to store the probe object on a property. 00:04:28.046 --> 00:04:32.336 align:middle Add private $probe with some documentation that says 00:04:32.516 --> 00:04:37.526 align:middle that this will either be a Probe instance from Blackfire or null. 00:04:39.276 --> 00:04:44.566 align:middle Update the code below to be $this->probe = $blackfire->createProbe(). 00:04:44.566 --> 00:04:53.666 align:middle Finally, inside onTerminateEvent, if $this->probe - I should not have put 00:04:53.666 --> 00:05:00.796 align:middle that exclamation point, that's a mistake - then $this->probe->close(). 00:05:00.896 --> 00:05:04.906 align:middle If you assume that I did not include the exclamation point... 00:05:05.156 --> 00:05:06.636 align:middle then this makes sense! 00:05:07.196 --> 00:05:10.496 align:middle If we created the probe, then we will close it. 00:05:11.046 --> 00:05:12.376 align:middle Problem solved. 00:05:13.046 --> 00:05:14.316 align:middle And... really... 00:05:14.676 --> 00:05:21.836 align:middle the fact that we set the probe onto a property is the real magic: that will prevent PHP 00:05:21.836 --> 00:05:23.726 align:middle from garbage-collecting that object... 00:05:24.196 --> 00:05:28.066 align:middle which will prevent it from closing itself until we're ready. 00:05:28.906 --> 00:05:31.626 align:middle While we're here, let's make this a little bit cooler. 00:05:32.276 --> 00:05:35.486 align:middle Change onRequestEvent to be an array... 00:05:35.676 --> 00:05:38.726 align:middle and add 1000 as the second item. 00:05:39.316 --> 00:05:40.616 align:middle This syntax is... 00:05:40.616 --> 00:05:45.016 align:middle weird. But the result is good: it says that we want to listen 00:05:45.016 --> 00:05:48.686 align:middle to this event with a priority of 1000. 00:05:49.246 --> 00:05:54.566 align:middle That will make our code run even earlier so that even more code will get profiled. 00:05:55.306 --> 00:06:00.256 align:middle Oh, and there's one other cool thing we can do: we can configure the profile. 00:06:00.956 --> 00:06:07.736 align:middle Add $configuration = new Configuration() from Blackfire\Profile. 00:06:07.736 --> 00:06:12.046 align:middle Thanks to this, we can control a number of things about the profile... 00:06:12.516 --> 00:06:17.906 align:middle the best being ->setTitle(): Automatic GitHub org Profile. 00:06:19.506 --> 00:06:21.266 align:middle Pass this to createProbe(). 00:06:24.136 --> 00:06:25.206 align:middle That's it! 00:06:25.206 --> 00:06:27.526 align:middle Let's see how things whole thing works. 00:06:28.326 --> 00:06:30.956 align:middle Back at the browser, I'll close the old profile... 00:06:31.486 --> 00:06:33.246 align:middle and refresh the homepage. 00:06:34.706 --> 00:06:36.806 align:middle Once the AJAX call finishes... 00:06:37.086 --> 00:06:39.746 align:middle reload the Blackfire profile list. 00:06:41.136 --> 00:06:44.176 align:middle Ah! We were too fast - it's still processing. 00:06:44.836 --> 00:06:46.196 align:middle Try again and... 00:06:46.946 --> 00:06:47.746 align:middle there it is! 00:06:48.176 --> 00:06:48.716 align:middle Open it up! 00:06:52.156 --> 00:06:56.806 align:middle http://bit.ly/sf-bf-auto-profile-subscriber Much better. 00:06:56.806 --> 00:06:58.356 align:middle A few things might still look a bit odd... 00:06:58.356 --> 00:07:00.836 align:middle because we're still not profiling every single line of code. 00:07:00.836 --> 00:07:04.896 align:middle For example, Probe::enable() seems to wrap everything. 00:07:05.346 --> 00:07:07.046 align:middle But all the important data is there. 00:07:07.766 --> 00:07:13.436 align:middle To avoid making a million of these profiles as we keep coding, I'll go back to the subscriber 00:07:13.696 --> 00:07:18.906 align:middle and avoid profiling entirely by setting $shouldProfile = false. 00:07:20.546 --> 00:07:25.686 align:middle Next: you already write automated tests for your app to help prove 00:07:25.846 --> 00:07:28.626 align:middle that key features never have bugs. 00:07:29.116 --> 00:07:29.856 align:middle You... ah... 00:07:30.316 --> 00:07:32.056 align:middle do write tests right? 00:07:32.516 --> 00:07:33.596 align:middle Let's... say you do. 00:07:33.836 --> 00:07:36.676 align:middle Me too. Anyways, have you ever thought 00:07:36.676 --> 00:07:40.676 align:middle about writing automated tests to prevent performance bugs? 00:07:41.306 --> 00:07:42.916 align:middle Yep, that's possible! 00:07:43.386 --> 00:07:49.436 align:middle We can use Blackfire inside our test suite to add performance assertions. 00:07:49.856 --> 00:07:51.036 align:middle It's pretty sweet... 00:07:51.486 --> 00:07:56.196 align:middle and now that we understand the SDK, it will feel great.