How to make Unreal’s Message Log 100 times faster – Larst Of Us
Skip to content
Bluesky
Mastodon
RSS Feed
How to make Unreal’s Message Log 100 times faster
One of the quirks that Unreal beginners are often irritated by is the fact that the Unreal editor has not only one, but two log windows. The more commonly used one is called ‘Output Log’ and is what you’d expect from a log: A simple text display that usually looks something like this:
Technically, it’s a simple display of text (with some filter and search functionality), which is a good thing since the amount of log messages in Unreal can, depending on the project, reach massive sizes. Thanks to the rather simple text-form, this doesn’t cause performance issues, even with multiple thousands log messages per second.
But wait, wasn’t there a second log? You are right, let’s take a look at Unreal’s second log, called the ‘Message Log’:
This one is the fancy version, offering extra features like links to assets, or even to specific nodes inside of blueprints. If, for example, a blueprint of yours tries to access a non-existing object, the log will show an error message with a link to the specific node that tried to access it:
What’s the drawback of those features? The message log is MUCH less performant than the output log. While you can send thousands of messages to the output log per frame while maintaining a playable frame rate, this is NOT possible with the message log. For testing, I created a small blueprint throwing 100 blueprint runtime errors per frame:
Not exactly a great performance. While a slowdown is to be expected, a difference of an order of magnitude is not. Even stranger: The frametime impact isn’t that severe right from the start, the first 1-2 seconds are perfectly playable. But the frametime builds up over time and it does so at a rapid rate. The more log messages are created, the slower the editor becomes:
Profiling The Crime Scene
Something is deeply wrong here, so let’s grab our favourite profiler, and see what’s going on!
Finding the slow block in the profiling data is quite easy, since it’s basically the only thing you can see when zooming in:
AActor::Tick being that slow makes perfect sense, since the error is triggered inside of it, with the ProcessLocalScriptFunction being the interal C++-function that executes the blueprint tick. Now I just need to go further down the callstack until I find something unexpected:
At ‘FMessageLogListingViewModel::RefreshFilteredMessages’ my alarm bells start to ring. The code should just add a single message, but apparently multiple messages – note the plural – are "refreshed"? This doesn’t sound good, so let’s check the code:
Indeed, the function does what the name implies: It tosses all(!) messages that are currently shown in the Message Log (even de-allocating the memory while doing so), and then re-adds them all one-by-one, depending on the filter. To be fair, if somebody would ask me to write a refresh function I would probably write the same (except for the empty()-call in the first line – we’ll get to that).
The actual problem is that the whole list is rebuilt every time a new message is added, meaning the cost of every newly created message is increased by the number of messages created so far.
At the start, this isn’t a problem, the first message is created, and the list is refreshed. Since only one message exists, only one message needs to be added to the list at this point. Then, the second message gets added, and the list rebuild already needs to add two messages, making 3 overall so far. The third one adds another 3 messages (six overall), etc.
Because of that, even though we only log 100 messages, 5050 messages are added to the list in our first frame alone. Since the message list is persistent between frames, this continues to add up: During the second frame, it will be 10050, then 25050, 35050, 45050, etc.<br>During frame 200, the refresh will need to add around two million messages! This actually matches the linear increase in the frame time perfectly:
So we figured out why this is slow, how can we speed things up? There are angles from which we can tackle this.
Starting with the small stuff
The first optimization that I did was to change the already mentioned emptying of the messages list. In the original version, the elements are not only removed from the list, but the array is also resized to 0 afterwards to free up memory. This sounds nice at first, since we could use this memory for other stuff elsewhere, but since we re-add all the messages right afterwards there is no need to waste time on slowly de-allocating memory. So let’s change the call to not affect memory allocation:
In my very short test this saved already multiple milliseconds, but I admittedly didn’t profile that change in great detail, we have a bigger fish to fry.
Skip unnecessary refreshes
One of the frustrating parts about the current behavior is how often the same list is...