Add timestamps to stdout, file loggers and editor Output panel

[Calinou]

Timestamps use ISO 8601 format, prefixing every printed line with YYYY-MM-DDTHH:MM:SS+HH:MM |. +HH:MM at the end denotes the timezone offset. In the editor, they use YYYY-MM-DD HH:MM:SS for better readability. Both are printed in local time.

Timestamp display can be toggled separately for stdout/stderr and file loggers in the Project Settings. By default, timestamps are logged to files, are not printed in stdout/stderr and are not shown in the editor Output panel. The "compact identical lines" option in the editor Output panel works correctly when timestamps are shown, with the timestamp becoming the time of the latest print.

• This closes Print timestamps in the editor Output panel godot-proposals#1786.

TODO

• Handle multiline strings in stdout (each line should have a timestamp). This is already done in the editor Output panel and file logging.
• Optimize code to query date/time only once (or perhaps twice) per second at most, as this can take a non-negligible amount of time if printing lots of lines at the same time.
  • Currently, in a debug build, master takes 1.8s to log and print 200,000 lines (with stdout not being displayed in terminal), and this PR takes 3.1s.¹
    • In an optimized build, this same operation takes 1.6s in master and this PR takes 2.2s.¹

Example log file

2023-07-16T00:01:15+02:00 | Godot Engine v4.2.dev.custom_build.6b39157b9 - https://godotengine.org
2023-07-16T00:01:15+02:00 | Vulkan API 1.3.242 - Forward+ - Using Vulkan Device #0: NVIDIA - NVIDIA GeForce RTX 4090
2023-07-16T00:01:16+02:00 |  
2023-07-16T00:01:16+02:00 | Test message.
2023-07-16T00:01:16+02:00 | 
2023-07-16T00:01:16+02:00 | Test message.
2023-07-16T00:01:16+02:00 | Test message 2.
2023-07-16T00:01:16+02:00 | Lorem ipsum dolor sit amet, consectetur adipiscing elit. Nullam est sapien, hendrerit a leo a, accumsan condimentum magna. Aliquam et nisl et nisi aliquet elementum ac id sapien. Cras nec rutrum risus. Suspendisse vel urna vel ante posuere varius ac sit amet nibh. Pellentesque ante est, venenatis a laoreet ut, aliquam quis nulla. Donec interdum malesuada lorem, in egestas augue ultricies quis. Integer sagittis dolor nunc, in ullamcorper felis scelerisque cursus. Nulla suscipit ut velit at vehicula. Nulla tempor dui nec fermentum porttitor. Sed ullamcorper hendrerit dictum. Curabitur non accumsan velit. Praesent eleifend dolor magna, tristique vehicula lacus dignissim at. Cras vel ultrices ipsum, quis condimentum sapien. Proin ut tortor varius, egestas nulla ut, aliquam nisi. Maecenas eu mi nec tellus pulvinar posuere ac a risus. Suspendisse nisl metus, fermentum vel tortor sit amet, mollis dapibus tortor. Etiam luctus ante elit, nec ultrices est dignissim a. Aenean vel facilisis nibh. Praesent eros leo, luctus non convallis quis, finibus et arcu. In ac elementum augue. Maecenas efficitur tortor eros, nec cursus est sagittis posuere. Curabitur bibendum posuere risus, vel rutrum lacus fermentum non. Sed quis quam eget justo posuere dictum. Donec nec feugiat libero. Donec suscipit dui at leo vestibulum, eget efficitur sapien porta. Maecenas et nunc vel nibh egestas sagittis eget nec nibh. Mauris fermentum est at aliquet auctor. Morbi a erat eget lectus porttitor maximus id vel diam. Proin et sodales leo. Fusce suscipit tincidunt porta. Donec sed turpis vel nulla lobortis rhoncus. Sed sollicitudin eget nulla quis blandit. Aliquam cursus porttitor neque et eleifend. Pellentesque efficitur finibus erat. Aliquam hendrerit arcu at elit feugiat molestie. Donec consectetur, nisi id tempus luctus, velit tellus auctor lorem, vitae facilisis urna ex eget felis. Morbi nec purus enim. Integer et quam tincidunt, interdum neque vel, ultricies sapien. Donec lobortis metus ipsum, id semper diam maximus ut. Mauris a felis et mauris ullamcorper viverra vitae in massa. Proin egestas felis euismod sapien sagittis ultricies. Quisque suscipit tristique ligula, a blandit lorem aliquet id. Quisque feugiat id est tristique cursus. Sed tincidunt eros ac ipsum consectetur tempus. Sed lacinia, sapien in dictum consectetur, tortor sapien malesuada orci, sit amet elementum lacus lorem a ante. Etiam ultricies, urna finibus maximus iaculis, nibh velit egestas nibh, et efficitur nibh nibh vitae sapien. Morbi quis suscipit est, nec rutrum elit. Pellentesque at mattis elit. Aliquam nulla urna, vehicula suscipit justo a, cursus dignissim ipsum. Curabitur finibus vestibulum aliquet. Nam scelerisque justo sed bibendum tempus. Aliquam erat volutpat. Aliquam eget malesuada ex. In hac habitasse platea dictumst. Suspendisse tempus dolor vitae dignissim aliquet. Sed magna dolor, euismod eget fringilla non, imperdiet et libero. 

Footnotes

1. These metrics include engine startup and shutdown, as this was measured using hyperfine and the --quit CLI argument. ↩ ↩²

[Calinou]

I've fixed timestamps not appearing in the written log files, so this PR is now ready for review. Thanks @SlugFiller for the help 🙂

[akien-mga]

Doesn't compile. How expensive are the added timestamp and timezone calculations on each message? Logging/printing is already fairly expensive, we should be careful about possibly increasingly its cost significantly.

[Calinou]

Doesn't compile. How expensive are the added timestamp and timezone calculations on each message? Logging/printing is already fairly expensive, we should be careful about possibly increasingly its cost significantly.

I've fixed compilation and have benchmarked the new logging code. Unfortunately, it's about 4× slower than before in a debug build, with each log taking on average 8 microseconds (where it previously required 1-2 microseconds).

This isn't due to using the higher-level String approach (I've tried replacing the timestamp string with a constant), but OS::get_singleton()->get_datetime_string_from_system() is relatively slow on its own. Maybe we could ensure it's called only once per second at most to reduce the overhead when spamming prints (we only display time up to the nearest second anyway).

[akien-mga]

Blocking merge for now as the performance hit is too heavy.

[kaydensigh]

As a way to minimize performance impact, would it be useful to only log ticks (formatted in MM:SS:msec) rather than system time? The log file itself I believe has the process launch time in the filename, so it would be possible to figure out the absolute time if needed.

[akien-mga]

As a way to minimize performance impact, would it be useful to only log ticks (formatted in MM:SS:msec) rather than system time? The log file itself I believe has the process launch time in the filename, so it would be possible to figure out the absolute time if needed.

Yeah I think using engine tick count would definitely be the way to go. It can still be formatted as absolute time if wanted, by calculating the diff to the original system time when the tick count started. It might drift a bit but for this purpose it's probably not critical.

Alternatively, a relative time since the start of the process also makes sense to me in a game log context (i.e. "how far into the game session did the user run into these bugs?").

We still need to make sure that whatever calculations are done for pretty formatting aren't too heavy - but avoiding system calls is definitely a must if we want to log timestamps.