hxScout Special! TLDR: A brief hxScout "tutorial" in the form of a walk-through of diagnosing a problem I ran intoOne thing I've noticed walking around in dark rooms is an annoying lag spike every 15 seconds or so. You can see it in the video I posted, around the 6:41 to 6:42 mark. There is a brief pause when Marika is mid-swing. It's not related to combat, but that is when it is most noticeable.
hxScout is a great tool for diagnosing these kinds of problems. So I thought this would be a good opportunity to demonstrate how to use it, what to look for, that sort of thing.
Setup and installation is already covered in other threads on the forum, but if you don't have it, here's what to do to get started.
Download
hxScout, then compile your game with telemetry enabled (it's in the advanced settings). You have to launch hxScout first, then your game.
When you launch hxScout, it begins listening for apps with telemetry enabled. When your game launches, you'll see a new hxScout session light up with a red box to indicate recording. You can stop recording at any time, or it'll stop automatically when the app closes.
At the very top of the screen is a timeline:
You'll notice part of it is highlighted (look at the right). The highlighted part is zoomed in within the larger window below it:
Each bar on the graph represents a frame. You can click on the bar to analyze the frame, or click and drag to highlight several frames. The total time of the frame(s) is shown on the right. You can see I highlighted the tall orange bar.
You want the bars to be short. Taller bars represent more time the game spent running computations. You can see on the right that one frame took a bit more than 2 seconds. 60 frames per second is the goal, so measuring seconds per frame is not good! But that's what we're going to fix
Time is spent doing one of three things: Rendering, Garbage Collection, and Active Time. Rendering is represented in green, and Active Time in light gray (although I think it's supposed to be blue?) Normally, most of the time is spent rendering, which is to be expected. You'll see below if I highlight some frames and look at the profiler, I get a breakdown of each function in the whole program (this includes your behaviors you wrote, the Stencyl engine, and everything Stencyl builds off of...Lime, OpenFL, etc.)
The two things to look out for are Self Time and Total Time. Self Time reports how long the computer took to execute that one particular function, where as Total Time reports how much time the computer spent on that function and all functions it calls. A good example would be if you have a behavior that does some stuff, then triggers an event. Total Time would include both the behavior and the triggered event, whereas Self Time would only include the code or blocks in that particular behavior.
What this means is if you're looking for inefficient code, you should pay attention to where Self Time is high. "High" is relative to how many frames you highlighted. I look for high percentages of total frame time. It is helpful to have an idea of how long code 'should' take to execute. If you highlight a lag spike (a tall bar) and you see a function with a high Self Time, there's a good chance that's where the offender lies.
The profiler gives you an expandable tree that has to be opened up pretty far before you get to functions you're likely to recognize. This will show the internal names, but they should be recognizable. When you make custom blocks, give them good internal names so they'll be recognizable.
You can see below I opened up the tree several levels. Usually you'll find what you're looking for below com.stencyl.engine.onUpdate--so I get in the habit of opening the tree up at least that far.
Behaviors you created are usually preceded by scripts.Design, which in my example is "Isometric Renderer". This is a scene behavior in my game that does what you'd probably expect: draw the isometric parts of the scene. The next line is VallasEngine.MDSUpdate, which is an extension block I made, and everything deeper is part of the extension.
This particular example isn't interesting because it's working well. At least on my system, I tend to get an FPS penalty just from using hxScout. High 40s and 50s reported on hxScout tends to be 60FPS without it, so nothing here to worry about.
Now, let's look at the offender orange bar.
Garbage Collection is an interesting problem to solve. For those of you who are unfamiliar with the term, Garbage Collection is the process of reclaiming memory that is no longer needed by whatever variable claimed it. Any time you create a new string, image, actor, whatever, it claims memory. In older languages, like C, when you were done with that variable you would then have to free the memory so it can be used again. A common problem was losing track of some variables and not freeing their memory. This would cause "memory leaks": memory that couldn't be reclaimed until the program terminated. Garbage Collection automates reclaiming memory so you don't have to manage it, but comes with the cost of not having control of when it runs.
Notice that besides Profiler, the frame can also be analyzed for Allocations (memory claimed), Collections (memory freed by Garbage Collection), Activities (just a text display version of the graph above), and Trace.
Time spent in Garbage Collection is represented in orange, so the culprit is quite obvious: the lag spike occurred when the system ran Garbage Collection, and there was so much garbage it froze the game while it was being dealt with. Opening the Collections tab reveals just how much.
So what is all this stuff? Some of it will be obvious (although not always obvious where it came from), whereas some might require some research. Dynamic is the Haxe equivalent of the "Anything" type attribute, and a lot of variables in Stencyl use it. Like with the profiler, you can expand the tree to get a sense of what functions claimed the memory that is now being reclaimed... like so:
Unfortunately, I don't really recognize most of what this is. I could do some research--and might end up needing it--but I usually start with the easiest things first. Just because you see multiple symptoms doesn't mean they come from multiple causes. Sometimes addressing the issues I immediately recognize also fixes the ones I don't, so I'll move on.
Fortunately, the next one is in code I wrote, so I know exactly what is going on.
ClipVertex is a class that represents a vertex in a polygon. I use them in a lot of places, but mostly to handle shadows. When a shadow is cast against a wall and onto another wall, it creates a polygonal shadow. This shadow is represented as a list of ClipVertex's. Indeed, expanding the tree reveals this code is where all of these ClipVertex's come from!
If you go back to the master timeline, there are 4 orange garbage collection cycles in quick succession. This occurs when the level is loading, so I'm not concerned. I start playing the game after that, and play for about 30 seconds or so. During this play test I just walked back and forth between two dark rooms really fast. In that time, 1.5 million ClipVertex's were created, and now they have to be disposed of.
The next biggest offender is Array. 1.3 million Array instances were created. (For those unaware, this is what Stencyl refers to as list attributes)
But if I expand it further, I see that the offender is related: arrays containing ClipVertex's. So two of the three big garbage offenders were clearly related, and I'm hoping the third is as well. Sometimes detective work is easier than research. I don't get lag spikes in lit rooms. Shadows are only cast when lights move, and other than in level creation, lights are only moved in dark rooms when the player's lamp is lit. So I'm suspecting the Dynamic garbage collection is related.
Now fixing the code--that's an entirely separate issue! Half the battle is identifying the problem, and I think after all this I have a good handle on where to focus my efforts.
One of the benefits of writing your own code is you have a much deeper knowledge of how things work than if you use someone else's. That's not to say you shouldn't use other people's behaviors. Noone really writes code "from scratch" anymore. If you write your own behaviors or extensions, they're still on top of Stencyl--and Stencyl is built on OpenFL, and OpenFL calls system libraries on your OS. But I would say that if you write code you intend others to use, give your functions clear names, and write organized code, so that the next person can easily figure out the architecture when they need to.
