WWDC2004 Session 307

Transcript

Kind: captions Language: en ladies and gentlemen please welcome performance engineer nathan slingerland right yeah good afternoon welcome to God shark so here's what we want to talk about today obviously we're here to to talk about the big shark so we want to introduce shark to you if you haven't used it yet all right for those of you haven't had a chance to run it we want to go over the basics show you how simple it is to use and for those of you who are longtime shark experts we want to want to show you all the great new features we've gotten shark for so and then of course if you've seen you may some of you may have seen the demo on Monday in the devtools keynote we want to go a lot more in depth with with what we did there to optimize celestia using shark so let's go so what is shark well it's been called apples best kept secret but not anymore starting this year we you know in this year's WWDC we've had a big push for this and we want you all to know that this is a great way to find and fix your performance problems so what is shark well it's a really easy to use profiling tool there's a GUI version as well as the command line version the command line version is very useful for scripting performance regression testing so you can you can archive your performance analysis for later review it see how you've made progress as you continually optimize your application and public beta is available on the web today of shark for and chud for and off this website off the developer tools website and it runs on Panther and tiger so that means yes you can use it on your development machines right now right and of course we support basically any kind of executable Makos CFM compatible with all the compilers that you can use in Mac OS 10 X 10 debug format stabs format so whatever you can throw at it shark and show you what's going on all right so so let's see how easy it is right what do you do to get started with shark it's just one click there's just this main window with one button start and stop I mean this is the typical way that you you start profiling and stop it with shark and you're on your way by default we selected time profile but if we also supply a rich set of other preset configurations you can also create your own configurations for doing customized performance analysis and by default we're going to profile the entire system but some profiling configs for up to make more sense to target a specific process so for example Malik tracing which we'll talk more about later you want to pick a target process or static analysis you want to pick a particular executable file sent to look at but for the most part you don't even need to go here you can just click the start button and go so once you've selected your your configuration or just left it at the default probably you're going to do a time profile right so what is that this is the most common workflow basically your time is it's just it's just like optimizing application performance you want to spend your time where you can affect application performance the most so that's what ever functions take the most wall clock time or whatever pieces of your code are taking the most wall clock time so we're using for time profile this is a statistical form of sampling and we're taking by default a thousand samples per second and each sample contains you know back-trace so how you got to a particular location in your code which process which thread and Sarah so all this information and we collect that and when we combine it we can create a profile so this is going to show you over the sampling period where you were spending time in a given process or thread or overall in the system and we're capturing everything so this includes the driver any drivers any kernel code that you're this executing applications so no matter what kind of developer you are this can help you profile your code and we're able to do this because we have also have a kernel extension right so we're sitting in the kernel capturing these these samples and this gives us very low overhead we really don't perturb the code on the system hardly at all so once you've got a profile you've hit start you hit stop and you run whatever it is you're interested in you're presented with this by default the heavy view and this is really the bottom line this is showing you starting from the top the most sampled to the least sampled function in the in the selected process by default we select the heaviest process on the system so a lot most of the time this is your code this is your application that you're trying to look at so that should you were the heavy view showed you where the hotspots are the tree view is going to show you where the hot code paths are so how did you get to those important functions right so that's just this tree button here at the bottom and new in shark for heavy entry simultaneously so you can you can use one to help you navigate the other so those are two ways we use very commonly to look at high-level problems in our code the third way is the enhanced chart view so this chart view has been there a while but it's been greatly enhanced in shark for basically what we're looking at is call stack depth that's on the y-axis versus time and the x axis and this can give you a really good idea of a couple things first of all I can show you patterns in your in your code right so patterns in the execution of your code and this can be good to look for repetitive behavior and we'll talk about more about that later in relation to malloc tracing and function tracing which we'll get to it also is a good way to look for you know if you feel thin narrow spikes in this call in this chart view that usually indicates that you're spending a lot of time and function call overhead right because you had to call many level money function levels deep but you did not actually doing all that much work once you get there so this can be you know we see this a lot in object-oriented modern you know layered code where we just we have everything hidden in layers and so sometimes I can hurt performance so for the colors here blue is the user space if you may see there are a few maroon colored stacks those are colonel and the yellow call stack is what's selected so that's what's being shown at the the right hand side there is the current call stack lightness doesn't mean anything except for layers so it's just indicating as you see these gradients in color each each color change is indicating a new function right vertically so those are the three main tools right that shark is providing for looking at your application but you know a lot of you probably are working on some pretty sophisticated code bases and you have some complex function call behavior and you really would like to you know you want to understand the performance of that application so shark for has introduced a lot of new features that are trying to help with high level analysis and understanding these more complex application architectures the first is is this color by library and what this is going to do is just going to color each different module that your program is using different frameworks or libraries a different color and it remembers the color inconsistent between the different views and this is an easy really quick visual way to see the difference between the modules or visually to see where you're spending time in what modules okay so another common problem you probably will see in your code is this is a tree view and you may see that you you have this important intermediate function this interior function for example be in this example and it's you'd like you see it in two different spots in the tree all right and you'd really like to know how much time total is being spent in B and its children right because we tend to subdivide work so in this example we have be calling c1 c2 and c3 and not a whole lot of time is being spent in and be itself so what we've added is a canonical view and if you select that we're going to see not just you know in the tree of you normally we see main calls flu calls bar well in this case we're going to see all the symbols all the interior symbols every symbol that shows up and it's total contribution right so in this case B and what it calls total up to 100 at the time where you're being spent so this is a good way to understand how much time you're spending in a function and its children so that kind of raises this question right traditional profiling tools tend to look at performance just like the same way that the program is broken down into functions right and that works pretty well when you have a few functions where you spend a lot of time we're in a few heavy function but if you have just a lot of functions in your code you've subdivided the work a lot and you're reusing code everywhere or your you spending a lot of time in system libraries that really isn't the best presentation and that's what data mining allows you to do it's going to allow you to customize how you're looking at a profile and by customizing it you can help ease your understanding of it right so shark provides a couple of basic data mining operations the first is exclude similar library and what this is going to do it's going to hide a similar library that you select and so we're not just taking the sample doubt it's important to remember this we're not just removing these samples right so if you hide the function foo any samples that landed in foo or just being assigned to whatever called it right so if you have a piece of code that call square root for example and you hide you exclude square root it's going to just assign the time to that function your function right and really that's a lot easier for a lot of us to understand is time spent in our code right because we can't do a lot about system libraries typically so along those same lines is flattened library we you know we are familiar with the pieces of app kit or core foundation or the other system libraries that we call right those function entry points but a lot of times you'll see interior functions inside of those libraries that you really don't know much about and you really don't care much about right about the implementation interior to that so flattened library is going to do that it's going to hide everything inside of a library except for the entry point so you're going to just see all the time it show up in the entry point which is what you understand right because that's what you called from your code I finally focused symbol if you typically navigate very deep call trees or if you just you you know you have a certain symbol that you only want to look at and what it calls that's what focus does it's going to just start the display of the the various call path from that symbol so these are different ways to really to customize how you're looking at the profile and internally in Apple we've found this very helpful in looking at performance analysis for tiger so those are the detailed data mining operations there are more macro level off up operations that are also eat very useful flatten recursion so you've probably seen this if you've ever looked at you know a piece of a piece of code you've seen a recursive call may be in you know NS view or some other even your own code and really that's not the most informative way to look at a piece of function right that's recursive function you'll actually like to see all those recursive calls collapsed into one and see all the time together and what all the recursive calls actually do collapse together so the flattened recursion check box is in the this advanced settings drawer that we've been looking at and you check this check box and all the recursive calls anywhere in the profile just get collapse to one so we talked about flatten a single library this will this flattened system libraries will slide in all of the system libraries that occur in the profile this is a really quick way to hide all that interior code that you don't really you don't really want to see and so another very useful and is exclude entries without source info usually when you're working on an application in your system you've turned on debugging information because you want to see symbols and shark and you want to get all the source information well the good news is that that's almost the only thing in the system with that information in it so if you exclude everything without that information you're going to only see your code it's going to perform that exclude operation on any symbol that doesn't have source information associated with it so this again this will just focus in on what you know on your source code so you know I encourage you to play with all these different officer up operations and you'll see very quickly what they do and how they can help you finally exclude supervisor you know a lot of us are very familiar with the colonel and what is doing inside and you know how did I get these for these red samples and Mike in my profile this is just a quick way to get rid of those samples and you know keep them from being a distraction while you're looking at your code okay so those are the high-level optimization tools that shark provides once you you've kind of gotten those out of the way you should you should be able to at least understand your code at a level where you want to optimize a specific function right so that's where we're shark shines for function level optimization right the most basic thing that shark does for you as it shows you your source code if you double-click on any symbol on those profile views that we talked about heavier tree it's going to show the source code and what it's doing here it's coloring the source according to how many samples landed on a particular source line so the brighter the yellow the more samples landed there that's a really quick visual way to see where you're spending time in your source and you also note that along the in the scrollbar it the coloring in the background of the scrollbar matches the coloring in the background of the table so this is a really very easy way to navigate you know quickly between hot spots in your code and finally you know to make the the profile and optimization cycle complete there's an edit button and this is going to show your source code inside of Xcode it's going to bring you back to Xcode so the typical optimization cycle right you you profile the shark you go to the code browser you see a problem you go you click Edit go back to Xcode recompile and so on so it's this iterative process where you continually go back and optimize again and again until you're happy with the code another great thing that shark will do for you is it will provide you with optimization tips so if you see one of these exclamation points and you're in the code browser and your code that means shark has a tip for you hook so it has an idea about what might be wrong or why you might be spending extra time on that particular line of source it so if you click on the on the ! it'll bring up this help balloon and finally in shark for we've added this ability to look at both source and assembly side by side right so now rather than having to jump back and forth or try and figure out how the you know what the compiler generated for a particular line of source code when you navigate around in the source viewer you'll see very quickly okay you know the highlighted line if you select here we have a line of source selected on the left and there are maybe three or four instructions there that are selected on the right and those are the instructions that go with that source wine so this is a real quick way to see what instructions were being generated okay well that's great but I don't know any PowerPC assembly well here you go right there's this online help you can you know it will follow along as you navigate through the assembly and it'll tell you in English you know here's what this instruction does and you know assembly languages just like any other programming languages has these simple operations and you can read about it here in this online help guide right so that's time profiling those are the tools that we use the time profiling right when you but you'll see that we also use these same tools over and over but with more sophisticated types of profiling which shark also provides some shark for we've added mallet racing and what this is doing is every time you an allocation happens in a target program it's going to take a sample it's going to remember the call stack and also how much memory was allocated so it's not shown here but there's also you can look at this in the profile view and say okay this function over the sampling run time allocated this much memory and that's useful for tracking down you know overall how much memory was allocated in various function but another interesting thing to do is to use the chart view to see patterns in the program behavior because this is not a statistical profile this is an exact trace of the malloc function and most interesting program behavior does some sort of allocation you can see patterns in your in your code in the execution of your code so here what we're looking at this is the dock as we mouse over and it kind of magnifies different icons or probably this we're looking at three icons here right and so you can see this repeated behavior sometimes in like in the case of the doc well maybe we expect that we expect repetition but this can also be a good clue is when you're doing extra operations that aren't me if necessary right so mallet racing is is a it's more general than just looking at where memory with allocated and a more general form of Malik tracing its function tracing so rather than just tracing the allocation functions in your code you can trace any functions in your code and again this is an exact trace so there are some predefined presets for 500 api's typical Network api's locking api's but you can also add your own functions right so if you do if you have a set of functions that you want to watch in your code and you want to measure exact function count and then the amount of time that the function took this is a great way to do it you can you just attach to your function or attach to your application and select the functions that you want to watch and this is in you know this is measuring each function calls time very accurately with the PowerPC DEKRA manner but without having to write any instrumentation code in your application the finally event profiling so if you are you long time shark users this you know we've had this for a while but this is also a very good way to correlate hardware and operating system events so things like cache misses and the hardware or virtual memory faults in the operating system with your code all right so here in this example we have l1 and l2 data cache misses but we're profiling a you know event profiling along with our normal time profile and so we see two columns have been added to the profile each of those counts l1 and l2 cache misses and also in the chart view we can see there's a chart above so you can track the l2 cache miss over time how much how is that changing over time in your application so and there are literally hundreds and hundreds of these performance events available finally in shark for java profiling so everything that you could do with you know CFM and ma co applications is also available for java now time and allocation tracing function tracing and it's going to show if you double-click on the Java function and source codes available it's going to show you the Java source in a code browser so oh you also you know those are the kind of the built-in configurations that we've been talking about you can create your own right using this configuration editor and you know one of the hard things that was there was in shark 3 was finding where performance counter events lived right so which pnc which performance monitor counter there's an event that counts cache misses live on well you'd have to either go to the processor user guide and look it up or you you would you know you just kind of blindly search around well now there's a text search for the performance event so you can type in cache miss or cash and it will come up with a list of which PMC's have an event that would that substring in it okay and in shark for we also added network profiling this is using rendezvous you can set up you know your your ex serve in your closet or you know you have a HP see cluster and you want to monitor what's going on in that machine that doesn't have a monitor and a mouse in front of it in the keyboard well this will let you monitor one or more of those machines that you set that up on so you don't have to sit in front of this machine you just go out it works very similar to X codes distributed build you know pick them as target machines and hit start and stop on your client machine and so let's let's have a demo with that can we switch to the demo machine please great alright so over here I have a machine this is Sanjay's machine it's running some code on it but all on shark here right and I'll go to the the network profiling window I'll say control network profiling of shared computers and there we can say you know somebody has shared this w WC 6 ok let's use that and it's it's running something over there let's hit start so again sharks very simple just hit the start button stop and now we're processing on the other machine here and this is the this is a profile taken from this machine so we can see oh that's what's the left yet well I wonder what that is maybe yeah Honda can tell us so Sanjay Patel that's can we have you come up here and explain it thanks so for those of you here on Monday you probably saw our celestia demo we'd like to show you a few more details about how we optimize that code so if we go back to slides for just a second hello ok they're back ok so Celestia is this open source program we found on the web and it's really cool it's a 3d space simulation of all the large bodies in the universe for more information you can check them out on this web link they actually use real data from Pasadena down at JPL to calculate where the planets and the stars are how they're orbiting so let's go back to the demo machine and so this is celeste use main window you can see it's hovering around the earth right now and we wanted to find out how this thing performs on Mac os10 so the first thing you have to do if you're going to try to optimize performance is put down a good metric in our case that would be how long it takes using a timer as you can see in the corner to run our art script and so right now we're running in timing so we can bring up shark and you can see as Nathan said shark is pretty simple there's a start button in the middle here we can choose our configuration but by default most of us are going to use the time profile let's just hit the start button so right now we're actually taking a thousand samples per second of whatever is running on the system beyond just Celestia if you hit stop shark is now processing the samples it took and it's going to show us by default what we call the heavy view so this is a list in order of importance of these functions that actually ran on this system now at the bottom here you can see so let's just taking up less than half of the processor cycles and if you pop that open you notice that the first thing is the mock colonel so new for shark for we actually filter out the idol thread so you won't pop there by default thanks for old shark fan and you might wonder why is Celeste you're getting less than half the CPU cycles on this system if you pop open the thread pops up you'll see that it's a single threaded app so we're running on a dual g5 it can't possibly take all of the seats you cycles on the machine now another way to look at this code is as Nathan mentioned we have a 3 view so this is the traditional top-down view of code so you start at start or main and you work your way down to the leaves of the function this is great for understanding the structure of your code how did you get there and new for shark floor we can do both heavy entry simultaneously so you can get a really good feel for the behavior of your program and of course it's Nathan mentioned we have the new chart view so this is interesting we have a dual processor system so we get two charts and on the x-axis we have time for each CPU now we know that celestia is a single threaded program so let's just look at it's one thread in one chart and new for sharp for we have this zoom slider this is a big upgrade compared to previous zooming and you can go back and forth the nice part is if you click on one of these call stacks you'll get the back traits for that point in time so you can see chronologically how your program behaves over time and you'll notice that there are some of these maroon or red samples those are calls into supervisor space and one thing I noticed was for the Celestia profile we had a lot of these calls into the supervisor space it turns out we're trying to draw about a thousand times per second and for those of us who are familiar with graphics applications you don't really need to try to draw that often because you can't so we limited it to 30 frames per second and that's what i call warp 2 we can go to that you can see things have sped up immensely by not doing all that work of trying to draw too often we can also go to this writing model which would be work three so it turns out you can do drawing in parallel with some of the computations for orbits and we can take another sample here and see how r s profile is changed so i'll put on my hardware hat for a second and say the threading is probably the most important thing you guys can do if you have any serious computation going on in your programs because no matter what architecture we're talking about we're going to end up being multi-core multiprocessor multi-threaded multi something so if you're not taking advantage of that parallel ISM in Hardware you're going to lose out but now we can see if we compare the first session to our second session you'll notice that it's very different on the first session we have this call to log it's at the top but now that we've limited drawing and done threading we have a totally different profile so this brings up an important point you shouldn't try to micro optimize right off the bat you should look for some high-level problems to figure out what your code is actually doing before you start diving into function level tuning but now we have a new profile and you'll see that cosine from libsystem is actually at the top of the chart and there's not much we can do about cosine but we should figure out who's calling cosine so if you open up a disclosure triangle you can see our main color is this orbit function now new and shark for we have what we call data mining operations and as Nathan mentioned if we want to hide say whole library for example libsystem we can just exclude and now all of the samples that used to be in co-signer attributed to its callers so you see our orbit function is now at the top of the chart and of course if you double-click you get your source code and it's highlighted according to hotspot you can see in this function almost all the time is going into one line calling cosine and of course it's a for loop what we should do is open up Xcode and see what we can do about that so you just hit the edit button okay and you can see we're calling cosine in a loop and we're actually just iterating over a whole array of data and getting the cosine of each value now new and tiger in the accelerate framework there just happens to be a cosine function that does that it just iterates over an entire array and if we jump over to that line you can see i just made a call here it's called V V cosine app that's available on tiger and what it does is it just takes an entire array operates cosine across the whole path and gives you a return array so we made that optimization we call that warped for and you'll see we took about 20 seconds to run through the demo before while we were threaded in limiting drawing using the accelerate framework we doubled the performance but there is a downside I kind of cheated that cosine function is single precision and the inputs and outputs in Celestia were double precision so I didn't want to cause any kind of astronomical catastrophe or global warming or anything so we decided we'll do our own cosine approximation function in double precision and I called that warp 5 and it end up being a little slower than just calling it a V force oops lost something there and then we also went to warp 6 which was a known unrolling of Maya code and that's important just unrolling one loop in this program bought us another thirty percent and what we'll end up with is performance that's on par with with the accelerate framework but it has a higher precision because i'm doing a higher precision estimate of cosine so let's take one more profile and figure out what our code is doing after we've made these optimizations so this is performance tuning of course it's an iterative process again you can see the profile has changed cosines no longer there we have our approximation function on top and what I want to do is take a look at this function called bigfix it's a C++ constructor and you look here and you say whoa shark is angry about something it's got a lot of what we call the call-outs there and if you you click on one of those you get some friendly advice or not so friendly advice depending on how bad your code was in this case we're doing type conversions from floating point in so this is one of the big bottle necks of for a g5 or even a g4 processor and what we want to do is try to optimize that but let's take a look at what the compiler generates underneath this code so we can now look at source and assembly side by side and of course we're trying to sell those big monitors this looks really great on 30 inch now the really nice part here is you can see Nathan scrolling around and for each line of source we're actually in sync with the as imbue so that's going to pop as you scroll around in the source so you can see exactly which lines of Adam correspond to which lines of source okay now if we just want to look at azum and don't really understand Adam then we have this new handy PPC Help button as Nathan showed and the cool part here is as you click on your azum the right page of the manual pops open with you so lots of information right at your fingertips you don't have to go fumbling around for manuals that's a pretty big improvement for someone like me and of course if you're really tuning for g5 or powerpc 970 we have this extra help here if we click this show dispatch groups your source will now be highlighted according to dispatch groups for the g5 so for those of you familiar with the g5 architecture you can actually tune down to the hardware the other nice feature is this 970 details drawer and if you highlight code you can see dynamically we're updating the charts at the bottom so you can see where every as of instruction is going so on the Left we have the functional units and on the right we have the dispatch slots so for those of you who really want to tune this is great stuff okay so let's go back to Celestia yeah so over a period of about two weeks or so with a lot of interruptions doing real work I spent I used shark to try to optimize this code so i ended up writing some altivec code i did some scheduling for the g5 i did some g five specific optimization and the some results of that is what i call warp nine and if we run through that see that we finish in about five seconds so that was pretty good now this is open source I'm going to return this all of course to the authors and post it on the web so you guys can have a crack at it too if you like it's a really cool program if we go back to our slides now here's the result of a couple of weeks of tuning effort we started out and if you run this demo as is it'll take over 20 25 minutes on a g5 and when we were done of course we got 25 seconds so around 300 times the performance so that was pretty nice so let's just summarize what we've talked about today the things we really want to say are as you can see hopefully that it's a really quick process to start using shark you don't have to do any kind of hardcore profiling you can take your optimized binary and simply profile that in order to see your source all you have to do is add the dash G flex they don't strip out your debugging symbols and of course we provide a lot of high-level views so if you're used to trees you can see it in tree view you can use the heavy view you can look at your code over time is a chart and of course once you've identified functions that are hot spots you want to source you want to tune the source code or tune the assembly and let shark give the optimization tips and of course now with new new and shark for we have the advanced profiling with so things like tracing malik's tracing specific functions or tracing specific system events like cache misses or page faults and of course hopefully you can tell shark we've tried really hard to make easy there's no magic here you just push the start button and that should get you going but there is a lot of machinery underneath here that makes it powerful enough or even the most expert users who want to tune all the way down to the metal so it's great for what we call high level or elder its algorithm 'ok analysis as well as low level tuning or hacking and we're compatible with codewarrior GCC xlc XLF snag whatever you've got we should be able to support you and the best part sharks available for free and it's available right now [Applause]