{"id":5433,"date":"2019-06-25T16:26:54","date_gmt":"2019-06-25T15:26:54","guid":{"rendered":"https:\/\/www.positech.co.uk\/cliffsblog\/?p=5433"},"modified":"2019-06-25T16:26:54","modified_gmt":"2019-06-25T15:26:54","slug":"starting-the-game-an-in-depth-profiling-look","status":"publish","type":"post","link":"https:\/\/www.positech.co.uk\/cliffsblog\/2019\/06\/25\/starting-the-game-an-in-depth-profiling-look\/","title":{"rendered":"Starting the game: An in depth profiling look"},"content":{"rendered":"\n

How long does your indie game take to start up? from clicking the icon to actually being able to take input at the main menu? Just for fun, I decided to analyze whats involved in doing so for mine.<\/p>\n\n\n\n

Because the aim here is to actually analyze the REAL impact, not the best case, I need to ensure that the game (Production Line<\/a>) is not just happily sat there all in RAM from a recent run-through, so it seems best to oh…maybe launch battlefield V beforehand (and quit it) just to populate disk\/RAM with a load of other stuff and do my best to evict all my games code.<\/p>\n\n\n\n

Then…its time to fire-up aqtime and take a look. I decided to do line-level, rather than just function-level analysis, which slows the game massively, taking 17 seconds to start (the reality is dramatically faster), but I can still do relative comparisons.<\/p>\n\n\n\n

First thing to notice is that pretty much the entire time is inside Game::InitApp() which makes sense.<\/p>\n\n\n\n

\"\"<\/figure>\n\n\n\n

Rather worryingly though, the vast majority appears to be inside SIM_Threadmanager::Initialise. That *may* be an artifact of aqtimes approach to thread profiling, but worth taking a look inside anyway… And it turns out that 100% of that time is inside SetThreadName() (which i only need for debugging anyway). This is a rare bit of code that I don’t understand well, and was from the evil interwebs:<\/p>\n\n\n\n

#pragma pack(push,8)\ntypedef struct tagTHREADNAME_INFO\n{\n\tDWORD dwType; \/\/ Must be 0x1000.\n\tLPCSTR szName; \/\/ Pointer to name (in user addr space).\n\tDWORD dwThreadID; \/\/ Thread ID (-1=caller thread).\n\tDWORD dwFlags; \/\/ Reserved for future use, must be zero.\n} THREADNAME_INFO;\n#pragma pack(pop)\n\nvoid SetThreadName(DWORD dwThreadID, char* threadName)\n{\n\tTHREADNAME_INFO info;\n\tinfo.dwType = 0x1000;\n\tinfo.szName = threadName;\n\tinfo.dwThreadID = dwThreadID;\n\tinfo.dwFlags = 0;\n\n\t__try\n\t{\n\t\tRaiseException(MS_VC_EXCEPTION, 0, sizeof(info) \/ sizeof(ULONG_PTR), \n(ULONG_PTR*)&info);\n\t}\n\t__except (EXCEPTION_EXECUTE_HANDLER)\n\t{\n\t\tvolatile int foo = 9;\n\t}\n}<\/code><\/pre>\n\n\n\n
<\/p>\n\n\n\n
The exception is basically ALL of the time. WTF? Apparently there is a less hacky way outlined here:  https:\/\/docs.microsoft.com\/en-us\/visualstudio\/debugger\/how-to-set-a-thread-name-in-native-code?view=vs-2019<\/a>  Which I will try later. I suspect the waiting for visual studios debugger is the cause of the problem.<\/p>\n\n\n\n
Anyway…onwards and upwards, so whats next? It basically all Init3D() (click to enlarge)<\/p>\n\n\n\n
\"\"<\/a><\/figure>\n\n\n\n
So basically my DirectX initialisation and the shadermanager stuff is most of the problem.  I suspect the DirectX initialisdation may be too black-boxed for me to influence further. The first big chunk is this line:<\/p>\n\n\n\n
PD3D9 = Direct3DCreate9(D3D_SDK_VERSION);    <\/code><\/pre>\n\n\n\n
<\/p>\n\n\n\n
Which takes up 34.74% of the start time. The next slow bit is  the largest at 41% which is:<\/p>\n\n\n\n
hr = PD3D9->CreateDevice( AdapterToUse, DeviceType, WindowHandle,\n D3DCREATE_SOFTWARE_VERTEXPROCESSING, &PresentParameters, &PDevice);    <\/code><\/pre>\n\n\n\n
<\/p>\n\n\n\n
So…holy crap. how can that line of code even be run? This can only happen if my checkcaps() code suggest the video card does not support hardware transform and lighting. I suspect some of the reporting here must be nonsense? Especially as my own debug logs suggest that the hardware TNL version is the one than ran… FFS :( lets look outside that code then…<\/p>\n\n\n\n
Most of the slowdown is in shader manager, which loads 11 shaders:<\/p>\n\n\n\n
\"\"<\/a><\/figure>\n\n\n\n
so it looks like about half the loading time here is actually spent writing out debug data! This is hard to avoid though, as I do find this data invaluable for detecting errors. And because an app can crash and lose all its data, I flush each line of my debug logs to disk with a hard drive flush on each line…<\/p>\n\n\n\n
\"\"<\/a><\/figure>\n\n\n\n
…so interestingly all the time seems to be inside OutputDebugString, which is only of any real use when the debugger is running. However! I *do* want to see that data in both release builds, and debug builds. Maybe I need a flag to tell if a debugger is present when the debug engine starts up? As a first pass I should at least build up a char* with the newline in to avoid twice the OutputDebugString calls. Here is the new code and timings.<\/p>\n\n\n\n
\"\"<\/a><\/figure>\n\n\n\n
Ooooh. I’ve halved the time of it. I’ve done the same with my non-directx debug code too. Now I’ll try changing that thread stuff… It turns out that SetThreadDescription is windows 10 only, so I need a different system (and apparently would need to update my platform SDK…urrrgh), so maybe best to just skip calling that code when no debugger is detected?<\/p>\n\n\n\n
This works (using isDebuggerPresent) but the profiler actually trips that flag too, so to set it work I needed to compare time stamps on debug files. Without the debugger, it looks like time from app start to menu ready is 0.395 seconds. With the debugger its…  0.532 seconds. <\/p>\n\n\n\n
That sounds pretty small, but actually I’m quite happy as I lost ZERO functionality, and the changes to the debug data will affect any time that data is written, not just during startup. 9Its not a lot, but there is *some*, and I’m an efficiency obsessive.<\/p>\n\n\n\n
I think I’ll put a clause around the debugengines OutputDebugString and nuke that unless IsDebuggerPresent() too :D<\/p>\n","protected":false},"excerpt":{"rendered":"
How long does your indie game take to start up? from clicking the icon to actually being able to take input at the main menu? Just for fun, I decided to analyze whats involved in doing so for mine. Because the aim here is to actually analyze the REAL impact, not the best case, I<\/p>\n
Continue Reading… Starting the game: An in depth profiling look<\/span>Continue Reading…<\/a><\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"footnotes":""},"categories":[129,4],"tags":[],"class_list":["post-5433","post","type-post","status-publish","format-standard","hentry","category-production-line","category-programming"],"_links":{"self":[{"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/posts\/5433","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/comments?post=5433"}],"version-history":[{"count":7,"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/posts\/5433\/revisions"}],"predecessor-version":[{"id":5445,"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/posts\/5433\/revisions\/5445"}],"wp:attachment":[{"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/media?parent=5433"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/categories?post=5433"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/www.positech.co.uk\/cliffsblog\/wp-json\/wp\/v2\/tags?post=5433"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}