New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logging: Add customizable logging backends and fmtlib based macros #3449

Closed
wants to merge 7 commits into
base: master
from

Conversation

Projects
None yet
10 participants
@jroweboy
Member

jroweboy commented Feb 20, 2018

Supersedes #2707

TL;DR:

  • Change the logging backend to support multiple sinks through the Backend Interface
  • Add a new set of logging macros to use fmtlib instead.
  • Qt: Compile as GUI application on windows to make the console hidden by
    default. Add filter configuration and a button to open log location.
  • SDL: Migrate to the new logging macros

I tried to apply the lessons learned from the last logging PR. This time I built my own sinks instead of trying to attach spdlog sinks. The new logger splits sinks out from sources by using the MPSC queue and a worker thread. The worker thread will check for new logs and call Write for each Backend that is registered.

How logging works now:

  • Setup for each frontend:
    • Load the settings, and configures the global logging filter (default "*:Info").
    • Get the log location from GetUserPath(D_LOGS_IDX) and creates the folder if missing.
    • Add Backends to the list of backends. Both frontends do a color console and a file backend
  • printf or fmt lib macro is called.
    • builds a Entry which gets added to the MPSC queue (so its thread safe to call the logging macros)
  • worker thread:
    • Consumes from the queue. Get the Entry and passes it to each configured backend
    • Backends can use the convenience functions in text_formatting to build the correct format string.

After this is merged, we will need to do what was planned for the original PR and migrate the old logging macros to the new one, followed by a final commit to rename it back to the original name.

Sorry for random format changes. I'm still using clang-format 6 while waiting for #3410 to get merged ;) hint hint

Debug tab changed to add logging stuff
citra-qt_2018-02-19_18-30-24


This change is Reviewable

Logging: Add customizable logging backends and fmtlib based macros
* Change the logging backend to support multiple sinks through the
Backend Interface
* Add a new set of logging macros to use fmtlib instead.
* Qt: Compile as GUI application on windows to make the console hidden by
default. Add filter configuration and a button to open log location.
* SDL: Migrate to the new logging macros
@cluezbot

This comment has been minimized.

cluezbot commented Feb 20, 2018

Hi, this is neobot, using neobrain's account. I'm keeping an archive of versions of this PR:

2018-02-20T01:28:22Z: 20f6cb1...jroweboy:33a750b806cf08b4a2141abcdf867d65277c256d

Entry entry;
while (running) {
if (!message_queue.Pop(entry)) {
std::this_thread::sleep_for(1ms);

This comment has been minimized.

@jroweboy

jroweboy Feb 20, 2018

Member

Is 1ms too much to wait for new logs?

@jroweboy jroweboy requested review from yuriks and lioncash Feb 20, 2018

#include "citra_qt/ui_settings.h"
namespace Debugger {
void ToggleConsole() {

This comment has been minimized.

@j-selby

j-selby Feb 20, 2018

Contributor

Is there a reason why this couldn't just be a a Qt window? Seems a bit weird to be adding win32 conhost bindings in the Qt frontend

EDIT: saw your comment below. all cool.

This comment has been minimized.

@jroweboy

jroweboy Feb 20, 2018

Member

Yup. I wanted to make a QT window, but that'll be for another day. I spent about 7 1/2 hours on this and I imagine a good UI for it would take just as long :)

*/
class FileBackend : public Backend {
public:
FileBackend(const std::string& filename) : file(filename, "w") {}

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

explicit FileBackend

}
void PrintColoredMessage(const Entry& entry) {
#ifdef _WIN32
static HANDLE console_handle = GetStdHandle(STD_ERROR_HANDLE);
HANDLE console_handle = GetStdHandle(STD_ERROR_HANDLE);

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

To make this a little more robust, you should probably check if the call doesn't fail. i.e.

console_handle = blah;
if (console_handle == INVALID_HANDLE_VALUE) {
    return;
}
return;
std::array<char, 4 * 1024> formatting_buffer;

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

This seems like something that should be managed by the logger itself, so it's not continually placed on the stack every time a message is logged, but it was already like this, so feel free to ignore it.

Entry entry;
entry.timestamp = duration_cast<std::chrono::microseconds>(steady_clock::now() - time_origin);
entry.log_class = log_class;
entry.log_level = log_level;
entry.filename = std::string(Common::TrimSourcePath(filename));

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

This can just be assigned to filename without the std::string constructor call.

Entry entry;
entry.timestamp = duration_cast<std::chrono::microseconds>(steady_clock::now() - time_origin);
entry.log_class = log_class;
entry.log_level = log_level;
entry.filename = std::string(Common::TrimSourcePath(filename));
entry.line_num = line_nr;
entry.function = std::string(function);

This comment has been minimized.

@lioncash
});
}
~Impl() {
if (running) {

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

Does this if statement matter? If the object it being torn down, I doubt the boolean value matters much.

@@ -113,45 +205,65 @@ const char* GetLevelName(Level log_level) {
}
Entry CreateEntry(Class log_class, Level log_level, const char* filename, unsigned int line_nr,
const char* function, const char* format, va_list args) {
using std::chrono::steady_clock;
const char* function, const std::string& message) {

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

I would take message by value here and std::move it into entry.message. This can avoid copies, as it can be moved into from the call site. e.g. The use in FmtLogMessage can utilize std::string's move constructor as-is, if this is passed by value instead of const reference.

FormatLogMessage(entry, format_buffer.data(), format_buffer.size());
fputs(format_buffer.data(), stderr);
fputc('\n', stderr);
auto str = FormatLogMessage(entry) + "\n";

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

\n can be a character literal, which can be cheaper to append than a string: '\n'

filter = f;
}
Backend* GetBackend(const std::string& backend_name) {

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

This should probably return a boost::optional instead of a raw pointer, so nullptr isn't used as a synonym for "not found".

This comment has been minimized.

@jroweboy

jroweboy Feb 20, 2018

Member

I was originally avoiding linking boost to common, but then i just learned that it was already linked to common.

Impl(Impl const&) = delete;
const Impl& operator=(Impl const&) = delete;
Common::MPSCQueue<Log::Entry>& GetQueue() {

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

Does it make sense to expose the queue itself, instead of providing a PushEntry function that forwards the entry to the queue as part of the API?

@cluezbot

This comment has been minimized.

cluezbot commented Feb 20, 2018

Hi, this is neobot, using neobrain's account. I'm keeping an archive of versions of this PR:

2018-02-20T04:36:08Z: 20f6cb1...jroweboy:8b25cc4fe7f93c9b82ba8e61a485a52ebc683062

entry.filename = Common::TrimSourcePath(filename);
entry.line_num = line_nr;
entry.function = function;
entry.message = message;

This comment has been minimized.

@lioncash

lioncash Feb 20, 2018

Member

message can be std::moved here now

@cluezbot

This comment has been minimized.

cluezbot commented Feb 20, 2018

Hi, this is neobot, using neobrain's account. I'm keeping an archive of versions of this PR:

2018-02-20T05:17:56Z: 20f6cb1...jroweboy:2246ec8779ffc2fdebc115f0f4c9d8dadc702ff0

jroweboy added some commits Feb 23, 2018

SPSCQueue: Add PopWait
Adds a condition var to SPSCQueue so when a new log is pushed it will
wake the consumer thread that is calling PopWait. This only applies to
to queues with NeedSize=true
Logging: Various logging improvements
* Uses PopWait to reduce the amount of busy waiting if there aren't many
new logs
* Opens the log file as shared on windows, letting other programs read
the logs, but not write to them while citra is running
* Flushes the logs to disk if a log >= error arrives
@cluezbot

This comment has been minimized.

cluezbot commented Feb 23, 2018

Hi, this is neobot, using neobrain's account. I'm keeping an archive of versions of this PR:

2018-02-23T07:36:30Z: 20f6cb1...jroweboy:d145ad4164ada509df4ad0f84387799fff283a48

@jroweboy

This comment has been minimized.

Member

jroweboy commented Feb 23, 2018

Summary of the new updates. Thanks to @chris062689 for suggesting some of these improvements.

  • Uses PopWait to reduce the amount of busy waiting if there aren't many new logs
  • Opens the log file as shared on windows, letting other programs read the logs, but not write to them while citra is running
  • Flushes the logs to disk if a log >= error arrives
@chris062689

This comment has been minimized.

Member

chris062689 commented Feb 23, 2018

I'll test these changes tonight, thanks @jroweboy for those tweaks, I think it improves usability.

@cluezbot

This comment has been minimized.

cluezbot commented Feb 25, 2018

Hi, this is neobot, using neobrain's account. I'm keeping an archive of versions of this PR:

2018-02-25T00:41:27Z: 20f6cb1...jroweboy:3a656087f486fe95751078da07b8c485f572b756

@B3n30

I don't like that the log is always written to a file. this could easily lead to TB big log files if you play for a few hours. Ofc this could be some sort of hidden child protection, but Imo it's better to have the option to disable logging to a file.

Second thing is: I don't like the path to the log_file is hardcoded. It would be great (but maybe for a later PR) to have the option to change the path and maybe add some formatting options for the filename (time of creation, continuous number, game name, whatever)

<item>
<widget class="QCheckBox" name="toggle_console">
<property name="text">
<string>Show Log Console (Windows Only)</string>

This comment has been minimized.

@B3n30

B3n30 Feb 25, 2018

Contributor

I don't like the '(Windows only)' label. I think a better option would be to remove or disable that checkbox on other OSs. Or add that feature for the other OSs, too

This comment has been minimized.

@jroweboy

jroweboy Feb 25, 2018

Member

If you read the comment in the source code, the idea is to replace this feature with a QT console window entirely. I don't see a point in dealing with platform specific hiding and showing a single checkbox on the debug tab.

using namespace std::chrono_literals;
Entry entry;
while (running) {
if (!message_queue.PopWait(entry)) {

This comment has been minimized.

@B3n30

B3n30 Feb 25, 2018

Contributor

This could lead to an incomplete log if Impl gets destroyed. It should probably be two while loops

@jroweboy

This comment has been minimized.

Member

jroweboy commented Feb 25, 2018

this could easily lead to TB big log files if you play for a few hours. Ofc this could be some sort of hidden child protection, but Imo it's better to have the option to disable logging to a file.

If this is really a problem, then we should move some of the Debug logs that we have into Trace.

There should not be a way to disable the log entirely imo. This will lead to scenarios where we can't debug issues because people downloaded a build with logging off and they are unable to figure out where to turn it back on. There is already a log level filter, so someone could just easily set it to Critical now, but turning off logs is a non-goal entirely to me.

@wwylele

This comment has been minimized.

Member

wwylele commented Feb 25, 2018

this could easily lead to TB big log files if you play for a few hours. Ofc this could be some sort of hidden child protection, but Imo it's better to have the option to disable logging to a file.

If this is really a problem, then we should move some of the Debug logs that we have into Trace.

Here example that you couldn't easily fix with Trace level:

When a game jumps to pc = 0 for some reason (Panic break, wrong branching, null function pointer calling...), citra will start to log Unmapped Read32 (Error level) for every single CPU instructions, which is very fast (especially in JIT mode because dynarmic would try to go through the whole code first). Now with log window hidden by default, user would only notice that the game freezes, and citra window unable to close (because the emu thread is locked in the CPU loop), and won't have an idea that the log file is being filled up very quickly.

This kind of log exists for many games (most of them is due to wrong region configuration though)

@wwylele

General design idea looks good to me but here are some nitpicking.

@yuriks Do you want to give a review?

@@ -119,7 +120,7 @@ int main(int argc, char** argv) {
auto argv_w = CommandLineToArgvW(GetCommandLineW(), &argc_w);
if (argv_w == nullptr) {
LOG_CRITICAL(Frontend, "Failed to get command line arguments");
NGLOG_CRITICAL(Frontend, "Failed to get command line arguments");

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

This log is never going to print because the program exit before the backend setup

@@ -2,13 +2,27 @@
// Licensed under GPLv2 or any later version
// Refer to the license.txt file included.
#include <QDesktopServices>
#include <QUrl>

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

No blank line between includes (unless it is the new clang-format style?)

* get a real qt logging window which would work for all platforms.
*/
void ToggleConsole();
} // namespace Debugger

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

new line at the end of file

* @param T In parameter to store the value if this method returns true
* @param timeout Time in milliseconds to wait for a signal from a Push
*/
bool PopWait(T& t, u64 timeout = 500) {

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

As a generic queue class I would pass std::chrono::duration as a parameter, letting user be able to use any unit.

Also, since PopWait with NeedSize = false doesn't do what one would expected, could you just disable it using static_assert?

This comment has been minimized.

@jroweboy

jroweboy Feb 26, 2018

Member

Since this one is in common, I wanted to avoid pulling in a dependency on chrono. In actuality, its only used in two places so its not a big deal if you want me to add it.

if (NeedSize) {
std::unique_lock<std::mutex> lock(size_lock);
if (size_cv.wait_for(lock, std::chrono::milliseconds(timeout),
[& size = size] { return size > 0; })) {

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

Probably cleaner to just capture [this]

private:
Impl() {
backend_thread = std::async(std::launch::async, [&] {
using namespace std::chrono_literals;

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

where is this used?

}
std::atomic_bool running{true};
std::future<void> backend_thread;

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

Why not just use std::thread as the name suggested?

virtual void Write(const Entry& entry) = 0;
private:
Filter filter;

This comment has been minimized.

@wwylele

wwylele Feb 25, 2018

Member

I don't see this member being used anywhere.

Also, although I see that this filter is intended to be used as a "sub-filter" for each backend after checking the global one, I found it strange that it is in the backend implementation logic, since the sub-filter logic would be always the same (if (filter.pass(entry)) print(entry); ), so it can just placed in the global logic (the Impl class).

This comment has been minimized.

@jroweboy

jroweboy Feb 26, 2018

Member

I like that idea better. Will change that.

@jroweboy

This comment has been minimized.

Member

jroweboy commented Feb 26, 2018

This kind of log exists for many games (most of them is due to wrong region configuration though)

Fair point. Any suggestions on how best to handle the large log file then?

@BreadFish64

This comment has been minimized.

Contributor

BreadFish64 commented Feb 26, 2018

This will lead to scenarios where we can't debug issues because people downloaded a build with logging off and they are unable to figure out where to turn it back on.

We don't support unofficial builds, so I don't really see how that's our problem.

@B3n30

This comment has been minimized.

Contributor

B3n30 commented Feb 26, 2018

IMO the best solution is to have an option to enable the logging to file by default and have a option in config/debug to enable logging to file. If someone ask for support/has an issue we can tell them to enable logging to file, run the game till the issue occurs and then send us the log.

Another solution would be to generate a warning if the log file reaches a certain size. But no idea on how to continue at that point.

@jroweboy

This comment has been minimized.

Member

jroweboy commented Feb 27, 2018

Does any one have any issue with cutting off the file log at 50MB? if your filter is setup such that you spam more than 50MB of data then you should likely modify the filter.

I still disagree that we should allow disabling file logging. Logging is meant to be a post mortem debugging tool, so we should have it on by default to catch errors when they happen, and not turn it on and attempt to replicate it.

@daniellimws

This comment has been minimized.

Contributor

daniellimws commented Feb 27, 2018

How about compressing the current log file at say 50MB, then create a new one (like part 2), so as to have "multi-parts" of the log? (Not sure if this would introduce dependencies)

Edit: But actually 50MB looks like a great lot for a log file

@adityaruplaha

This comment has been minimized.

Contributor

adityaruplaha commented Feb 27, 2018

Well, for many commercial games, the log spam is very high. So it might reach well over 50 MB.


@daniellimws I think that's a great idea.


Well, it's just a suggestion, but can't we just check if the Read32 exception (or similar) has already been thrown? Then we can just print a "...". Then it'll handle the problem quite well. But it'll be a little like a hack.

@jroweboy

This comment has been minimized.

Member

jroweboy commented Feb 27, 2018

I don't have the time to put in enough effort to satisfy everyone anymore on this PR. Heres the patch that I was writing, its not complete, but it should be pretty good. If someone wants to pick this up and finish it go ahead.

diff.txt

In the diff, I've added a condition var to backend impl instead of in the queue so that it can wait on both variables instead of spin waiting on running. I also limited the amount written to disk in the file backend to 50 MB. Addressed most of wwylele's comments. After shutting down, it tries to write at least 100 more logs to clear out the queue before finally closing. Was working on removing and adding the ConsoleBackend when showing/hiding the console as a test of that system and it didn't work. Don't care to fix that but its something that the next person could look at or eventually if I get time again I'll look at it. Got more important PRs to work on in the meantime.

@daniellimws I recall you wanted something to pick up. I'd hate to pass the buck off to someone, but you are more than willing to resubmit this PR with those issues addressed if you want.

@jroweboy jroweboy closed this Feb 27, 2018

@jroweboy

This comment has been minimized.

Member

jroweboy commented Feb 27, 2018

FYI I'm closing this because it conflicts with multiplayer UI and since its not getting merged soon, i might as well just close the UI gets fixed and merged

daniellimws pushed a commit to daniellimws/citra that referenced this pull request Mar 9, 2018

daniellimws added a commit to daniellimws/citra that referenced this pull request Mar 10, 2018

Squash previous commits
Logging: Add customizable logging backends and fmtlib based macros

* Change the logging backend to support multiple sinks through the
Backend Interface
* Add a new set of logging macros to use fmtlib instead.
* Qt: Compile as GUI application on windows to make the console hidden by
default. Add filter configuration and a button to open log location.
* SDL: Migrate to the new logging macros

Use the correct linker flag for mingw

Address review comments

fixup! move message

SPSCQueue: Add PopWait

Adds a condition var to SPSCQueue so when a new log is pushed it will
wake the consumer thread that is calling PopWait. This only applies to
to queues with NeedSize=true

Logging: Various logging improvements

* Uses PopWait to reduce the amount of busy waiting if there aren't many
new logs
* Opens the log file as shared on windows, letting other programs read
the logs, but not write to them while citra is running
* Flushes the logs to disk if a log >= error arrives

fixup! Prevent crashes on closing by waiting for the impl thread

Apply patch by jroweboy

Logging: Add customizable logging backends and fmtlib based macros

Fix problems by jroweboy in citra-emu#3449

Rename FileBackend name to file

Make RemoveBackend work

But haven't fixed the error of Citra crashing yet
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment