WEBVTT

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

00:00:00.786 --> 00:00:05.276 align:middle
Now that we've got our application in
production mode and we've dumped the autoloader,

00:00:05.596 --> 00:00:09.996 align:middle
it's easier to see what the biggest
performance problem is on this page:

00:00:09.996 --> 00:00:12.936 align:middle
https://bit.ly/sf-bf-profile4 And actually,

00:00:12.936 --> 00:00:15.246 align:middle
there might not be any more
problems worth solving.

00:00:15.786 --> 00:00:19.176 align:middle
I mean, it's loading in 104 milliseconds...

00:00:19.526 --> 00:00:22.536 align:middle
even with the Probe doing
all the profiling work.

00:00:23.206 --> 00:00:25.436 align:middle
But... let's see for sure.

00:00:26.046 --> 00:00:30.756 align:middle
The function with the highest exclusive
time now is PDOStatement::execute()...

00:00:31.166 --> 00:00:34.636 align:middle
which is a low-level function
that executes SQL queries.

00:00:34.636 --> 00:00:40.676 align:middle
If we hover over the query info, these
are only taking 12.5 milliseconds...

00:00:40.676 --> 00:00:44.656 align:middle
but we are making 43 SQL calls on this page.

00:00:45.586 --> 00:00:46.666 align:middle
Is that a problem?

00:00:47.126 --> 00:00:50.396 align:middle
It's not ideal, but is it worth fixing?

00:00:51.066 --> 00:00:53.596 align:middle
I guess it depends on how much you care...

00:00:53.846 --> 00:00:59.416 align:middle
and whether the fix would be easy or if it
would add a lot of complexity to our app.

00:01:00.566 --> 00:01:04.696 align:middle
When you're trying to identify where the
problem is, there are two ways to look

00:01:04.696 --> 00:01:08.786 align:middle
at the call graph - and I often do both
to help me understand what's going on.

00:01:08.886 --> 00:01:15.446 align:middle
First, you can read from top to bottom - trace
through your whole application flow to figure

00:01:15.446 --> 00:01:18.696 align:middle
out what's going on down the hot path.

00:01:18.696 --> 00:01:23.846 align:middle
Or, you can do the opposite: start at the
bottom - start where the problem is...

00:01:24.066 --> 00:01:27.016 align:middle
and trace up to find where your code starts.

00:01:33.226 --> 00:01:40.486 align:middle
Let's start from the top: handleRaw()
is the framework booting up...

00:01:40.826 --> 00:01:42.606 align:middle
and as we trace down...

00:01:43.106 --> 00:01:45.916 align:middle
it renders our controller,
renders our template...

00:01:46.266 --> 00:01:48.926 align:middle
and we're once again inside the body block.

00:01:49.766 --> 00:01:51.626 align:middle
This is really the same as last time!

00:01:52.326 --> 00:01:58.586 align:middle
Our AppExtension::getUserActivityText()
calls the countForUser() function 23 times.

00:01:59.136 --> 00:02:03.126 align:middle
That makes sense: we probably
have 23 comments on the page...

00:02:03.736 --> 00:02:08.826 align:middle
and for each comment, we need to count all
the author's comments to print out this label.

00:02:08.826 --> 00:02:14.876 align:middle
Before we think about if, and how we
might fix this, let's back up and look

00:02:14.876 --> 00:02:17.016 align:middle
at other dimensions of this profile.

00:02:18.236 --> 00:02:23.176 align:middle
In addition to wall time, we can
completely re-draw the call graph based

00:02:23.176 --> 00:02:26.606 align:middle
on only I/O time or CPU time.

00:02:27.346 --> 00:02:31.576 align:middle
Remember, wall time is I/O time + CPU time.

00:02:32.236 --> 00:02:37.796 align:middle
Or we could do something totally different: look
at which functions are using the most memory...

00:02:38.236 --> 00:02:40.696 align:middle
or even the most network bandwidth.

00:02:41.636 --> 00:02:45.636 align:middle
When we look at this in the network
dimension, PDOStatement::execute() -

00:02:45.986 --> 00:02:50.876 align:middle
the function that makes SQL calls
- shows up here as a big problem.

00:02:51.566 --> 00:02:55.946 align:middle
That's because SQL queries are
technically network requests.

00:02:56.096 --> 00:02:59.206 align:middle
Re-draw the call graph for
the I/O Wait time dimension.

00:03:00.126 --> 00:03:03.106 align:middle
We see the same problem here
because network calls -

00:03:03.436 --> 00:03:06.786 align:middle
and so SQL calls - are part of I/O wait time.

00:03:07.636 --> 00:03:12.156 align:middle
The point is: while "wall time" is
typically the most useful dimension,

00:03:12.556 --> 00:03:17.376 align:middle
don't forget about these other ones: they can
give us more information about what's going on.

00:03:18.436 --> 00:03:21.946 align:middle
Is a function slow because
of inefficient code inside?

00:03:22.236 --> 00:03:25.186 align:middle
Or is it, for example, because
of a network call?

00:03:26.106 --> 00:03:27.846 align:middle
Click back to I/O wait time -

00:03:27.846 --> 00:03:32.856 align:middle
PDOStatement::execute() is definitely
the issue according to this -

00:03:33.526 --> 00:03:35.356 align:middle
and the critical path is pretty clear.

00:03:36.026 --> 00:03:40.616 align:middle
This one function is taking
over half the I/O wait time...

00:03:41.166 --> 00:03:43.756 align:middle
but that's only 6 milliseconds.

00:03:44.306 --> 00:03:46.646 align:middle
Optimizing this might not be worth it...

00:03:46.896 --> 00:03:51.126 align:middle
but let's at least see if we can
figure out how to call it less times.

00:03:52.426 --> 00:03:57.636 align:middle
As we already discovered, the problem is
coming from CommentRepository::countForUser()

00:03:57.966 --> 00:04:02.166 align:middle
which is called by
AppExtension::getUserActivityText().

00:04:04.396 --> 00:04:14.656 align:middle
Over in src/Twig/AppExtension.php, each time
we render a comment, it calls countForUser()

00:04:15.006 --> 00:04:18.196 align:middle
and passes the User object
attached to this comment.

00:04:18.956 --> 00:04:20.286 align:middle
Can we optimize this?

00:04:20.926 --> 00:04:25.816 align:middle
Well... sometimes, the same
user will comment many times

00:04:25.816 --> 00:04:29.616 align:middle
on the same sighting - like this vborer user.

00:04:30.526 --> 00:04:36.956 align:middle
When that happens, we're making a query to
count that user's comments for every comment.

00:04:37.526 --> 00:04:38.746 align:middle
That's wasteful!

00:04:38.746 --> 00:04:42.646 align:middle
So here's one idea: leverage "property caching".

00:04:43.196 --> 00:04:47.836 align:middle
Basically, we'll keep track of
the "status" strings for each user

00:04:48.176 --> 00:04:53.236 align:middle
and use that to avoid calculating the
status more than once for a given user.

00:04:54.676 --> 00:05:00.096 align:middle
Start by moving most of the logic into a private
function called calculateUserActivityText():

00:05:01.766 --> 00:05:04.456 align:middle
this will have a User argument
and return a string.

00:05:09.416 --> 00:05:15.556 align:middle
Next, add a new property to the top of
the file: private $userStatuses = [].

00:05:15.556 --> 00:05:19.906 align:middle
Back in the public function, here's the magic:

00:05:20.356 --> 00:05:26.206 align:middle
if not
isset($this->userStatuses[$user->getId()]),

00:05:26.886 --> 00:05:27.696 align:middle
then set it

00:05:27.696 --> 00:05:37.136 align:middle
by saying $this->userStatuses[$user->getId()]
= $this->calculateUserActivityText($user).

00:05:38.426 --> 00:05:45.026 align:middle
At the bottom of the function, return
$this->userStatuses[$user->getId()].

00:05:46.426 --> 00:05:49.516 align:middle
This is one of my favorite performance tricks

00:05:49.706 --> 00:05:53.486 align:middle
because it has no downside,
except for some extra code.

00:05:53.486 --> 00:06:00.196 align:middle
If getUserActivityText() is called and
passed the same User multiple times

00:06:00.296 --> 00:06:03.526 align:middle
within a single request, we
won't duplicate any work.

00:06:03.636 --> 00:06:07.676 align:middle
So... we probably made our site faster, right?

00:06:07.676 --> 00:06:09.156 align:middle
Let's find out!

00:06:09.626 --> 00:06:14.516 align:middle
Since we're in Symfony's prod environment,
just to be safe, let's clear the cache:

00:06:14.516 --> 00:06:24.966 align:middle
php bin/console cache:clear and warm it up:
Back in the browser, refresh the page and...

00:06:25.276 --> 00:06:26.386 align:middle
let's profile!

00:06:28.956 --> 00:06:33.356 align:middle
I'll name this one [Recording]
show page try property caching.

00:06:36.716 --> 00:06:45.196 align:middle
View the call graph:
https://bit.ly/sf-bf-profile-prop-caching.

00:06:45.196 --> 00:06:47.096 align:middle
Ok - PDOStatement still looks
like a main problem...

00:06:47.096 --> 00:06:49.186 align:middle
but I think we're a little faster.

00:06:49.736 --> 00:06:50.236 align:middle
You know what?

00:06:50.336 --> 00:06:52.416 align:middle
Let's just compare the two profiles.

00:06:53.176 --> 00:06:56.716 align:middle
Go back to the dashboard and compare
the previous profile to this one.

00:07:00.376 --> 00:07:04.156 align:middle
https://bit.ly/sf-bf-compare-prop-caching.

00:07:04.296 --> 00:07:05.926 align:middle
I'll close the old profile.

00:07:05.926 --> 00:07:07.426 align:middle
Ok, so it did help - lower
time in each dimension...

00:07:07.426 --> 00:07:08.976 align:middle
and we saved 5 queries.

00:07:09.386 --> 00:07:11.286 align:middle
So, this is a win, right?

00:07:11.916 --> 00:07:16.946 align:middle
Maybe. If you profiled other Big
foot sighting pages, which I did,

00:07:17.316 --> 00:07:20.516 align:middle
you would find that this often did not help...

00:07:20.726 --> 00:07:22.876 align:middle
or helped very little.

00:07:22.876 --> 00:07:27.646 align:middle
In fact, this is the first time
I've seen it help nearly this much.

00:07:27.686 --> 00:07:32.426 align:middle
So, does the improvement justify
the added complexity in our code?

00:07:32.426 --> 00:07:38.036 align:middle
If we can repeat this 13%
improvement consistently, yea, it is.

00:07:38.336 --> 00:07:41.726 align:middle
But if it's more like 1%, probably not.

00:07:42.236 --> 00:07:45.626 align:middle
And even 13% is not that much...

00:07:45.816 --> 00:07:49.326 align:middle
and PDOStatement::execute()
is still the biggest problem.

00:07:49.936 --> 00:07:55.776 align:middle
I feel like the profile is trying to ask
us: is there a better way to optimize this?

00:07:56.656 --> 00:08:01.046 align:middle
Next, let's try another approach:
using a real cache layer.

00:08:01.806 --> 00:08:08.116 align:middle
Truly caching things has its own downside:
added complexity in your code and possibly -

00:08:08.206 --> 00:08:13.196 align:middle
depending on what you're caching - the
need to worry about invalidating cache.

00:08:13.826 --> 00:08:15.616 align:middle
We'll want to be sure it's worth it.