WEBVTT NOTE Created by CaptionSync from Automatic Sync Technologies www.automaticsync.com 00:00:01.126 --> 00:00:04.686 align:middle We just made Blackfire profile our first page. 00:00:05.456 --> 00:00:08.746 align:middle One of the best things about Blackfire is that, instead of just... 00:00:08.746 --> 00:00:14.166 align:middle giving me some raw data-dump and saying: Good luck navigating that black pit of data! 00:00:14.556 --> 00:00:19.586 align:middle ... they expose this treasure trove of info on their site with a beautiful interface. 00:00:20.366 --> 00:00:22.346 align:middle This is called the "call graph". 00:00:23.136 --> 00:00:28.066 align:middle The most challenging part of Blackfire for me was learning what all this stuff means... 00:00:28.186 --> 00:00:30.366 align:middle so I could really get the most out of it. 00:00:30.966 --> 00:00:36.206 align:middle If you stick with me for the next few minutes, your profiling game will get a huge boost. 00:00:36.866 --> 00:00:43.326 align:middle By the way, throughout the tutorial, I'll give you links to view the exact profile on Blackfire 00:00:43.326 --> 00:00:45.176 align:middle that I'm navigating in the video. 00:00:45.896 --> 00:00:47.926 align:middle Feel free to open it up and play around. 00:00:48.256 --> 00:00:54.656 align:middle The first one is here: http://bit.ly/sfcasts-bf-profile1. 00:00:54.656 --> 00:00:59.436 align:middle And yes, I know, the cool-looking graph in the middle is calling to us, 00:00:59.436 --> 00:01:02.386 align:middle but let's start by looking at the the left side: the list of function calls, 00:01:02.386 --> 00:01:07.356 align:middle ordered from the functions that took the longest to execute on top... 00:01:07.356 --> 00:01:10.536 align:middle down to the quickest on the bottom. 00:01:10.536 --> 00:01:15.546 align:middle Well actually, Blackfire "prunes" or "removes" function calls that took very little time... 00:01:15.546 --> 00:01:17.706 align:middle so you won't see everything here. 00:01:17.706 --> 00:01:19.876 align:middle The functions are ordered by "time" 00:01:19.876 --> 00:01:22.876 align:middle because we're viewing the call graph in the time "dimension". 00:01:23.706 --> 00:01:28.546 align:middle You can also look at all of this information ordered by several other dimensions - 00:01:28.916 --> 00:01:31.276 align:middle like which functions took the most memory. 00:01:31.916 --> 00:01:35.276 align:middle It's kind of like the process manager on your computer: 00:01:35.936 --> 00:01:40.776 align:middle you can see which applications are currently taking up the most CPU, the most memory, 00:01:40.996 --> 00:01:45.246 align:middle reading the most info from your disk or even using the most network. 00:01:45.816 --> 00:01:47.426 align:middle But more on these dimensions later. 00:01:48.396 --> 00:01:52.546 align:middle In the profiling world, time is called "wall time". 00:01:52.946 --> 00:01:57.976 align:middle But, it's nothing fancy: wall time is the difference between the time 00:01:57.976 --> 00:02:03.396 align:middle at which a function was entered and the time at which the function was left. 00:02:04.006 --> 00:02:07.376 align:middle So... wall time is a fancy word for... 00:02:07.436 --> 00:02:11.626 align:middle um... time: the amount of "time" a function took to run. 00:02:12.016 --> 00:02:17.606 align:middle So... we just find the function with the highest wall time and optimize it, right? 00:02:18.416 --> 00:02:21.996 align:middle Well... what if a function is taking a really long time... 00:02:22.106 --> 00:02:28.456 align:middle but actually, 99% of that time is due to a function that it calls. 00:02:29.296 --> 00:02:32.506 align:middle In that case, the other function is probably the problem. 00:02:33.466 --> 00:02:38.436 align:middle To help sort this all out, wall time is divided into two parts: 00:02:38.886 --> 00:02:42.006 align:middle exclusive time and inclusive time. 00:02:43.106 --> 00:02:45.786 align:middle If you hover over the red graph, you'll see this: 00:02:46.106 --> 00:02:52.856 align:middle exclusive time 37.9 milliseconds, inclusive time 101 milliseconds. 00:02:53.916 --> 00:02:58.186 align:middle Inclusive time is the full time it took for the function to execute. 00:02:58.716 --> 00:03:03.306 align:middle Exclusive time is more interesting: it's the time a function took 00:03:03.306 --> 00:03:11.966 align:middle to execute excluding the time spent inside other functions it called: it's a pure measurement 00:03:12.016 --> 00:03:16.066 align:middle of the time that the code inside this function took. 00:03:16.826 --> 00:03:21.076 align:middle Right now, we're actually ordering this list by exclusive time, 00:03:21.536 --> 00:03:24.496 align:middle because that usually shows you the biggest problems. 00:03:25.396 --> 00:03:27.646 align:middle You can also order by inclusive time... 00:03:27.856 --> 00:03:34.006 align:middle which is probably not very useful: the top item is where our script starts executing, 00:03:34.536 --> 00:03:37.066 align:middle the second is the next function call, and so on. 00:03:38.336 --> 00:03:39.636 align:middle Go back to exclusive. 00:03:40.676 --> 00:03:44.606 align:middle So apparently, the biggest problem, according to exclusive time, 00:03:44.776 --> 00:03:47.946 align:middle is this UnitOfWork::createEntity function... 00:03:48.196 --> 00:03:49.336 align:middle whatever that is. 00:03:49.886 --> 00:03:55.066 align:middle If you use Doctrine, you might know what this is - but let's pretend we have no idea. 00:03:55.996 --> 00:03:59.576 align:middle Before we dive further into the root cause behind this slow function, 00:03:59.796 --> 00:04:04.616 align:middle the other way to order the calls is by the number of times each is called. 00:04:05.096 --> 00:04:09.136 align:middle Wow! Apparently the function that's called the most times - 00:04:09.366 --> 00:04:14.196 align:middle over 6 thousand times - is ReflectionProperty::setValue. 00:04:14.576 --> 00:04:16.976 align:middle Huh. I wonder who calls that? 00:04:17.736 --> 00:04:19.336 align:middle Click to expand that function. 00:04:20.286 --> 00:04:21.736 align:middle I love this! 00:04:22.336 --> 00:04:28.496 align:middle Even though we're viewing the call graph in the "time" dimension, this gives us all the info 00:04:28.496 --> 00:04:35.696 align:middle about this function: the wall time, I/O wait time, CPU time, memory footprint and network. 00:04:36.426 --> 00:04:43.516 align:middle This isn't a particularly time consuming function - its wall time is 9.13 milliseconds. 00:04:44.166 --> 00:04:47.296 align:middle Wall time itself is broken down into two pieces, 00:04:47.436 --> 00:04:54.476 align:middle and this is important: wall time = I/O time + CPU time. 00:04:55.166 --> 00:05:01.846 align:middle There is nothing else: either a function is using CPU or it's doing some I/O operation, 00:05:02.126 --> 00:05:05.126 align:middle like talking to the filesystem or making network calls. 00:05:05.126 --> 00:05:11.206 align:middle In this case, the 9.13 milliseconds wall time is all CPU time. 00:05:12.056 --> 00:05:16.636 align:middle Okay, but who actually calls this function so many times? 00:05:17.356 --> 00:05:20.606 align:middle Above this, see those 3 down arrow buttons? 00:05:21.196 --> 00:05:27.106 align:middle These represent the three other functions that call this one - the size is relative 00:05:27.106 --> 00:05:29.566 align:middle to how many times each calls this. 00:05:30.356 --> 00:05:31.106 align:middle Click the first one. 00:05:32.346 --> 00:05:35.876 align:middle Ah ha! It's UnitOfWork::createEntity! 00:05:36.376 --> 00:05:44.206 align:middle That's the function with the highest exclusive time - it calls this function 4,959 times. 00:05:44.756 --> 00:05:46.046 align:middle Wow. So... 00:05:46.276 --> 00:05:48.056 align:middle it's definitely a problem. 00:05:48.966 --> 00:05:52.706 align:middle If you click the other two arrows, you can see the other two callers: 00:05:53.656 --> 00:06:00.006 align:middle one calls this 984 times and the other 216 times. 00:06:00.666 --> 00:06:01.776 align:middle Both are from Doctrine. 00:06:02.936 --> 00:06:07.736 align:middle Close all of this up and go back to ordering by the highest exclusive time. 00:06:09.026 --> 00:06:11.346 align:middle Open up UnitOfWork::createEntity(). 00:06:12.566 --> 00:06:17.416 align:middle As I mentioned, even though we're currently viewing the call graph in the "time" dimension, 00:06:17.666 --> 00:06:21.056 align:middle we can see all this function's dimensions right here. 00:06:21.616 --> 00:06:26.796 align:middle Hover over the time graph: even though the exclusive time is significant - 00:06:26.946 --> 00:06:32.066 align:middle 37.9 milliseconds - most of this function's time is still inclusive: 00:06:32.636 --> 00:06:35.826 align:middle it's taken up by other functions that it calls. 00:06:36.786 --> 00:06:41.416 align:middle That helps give us a hint as to if the problem is inside this function... 00:06:41.626 --> 00:06:43.876 align:middle or inside something it calls. 00:06:44.696 --> 00:06:47.876 align:middle And actually, every dimension has inclusive 00:06:47.876 --> 00:06:52.396 align:middle and exclusive measurements: like CPU time and even memory. 00:06:53.076 --> 00:07:00.076 align:middle If any of these had a high inclusive value - meaning some function it calls is really taking 00:07:00.076 --> 00:07:03.616 align:middle up that resource - you can see what functions it calls 00:07:03.896 --> 00:07:06.956 align:middle by clicking one of the arrow buttons below this. 00:07:07.906 --> 00:07:09.776 align:middle What I really want to know though is... 00:07:09.966 --> 00:07:13.396 align:middle what's happening in our code to cause this function - 00:07:13.616 --> 00:07:17.886 align:middle UnitOfWork::createEntity() - be called so many times? 00:07:19.296 --> 00:07:20.946 align:middle Click the biggest arrow above. 00:07:21.756 --> 00:07:26.436 align:middle Ah: ObjectHydrator::getEntity() is the main culprit. 00:07:26.906 --> 00:07:27.976 align:middle But... honestly... 00:07:28.296 --> 00:07:34.626 align:middle I don't know what that function is either: this is still way too low-level in Doctrine - 00:07:35.106 --> 00:07:37.446 align:middle I have no idea what's really going on. 00:07:38.026 --> 00:07:42.096 align:middle So next, let's use the call graph - the pretty diagram on the right - 00:07:42.396 --> 00:07:44.656 align:middle to get a full picture of what's happening going on... 00:07:44.886 --> 00:07:46.016 align:middle and how to fix it.