VISUAL BENCHMARKING in C++ (how to measure performance visually)

Key Takeaways

looking at data visually has always been so useful to us humans I mean numbers a great don't get me wrong but I've always understood more when it's laid out in front of me in some kind of visual format we've talked about benchmarking before about how we can use timers to see how long certain blocks of code take if you miss that video you can find it in the top right corner but today we're gonna be looking at something much better we're gonna take that data and look at it visually hey what's up guys my name is Jonah welcome back to my C++ series yeah okay you guys get the point so this videos gonna be a little bit different than the usual ones I just thought I would mix it up a little bit let me know what you think of this kind of format what we're gonna be talking about today is gonna be really simple any one of you could just take this and slap it into your own code and actually use it in a matter of minutes and the benefit that you're gonna get is huge I mean I'm like doing this kind of stuff in any kind of project that I'm working on the kind of long term that I'm gonna keep coming back to and when I care about the performance you know I've got a system like this running because being able to see so visually obviously just so so so important but before we get into that I just want to thank Skillshare for sponsoring this video Skillshare is an online learning community with thousands of classes covering dozens of creative and entrepreneurial skills with unlimited access to all of these classes if you sign up for a premium membership which is less than $10 per month it's really one of the best places on the internet that you can go to to learn just such a wide variety of stuff they just have so many classes on there anything from illustration graphic design how to make better videos how to make better websites animation how to shoot better photos classes on music production and even interior design I mean who wouldn't benefit by just making their space better if you haven't checked out Skillshare yet I encourage you guys to do so there's really no reason not to because there is a link in the description to a two-month free trial that should give you more than enough time to check it out see if you'd like it and learn something new and of course that link to two months of fries you're sharing membership is in the description below let's talk about profiling okay so here we have a blank super floss project this is just like whole sandbox that I like to play with you guys know me I like to start off with a completely blank project that way you get to see everything from scratch so the first thing I want to do is actually write some functions for us to profile there's nothing here to actually record the performance of we want to come up with something for us to actually test out so I'm just gonna write two functions they're not gonna be anything particularly exciting they're just gonna print stuff off into the console I'll stick a square root in one of them just for fun but there's this can be absolutely anything if you have your own program of course you're gonna already have all these functions this is just something that I'm creating just some dummy data for us to actually deal with so with these functions ready to go the next step is to see how long they take to execute I did a video recently about benchmarking in C++ I'll have it linked in the top right corner make sure that you check it out we're basically gonna steal the timer class from there and use it here and as you can see what I've done is I'm just printing the name of the timer along with how long it took in milliseconds so that we know how long our timer took using our timer is pretty straightforward it's a scope based timer which basically just means that we need to construct an object for it to start timeing and then upon disruption or in other words when the scope ends it will automatically stop and print our results to the console let's go ahead and run this program and see what we get okay so here we have the result function - took nine hundred and eighty-seven milliseconds and then we annoyingly have to scroll all the way back here to find function one which actually took more time at 1012 milliseconds cool so we can get results out of this timer it's pretty nice but obviously they are still just numbers and not only that but they are just really hard to find and it's just super annoying to go through your console looking for these numbers and then trying to make sense of how everything worked out enter visualisation will actually enter Google Chrome how many of you guess that we would be using Google Chrome to visualize our profiles so chrome actually comes with some profiling tools of its own amongst other development tools obviously for things like web apps or web pages and there's this particular one called chrome tracing and it's really bare bones really really simple it lets us visualize our profile in kind of a stack trace for you like this you just type in chrome colon four slash four slash tracing into your URL bar and then there you have it chrome tracing and because it's just part of chrome it's most likely already installed on your computer and ready to go so as you can see it looks pretty bare-bones and that's one of the things that I love about it the way that it works is it simply loads in a JSON file which has all of the data in it so our next step is to take all of that timing data that we're recording with our timer and put it into a JSON file in the format that chrome tracing expects and that's what we're gonna do now so back here in our code just above our timer class I've got this other class called instrumental and this is this is quite a simple class really all it's doing is just formatting a JSON file and writing it out into a file so we begin with this begin session function really all that is doing is opening a file and then writing a header which is just essentially the beginning of the JSON file that needs to be in a particular format for Chrome tracing and then the end session does a similar thing but it just writes out a simple footer closes the file does all that kind of stuff and we also have this concept of sessions which is really simple now right profile is the meat of this entire class this is what writes and individually timed profile so every time we run our timer this is what we want to output and you'll notice that at the end of this once it's output all the board's JSON into the output stream it actually flushes it the reason we want to do this every time we write a profile is because just in case our program crashes or we terminate it or whatever we don't want to lose all of our profiling data we want to kind of stream this into the file as we go along so that if anything like happens and we we can't end smoothly everything all that data is just safe and ready for us to actually use so I'm gonna go ahead and rename this into instrumentation timer just so that it's a little bit more clear about what it's used for because we're gonna add some code here in a minute that actually makes it like specifically use the instrumentum and by the way this concept of instrumentation is is going through our code and adding like these profiling times that's why all of this is to do with instrumentation so again the right profile function is exactly what we're looking for so I'm gonna grab that it uses profile result as a struct that just contains data such as the name the start and the end so I'm just gonna call that function here with the name the start and the end time point okay so the next thing that I'm going to do is scroll down to our main function and what we need to do is begin and end our sessions so what begins session actually does is it creates a new file with a given file name we're just relying on the default parameter here which is results dot JSON and then everything in between the begin session and end session gets put into that specific profiling file and this enables us to split up our profiling data into multiple files which as you can imagine can be quite useful for example in a game we might want a profile specifically the kind of loading screen or the startup section of our code but then when we're actually rendering and we're running kind of frame-to-frame and we've actually got the gameplay that's like a completely different ballgame altogether maybe we want to profile that separately and by having this concept of sessions we can we can do that as as much as we want alright so after just cleaning up our code and fixing some errors a little bit we have our running program you can see it doesn't output anything into the console anymore because it should all be going into our results JSON file so let's take a look at that if we open the containing folder go to our root directory here we have results our JSON file let's just drop that into visual studio to take a look at the text contents of this file so we have function one for example which is that name of the time we have the duration and then we also have the actual starting time point TS I'm assuming stands for timestamp and then we just have like an array of this and that is essentially all of the data that we need to give chrome tracing so now that we have this JSON file let's go ahead and drop it into chrome tracing and see what we get okay so check this out we have our profiling data visualized now we have function one function two but you can see that something's a little bit wrong on the timeline here it says 1000 microseconds and that's what the wall duration is down here as well one millisecond obviously this did not take one millisecond it took a thousand milliseconds so we're off by a factor of a thousand let's go back and see if we can fix that should be pretty simple if we just change our time point cast to cast into micro seconds instead of milliseconds and we should have our timing start and end data in the right format for chrome tracing let's rerun our program here to get some new data bit back into chrome tracing and now you can see where 2,000 milliseconds we've got the right kind of scale so this is really cool because obviously we can see all this stuff visually we have function one first then we run function two we can see how long it takes and of course as we saw earlier we can actually look at this in kind of like a stack trace format so let's go ahead and add another function I'll call it run benchmarks this will just call function 1 and function two but now since we have like another function up in the stack we should be able to visualize this as well I'll just print something out to the console like running benchmarks and then we'll stick that instrumentation timer into this function as well we'll have to give it a name of course which is getting a little bit annoying but we'll address that in a minute let's go ahead and run our code and see what we get you can see it's printing running benchmarks here at the top and if we get this new results like JSON file pop it into chrome tracing there you have it we have run benchmarks which calls function 1 followed by function 2 we can seal this visually and we can see the entire time of both of the benchmarks by looking at wall duration of run benchmarks so this is where she's getting somewhere now I like this this is getting visual it's really nice but unfortunately this run benchmarks having to just just copy and paste and then image the name of each function that we call it's getting a little bit annoying what can we do to fix this up additionally this kind of timing code is not something that we want to run all the time in our program there should be an easy way to shut all of this off because of course it does add some considerable overhead so we're gonna solve both of these problems by writing some macros I'm gonna define a macro here called profile scope which is gonna take your name as a parameter this is basically just going to wrap our instrumentation time a call will just concatenate the line number here just so that we can have a unique name for our variable in case we have a bunch of these in a row but we don't need the double hash here depending on which compiler you use I'm just going to use it to be safe we're just concatenated timer along with the line number here now we can replace our instrumentation timer calls with this profile scope macro and then finally I'm just gonna add a define here called profiling which will set to 1 if this is set to 1 then profiling is enabled which means we will actually have profile score brought our instrumentation timer and do all that stuff however if it's disabled you can see that we can just have it just be empty which means that it would replace profile scope with just no occurred at all which effectively just strips out that timer from any kind of build which has profiling set to zero so this is great but obviously doesn't fix our problem of what if I just introduced a new function like this run app function and then I want to profile the scope oh no I have to go back here and change my string to run app that just makes it a little bit more cumbersome and annoying can we do something about this yes of course we can I'm going to write a new macro called profile function no parameters for this one this is just gonna call profile scope but for the name it's gonna take in the name of the function which we can do using this compiler macro called function don't forget to include this into the else statement of your macro like I did and then you can replace profile scope with profile function all throughout your code and this is just going to be completely magical we can just run this and it will actually take the name of the function and set that as the name of the profile so if we drop this back into chrome tracing you can see that we have the same result as before we have run run benchmarks function one function two but this was not a string that we actually put in ourselves this was done by the preprocessor which is really cool however we kind of run into a problem here what if we have parameters and by that I mean specifically overloaded functions what if both of these functions are called print function they have the same function name but dead they have different safe inches so in other words we've added an int value here which just adds its value to I and then I have print function with that parameter being called which is one function and then the other function without a parameter being cold if I run this now and take a look at it they're both gonna be called print function because all that preprocessor function defined is doing is taking the actual name of the function which is print function and that's it but we actually want more information we want the savings check can we do that there's another one called func cig which is a function signature if we plug that in to our profiles go back and take a look at this then of course we'll get the entire function signature which is great now there is this calling convention that's part of the signature which we don't really care about but of course if you really wanted to just buy some string processing you could easily just strip that out before you put it into your JSON file okay awesome this is looking pretty good now you can take this profile function macro and just put it into like literally every single function of your program if you want to see what this looks like and if we were to like add a namespace such as like benchmark or something into here since we're using that func macro of course we'll get all of that information as well which is really cool and in case there are areas in your code that you want to profile that I'm not functions specifically you can seek that profile scorpion to any scope whatsoever you can make an empty scope if you need to and you'll see everything here so here we have that benchmark namespace is showing up awesome so the other cool thing that chrome tracing supports is multiple threads you can actually set a thread ID over here we're just setting it to zero in this example and then if you do that you can actually visualize all of your threads running concurrently which first of all is useful outside of profiling to just see what on earth is going on in your program that's one of the things that I love about this but then of course it makes timing in general and profiling a lot more powerful so let's go ahead and stick a thread ID into our structure here and then we'll also output that thread ID into our JSON file of course now we need to go to our stop function in our timer and see what thread the time was actually run on so that we can set up this thread ID and of course the C++ standard library makes it very difficult to actually retrieve the thread ID as an actual integer but since thread ID implements a hash function we can just use this little trick we'll pass our thread ID into that struct of course into right profile and then let's just go down here and change our benchmarks a little bit so they actually use multiple threads so that we can see this thread stuff in action I initially tried to use sed bind here but that ended up being way more trouble than it's worth because of course it's an overload of an identically named function and so you have to cast into anyway it just becomes a huge mess it's a lot easier to just use lambdas so I used that I also added in these two joins at the end of this function just so that we don't actually exit this run benchmark function until both of these threads have completed their work all right let's run our new multi-threaded benchmark which in general is not a good multi-threading test because of all the flushing that is pinging that is happening from the C out function but that's not the point of course our point is actually to see the crew tracing results and if we drop that in you can see we have three distinct threads that run benchmark one and then the two other threads that it kicks off I'm just gonna go back into the code and get rid of that B thread we really needed just that we can see the call stack from that initial run benchmarks thread which is just our main thread if we read on this program and then drop in that file there you have it so we have run benchmarks which actually calls the print function with no parameter by itself and then the integer one is spun off on a different thread and you can see how we can visualize that in chrome tracing which is super cool finally I just want to show you guys more of a real-world example of how you can use this so here I have a branch of the hazel engine that I wanted to profile I've split it up into three sessions startup run time and shutdown let's start by taking a look at the startup so this is pretty cool because you can see how long it takes your application to basically start up and here most the time is spent in loading and mesh so you can see the import is ready in the file and we have a few other things going on here that you could of course drill down and take more of a look at if for example it was just taking a little bit too long to load and you weren't sure so this is really cool because you get to see everything visually obviously the runtime is probably the most interesting one this is actually the application as it renders frame to frame so if you drill down you can actually see exactly how long a frame took so in this case about 1 and 1/2 milliseconds that is the duration of an entire frame you can see how it gets a bit broken down here into all the different parts for example it's really easy to see how long the layer update took compared to everything else so yeah that's pretty much it I think this stuff is super useful I'll have a link in the description below to some kind of like gist or something like that that'll contain the code that I used in this video the guys to try it out yourselves anyway I hope you guys enjoyed this video if you did please hit that like button I want to see you guys actually use this put it into your code give it a shot right now and just visualize everything that you're doing it's amazing because not only is it gonna help you benchmark you've heard and see what pastas slow a pasta sauce but if you're building something quite big this will let you kind of visually look at the code as it runs because as I mentioned like it's not just the timing it's not just like the actual daughter of ok this took 60 milliseconds this took 3 milliseconds this turbo but it's not just that that's interesting it's the actual structure of your entire code especially if you've got numerous threats being able to see something like that is is so so so useful so let me know what you thought of this in the comment section below hopefully it was useful to you guys don't forget to check out the free two months of Skillshare premium link in the description below and I'll see you guys next time goodbye [Music]