Any way to extend Player.log and Player-prev.log to support arbitrary number of rolling log files?

Unity Engine
1

The player logs are obviously an incredibly helpful resource. But I often find that I miss out on some data because Unity only supports two copies of the log: The most recent/current log, and the one from the previous run of the game. I’d like to be able to support more than just the two levels.

First of all, why? Because I often find that by the time a player is reporting an issue to me, the log file containing the useful data is either already gone, or will be gone before the player can easily access the log file and send it to me. I realize there are cases where this sort of thing could balloon to using up a lot of disk space, but especially for test builds it would be helpful to be able to support an arbitrary number of “previous” logs, up to some limit.

So far I don’t see any simple/obvious way to do this, but I figured I’d ask before I try to roll my own log rotation mechanism.

1 Like
2

I do! :slight_smile:

The location of the log file is defined, so you have the path and filename.

You should get the user’s home directory part of the path from System.Environment and not construct it yourself.

Every time your app launches, you use System.IO to check if Player-Prev.log exists, and if it does, you rename it to include the timestamp (date + hh:mm:ss) like PlayerLog_2024-02-27-09-01-43.log.

You want to rename Player-Prev because at the time the app launches, because you’re interested only in keeping the previous log since the current log is for the current session.

Only thing you need to be careful with is DateTime.To(Long)String(). Don’t use those because the formatting may vary depending on locale, and may include characters that are illegal in the filesystem like slashes. Instead use DateTime.Now.Seconds and such.

1 Like
3

Yeah, I guess I’ll go with that approach. I kind of wanted to avoid it out of concern that I wasn’t sure exactly when Player.log got copied over to Player-prev.log, and I didn’t want to do my own rotation when the engine was doing the same thing, resulting in weird race conditions or file access issues. Hopefully by the time my first bootstrapper scene is loaded, it’s safe to proceed.

4

I’ve implemented rolling log files, with a directory size limit, and a size limit on each file that gets created while playing, but I did it by rolling my own solution to replace Unity’s log files because they don’t have very good performance.

5

Interesting to replace Unity’s logs with your own. Unity’s logging performance is pretty horrible, so I mostly only use it sparingly. I’d be curious if you’ve pinned down the underlying cause of the slowness, in order to address that in your own implementation?

6

I don’t really know what Unity is doing when writing logs. I’ve focused on my own solution from the start because I also just needed a persistent, rolling log file solution for work. I currently need to be able to pull log files from many different devices running iOS, Android, Windows, and Linux. If something happens on a particular device that is deployed in the field, I need to be able to go back and analyze what occurred at that time. I just know that when I was finished with my own solution it was definitely faster than what Unity is doing with LogStringToConsole.

9668180--1377113--Logs.png
9668180--1377113--Logs.png875×371 45.3 KB

In this benchmark I started with an empty project that just calls Debug.Log(“Hello world!”) a number of times that would cause it to max out at around 60FPS. That turned out to be around 200 log entries per frame in my test build. Those are the results you see on the left. Then I built the same app using my logger instead, and measured the results on the right. So, you can see for yourself the performance increase I was able to achieve. Debug.Log was allocating around 800kB of garbage memory every frame, but my solution doesn’t allocate any garbage.

So, rather than trying to explain what others are doing wrong, I can tell you what I am doing, that I consider to be right. Hopefully I can keep this long story short.

Issues

Garbage
Creating strings dynamically at run time is a potential source for a lot of garbage memory allocation, putting pressure on the garbage collector to clean it up later.

Allocation
Allocating memory for each new string has a significant impact on performance in and of itself.

StringBuilder Issues
StringBuilder is suggested as a way of mitigating allocations from string manipulation. However, when you append a number variable to a StringBuilder in Unity (as of 2021 & 2022) it calls number.ToString() which allocates garbage memory. Also, as I read through the source code of StringBuilder I felt that I could do better. I did not like that StringBuilder just allocates new character arrays internally as needed. I wanted something like StringBuilder that would never allocate garbage, even behind the scenes.

File Operations
In my testing I isolated the most costly operations when writing bytes to disk. Opening the FileStream is relatively costly, but once open, flushing the bytes is pretty fast. I was tempted at first toward asynchronous file operations, before I learned more about the subject, but I found that just having the file open and flushing bytes was much faster than any of the async FileStream methods (for writing, reading is a different story.) After all, this is a truly async operation, like sending packet bytes through a socket. “There is no thread,” to quote Stephen Cleary. So, “async” methods to push the bytes out the door are just wasting time in synchronizing back to your code to inform you that the operation finished, which you don’t need to know. The “synchronous” send methods are already asynchronous at the system level. The system doesn’t need anything more from you after being told to send, and the system will handle it outside of your application.

Solutions

Pooling
If you keep allocated memory around for re-use, you can avoid the costs that come with re-allocation and garbage collection. There is no free lunch, and this is the trade off. How did I achieve the win-win situation of drastically increased CPU performance and reduce memory allocation simultaneously? Memory pooling. If I need the memory, I need the memory, but I should recycle it, rather than throw it in the garbage dump. So, I basically made a system that I think of as “The Recycling Center” as an alternative to only relying on The Garbage Collector.

This could be a long story in and of itself, so I’ll try to be brief. The Roslyn .NET compiler uses an ArrayPool class for some internal operations, for all the same reasons I described. Developers have discovered the existence of this formerly clandestine helper class, and now it sees a lot of use by the public. I read through the source code for ArrayPool as well, and again, I just felt like I could do better. I’ll spare the details, but I am convinced that I did make a better ArrayPool. I use this underneath all of my custom collection classes to recycle internal memory. Some of those collections are themselves object pools that help me pool and recycle things like character arrays.

StringBuilder Alternative
I made a replacement for StringBuilder called StringMaker that uses shared memory pools to recycle a minimal amount of memory, only what is necessary for the required operations. When memory is no longer needed it gets recycled back into the shared pool, avoiding both allocation costs and GC pressure.

I’m actually glad that StringBuilder was flawed because it forced me to write my own code that translates the bits of simple data types like int and float into strings of human readable characters, which was an experience I value, in hindsight. In so doing, I realized that .NET code cannot render floating-point numbers accurately. I’m not sure if this will be surprising or expected at this point, but again I found myself dissatisfied with certain aspects of the Microsoft source code we all depend on.

Spans
Spans are amazing. I’ve considered making a public service announcement just to evangelize how great Spans are, versus how underutilized they seem to be. The .NET team has been spending a lot of time recently trying to convert all of their existing libraries over to using Spans wherever possible. Basically, you can define a Span around an array, and slice them up however you like. They allow you to allocate arrays on the stack quickly that disappear when you leave the method, no garbage involved. There are a bunch of subtle little ways they help you work with memory more efficiently, in a safe, intuitive way, that can help with things like avoiding garbage allocation.

Strings are implicitly converted to ReadOnlySpan, so I almost never define string as an argument type anymore in any of my methods. A ReadOnlySpan is much better because it can accept a string, a char array, or any other source of characters that can just stackalloc and copy into a local array of characters. This one type gives you so much more flexibility than working with string objects directly.

Benchmarks
In the process of developing all of this it became essential to test my own code and verify beyond any doubt that I was actually gaining performance. BenchmarkDotNet is an awesome tool that allows you to do just that. It’s gotten to the point that if I am going to do something new, I make a list of all the ways I could do it, I read any relevant source code, I benchmark every possible option, and I develop my own personal style around that which uses the most absolutely optimal algorithm. They say don’t early optimize and don’t use micro-optimizations, but maybe I’m the exception to that rule.

Bespoke Solutions & Quality Code
You asked why my solution has better performance, and the honest answer is micro-optimizations throughout the entire custom code base from top to bottom. I went to the drawing board, and any time I felt some bit of code wasn’t literally perfect I re-wrote it, including standard .NET System classes. However, it’s probably only been possible because I’m the odd developer who has been afforded years of well paid time to develop whatever I want, however I see fit. It’s the first time in my career that I’ve ever really had that opportunity, so I made sure not to waste it.

I’ve recently been re-writing a Unity server with MLAPI (the precursor to Netcode for GameObjects) to just be a pure C# app with raw UDP sockets. In so doing, I came across something that I think shows how much room for improvement there is left in the software development world, if we can just stop grinding toward new features long enough to go back and refine what we’ve already got. Here you can see that the .NET team only just recently added a way for C# to send a packet through the Socket class without spewing out garbage memory allocations for each packet sent. It squeaked into the .NET 8 release candidate. It was 2023, and C# added basic socket functionality without garbage just this past year. [API Proposal]: add overloads with SocketAddress to Socket's SendTo and ReceiveFrom · Issue #87397 · dotnet/runtime · GitHub

1 Like
7

That’s an impressive write-up, and quite interesting. Really cool set of tools you’ve developed. Thanks for sharing.

1 Like
8

Before you go ahead implementing your own logging solution, Unity actually has you covered with its own Logging package specifically made to fix many of the issues with Debug.Log. :wink:

1 Like
9

Debug.Log will:

  1. Resolve the stacktraces based on stacktrace setting in the project. Resolving native stacktraces in particular is slow if your project is configured that way;
  2. Flush the log file to disk.