WEBVTT

NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com

00:00:01.076 --> 00:00:06.266 align:middle
There are two different ways to optimize any
function: either optimize the code inside

00:00:06.266 --> 00:00:09.926 align:middle
that function or you can try to
call the function less times.

00:00:10.736 --> 00:00:16.316 align:middle
In our case, we found that the most problematic
function is UnitOfWork::createEntity.

00:00:16.996 --> 00:00:20.586 align:middle
But this is a vendor function:
it's not our code.

00:00:20.976 --> 00:00:23.386 align:middle
So it's not something that we can optimize.

00:00:23.616 --> 00:00:27.996 align:middle
And honestly, it's probably
already super-optimized anyways.

00:00:28.766 --> 00:00:31.426 align:middle
But we could try to call it less times...

00:00:31.776 --> 00:00:36.476 align:middle
if we can understand what in our
app is causing so many calls!

00:00:37.266 --> 00:00:41.546 align:middle
The call graph - the big diagram in the
center of this page - holds the answer.

00:00:41.546 --> 00:00:46.126 align:middle
Start by clicking on the magnifying
glass next to createEntity.

00:00:47.656 --> 00:00:51.116 align:middle
Woh! That zoomed us straight
to that "node" on the right.

00:00:51.526 --> 00:00:53.266 align:middle
Let's zoom out a little.

00:00:54.436 --> 00:00:59.346 align:middle
The first thing to notice is that the call
graph is basically a visual representation

00:00:59.476 --> 00:01:01.856 align:middle
of the information from the function list.

00:01:02.806 --> 00:01:06.746 align:middle
On the left, it says this
function has two "callers".

00:01:07.506 --> 00:01:09.856 align:middle
On the right, we can see those two callers.

00:01:10.416 --> 00:01:13.116 align:middle
But when you're trying to
figure out the big picture

00:01:13.116 --> 00:01:16.716 align:middle
of what's going on, the call graph is way nicer.

00:01:17.566 --> 00:01:19.586 align:middle
Let's zoom out a bunch further.

00:01:24.226 --> 00:01:26.196 align:middle
Now we can see a clear red path...

00:01:26.606 --> 00:01:30.286 align:middle
that eventually leads to
the dark red node down here.

00:01:31.856 --> 00:01:33.846 align:middle
This is called the critical path.

00:01:34.546 --> 00:01:39.856 align:middle
One of Blackfire's main jobs is to help
us make sense out of all this data.

00:01:40.676 --> 00:01:45.436 align:middle
One way it does that is exactly
this: by highlighting the "path"

00:01:45.436 --> 00:01:47.386 align:middle
to the biggest problem in our app.

00:01:48.186 --> 00:01:52.796 align:middle
I'm going to hit this little "home"
icon - that will reset the call graph,

00:01:52.976 --> 00:01:56.056 align:middle
instead of centering it around
the createEntity node.

00:01:57.296 --> 00:02:01.586 align:middle
In this view, Blackfire does hide
some less-important information

00:02:01.586 --> 00:02:07.276 align:middle
around the createEntity node, but it gives us
the best overall summary of what's going on:

00:02:07.706 --> 00:02:10.566 align:middle
we can clearly see the critical path.

00:02:10.566 --> 00:02:15.406 align:middle
The critical thing to understand is:
why is that path in our app so slow?

00:02:16.436 --> 00:02:18.726 align:middle
Let's trace up from the problem node...

00:02:18.956 --> 00:02:22.666 align:middle
to find where our code starts.

00:02:22.666 --> 00:02:25.166 align:middle
Ah, here's our controller being rendered...

00:02:25.366 --> 00:02:27.236 align:middle
and then it renders a template.

00:02:27.786 --> 00:02:32.736 align:middle
That's interesting: it means the problem
is coming from inside a template...

00:02:32.736 --> 00:02:35.796 align:middle
from inside the body block apparently.

00:02:36.696 --> 00:02:40.566 align:middle
Then it jumps to a Twig extension
called getUserActivityText()...

00:02:40.816 --> 00:02:45.896 align:middle
that calls something else
CommentHelper::countRecentCommentsForUser().

00:02:46.626 --> 00:02:49.236 align:middle
That's the last function
before it jumps into Doctrine.

00:02:49.826 --> 00:02:56.026 align:middle
So the problem in our code is something
around this getUserActivityText() stuff.

00:02:56.026 --> 00:03:00.206 align:middle
Let's open up this template:
main/sighting_show.html.twig -

00:03:00.536 --> 00:03:04.476 align:middle
at templates/main/sighting_show.html.twig.

00:03:04.476 --> 00:03:12.146 align:middle
If you look at the site itself, each commenter
has a label next to them - like "hobbyist"

00:03:12.146 --> 00:03:17.446 align:middle
or "bigfoot fanatic" - that tells
us how active they are in the great

00:03:17.446 --> 00:03:21.146 align:middle
and noble quest of finding BigFoot.

00:03:21.146 --> 00:03:27.896 align:middle
Over in the Twig template, we get this text via
a custom Twig filter called user_activity_text.

00:03:27.896 --> 00:03:30.786 align:middle
If you're not familiar with Twig, no problem.

00:03:31.126 --> 00:03:34.396 align:middle
The important piece is that
whenever this filter code is hit,

00:03:34.706 --> 00:03:40.796 align:middle
a function inside src/Twig/AppExtension.php
is called...

00:03:41.266 --> 00:03:44.326 align:middle
it's this getUserActivityText() method.

00:03:45.266 --> 00:03:48.496 align:middle
This counts how many "recent"
comments this user has made...

00:03:48.836 --> 00:03:53.906 align:middle
and via our complex & proprietary
algorithm, it prints the correct label.

00:03:55.316 --> 00:03:59.786 align:middle
Back over in Blackfire, it told us
that the last call before Doctrine was

00:03:59.936 --> 00:04:05.826 align:middle
CommentHelper::countRecentCommentsForUser()
- that's this function call right here!

00:04:06.616 --> 00:04:10.326 align:middle
Let's go open that up - it's
in the src/Service directory.

00:04:11.186 --> 00:04:15.496 align:middle
Ah. If you don't use Doctrine,
you might not see the problem -

00:04:15.496 --> 00:04:19.446 align:middle
but it's one that can easily happen
no matter how you talk to a database.

00:04:20.206 --> 00:04:25.886 align:middle
Hold Command or Ctrl and click the
getComments() method to jump inside.

00:04:25.886 --> 00:04:32.456 align:middle
Here's the story: each User on our site has
a database relationship to the comment table:

00:04:32.906 --> 00:04:35.126 align:middle
every user can have many comments.

00:04:35.566 --> 00:04:40.446 align:middle
The way our code is written,
Doctrine is querying for all the data

00:04:40.636 --> 00:04:44.506 align:middle
for every comment that a User has ever made...

00:04:44.726 --> 00:04:51.156 align:middle
simply to then loop over them, and count how
many were created within the last 3 months.

00:04:51.156 --> 00:04:54.796 align:middle
It's a massively inefficient
way to get a simple count.

00:04:55.306 --> 00:04:57.676 align:middle
This is problem number one.

00:04:58.376 --> 00:05:00.426 align:middle
It seems obvious now that I'm looking at it.

00:05:00.796 --> 00:05:02.036 align:middle
But the nice thing is that...

00:05:02.266 --> 00:05:07.666 align:middle
it's not a huge deal that I did this wrong
originally - Blackfire points it out.

00:05:08.206 --> 00:05:13.176 align:middle
And not over-obsessing about performance
during development helps prevent

00:05:13.366 --> 00:05:14.746 align:middle
premature optimization.

00:05:14.856 --> 00:05:17.306 align:middle
So let's fix this performance bug.

00:05:18.216 --> 00:05:23.556 align:middle
Open up src/Repository/CommentRepository.php.

00:05:23.556 --> 00:05:28.096 align:middle
I've already created a function that will
use a direct COUNT query to get the number

00:05:28.096 --> 00:05:30.926 align:middle
of recent comments since a certain date.

00:05:31.626 --> 00:05:32.856 align:middle
Let's use this...

00:05:32.936 --> 00:05:35.146 align:middle
instead of my current, crazy logic.

00:05:36.096 --> 00:05:41.796 align:middle
To access CommentRepository inside CommentHelper
- this is a bit specific to Symfony -

00:05:42.386 --> 00:05:47.276 align:middle
create a public function
__construct() and autowire it

00:05:47.276 --> 00:05:51.206 align:middle
by adding a CommentRepository
$commentRepository argument.

00:05:52.146 --> 00:05:54.476 align:middle
Add a private $commentRepository property...

00:05:54.916 --> 00:06:00.636 align:middle
and set it in the constructor:
$this->commentRepository = $commentRepository.

00:06:01.686 --> 00:06:04.186 align:middle
Now... I don't need any of this logic.

00:06:04.866 --> 00:06:09.906 align:middle
Just return
$this->commentRepository->countForUser().

00:06:10.786 --> 00:06:11.986 align:middle
Pass this $user...

00:06:12.266 --> 00:06:18.056 align:middle
and go steal the DateTimeImmutable from
below and use that for the second argument.

00:06:18.766 --> 00:06:20.986 align:middle
Celebrate by killing the rest of the code.

00:06:20.986 --> 00:06:25.366 align:middle
If we've done a good job,
we will hopefully be calling

00:06:25.366 --> 00:06:30.946 align:middle
that UnitOfWork function many less
times - the 23 calls into Doctrine

00:06:30.946 --> 00:06:35.546 align:middle
from CommentHelper eventually caused
many, many things to be called.

00:06:36.196 --> 00:06:38.666 align:middle
So... let's profile this and see the result!

00:06:39.326 --> 00:06:42.736 align:middle
We'll do that next and use
Blackfire's "comparison" feature

00:06:43.036 --> 00:06:46.056 align:middle
to prove that this change was good...

00:06:46.416 --> 00:06:48.836 align:middle
except for one small surprise.