Log not buffering multiple lines due to AutoFlush #19029
Comments
|
IIRC the current setup was motivated by making sure that we didn't lose important log messages when the runtime crashes without first flushing the buffers. This was important for exceptions, and everything else just came along for the ride. |
|
Something like this would be best for performance teinarss@29d6d58 |
|
Illustration how 28 writes per second are done to debug.log. 22 for perf. 50 OS calls times 2, one for seek, one for write. I think the simple solution of buffering each 50 logic ticks - or up to 4096k - would suffice together with catching top level exceptions that flush logs. Don't use too much generics in critical code. Also i think having a log flush thread is overkill. It only results in using locks and therefore locking. Logging debug.log info per frame on a single line also helps. Logging all logs to a single stream may also help. You could use syslog but likely difficult to support on all platforms. |
|
I believe you have the wrong interpretation for the facts at hand. The logging issue is in fact na issue because it blocks a thread that was supposed to be doing some more important work. Dispatching the log writing to another thread (an |
|
Thanks. I think I do understand it frees up the main thread. And i think a logging thread would be useful if the game would be logging many megabytes of data each second. The solution may be overkill for the problem at hand. Using a thread and locking would also introduce similar system calls, use resources, introduces code complexity. We are talking here about a few and often short text lines. Using default buffering - as you would use when writing to any text file - rather than interactive console - would perhaps suffice. The TextWriter that is used already does this buffering by default unless you set Autoflush which makes it flush after each newline. It is also not about the amount of data, just that it generates quite a lot of "expensive" system calls for such a small amount of text. |
|
I think something in log must change. I know OpenRA default mods won't have too big problem on logs because AI/player won't build big army, but for user who use this engine on developing, this problem cannot be ignore. On 400 actors, this bug on performance is critical: it absorbs 10-15% of the FPS, which is painful for light weight game/mod made by OpenRA for universal computer. I think we should solve this by either muti-thread (log thread doesn't block other threads)or player options in Debug Options Menu(default on) for one of the last method for better performance. |
|
@dnqbob i will fill a PR with my previous idea, shortly. |
And I will take this PR to rv-engine and ta-engine, if upstream doesn't merge it -- it is too painful on my computer to playtest those mods on a 2v2 game, which I think is a bottom line of the performance requirement. |
|
please consider to have the option to always log the different tick times as first log columns. makes logs more unified and easier to process with external tooling. invite modders to not log each tick only the tick time. |
|
I locally increased the LongTickThresholdMs to 5 and watched a 4-AI bot skirmish. perf.log looked like this: Of course I know it will look quite different on slower CPUs, that's not my point. Setting the default threshold to 10 ms to help performance on slow systems (and setting it back to 1 ms in our local settings.yaml for us devs) seems like a good compromise to me, we should still be able to spot any new simulation perf regressions and infinite loops can be debugged in other ways, too. Same goes for the |
|
Using LoggerMessage or similar pattern may be beneficial in future. |
Version: bleed
Impact: high
Background:
The game main loop assumes the maximum fps configured is the minimum fps possible. On hosts that cannot keep up with the configured renderInterval or forcedRenders the game becomes slower and slower untill 120% CPU is used. See #18491.
One of the reason why the games becomes slower and slower is due to the increase of logging of slow events to debug and perf log channels.
Problem:
Log uses TextWriter to write text to a file. The AutoFlush causes data to be written per logged line.
PerfTimer.LogLongTicklogs events that take longer than 1ms. On slow systems - that can't keep up - the number of events grows. On OS level this results in continuous expensive calls to lseek and write each logic tick for each line log statement.Example debug.log, same for perf.log. Last column in time in microseconds spent in system call.
Bug:
Possible solution:
Log.tick.LogChannel.Enabledto alllowif(Log.Enabled("perf)) Log.Write("perf", "{0}", expensiveCalculationSlowTime);PerfTimer.LogLongTickin release builds to a much higher value i.e. 10ms.Log.Write(Log.Perf, "line");Avoiding a call toChanneleach time.--Tick:each tick. Causing the tick only to be logged when relevant.Example perf.log output:
The text was updated successfully, but these errors were encountered: