From 2c199e7c4217d8c0b497628628573b52dc2b569f Mon Sep 17 00:00:00 2001 From: Connor McLaughlin Date: Wed, 25 May 2022 00:15:41 +1000 Subject: [PATCH] Qt: Add log timestamps --- pcsx2-qt/MainWindow.cpp | 2 + pcsx2-qt/MainWindow.ui | 10 ++++ pcsx2-qt/QtHost.cpp | 126 +++++++++++++++++++++++++++------------- pcsx2/System.cpp | 4 +- 4 files changed, 100 insertions(+), 42 deletions(-) diff --git a/pcsx2-qt/MainWindow.cpp b/pcsx2-qt/MainWindow.cpp index 133abbf271..4fe0a2a9c1 100644 --- a/pcsx2-qt/MainWindow.cpp +++ b/pcsx2-qt/MainWindow.cpp @@ -219,6 +219,8 @@ void MainWindow::connectSignals() connect(m_ui.actionEnableIOPConsoleLogging, &QAction::triggered, this, &MainWindow::onLoggingOptionChanged); SettingWidgetBinder::BindWidgetToBoolSetting(nullptr, m_ui.actionEnableFileLogging, "Logging", "EnableFileLogging", false); connect(m_ui.actionEnableFileLogging, &QAction::triggered, this, &MainWindow::onLoggingOptionChanged); + SettingWidgetBinder::BindWidgetToBoolSetting(nullptr, m_ui.actionEnableLogTimestamps, "Logging", "EnableTimestamps", true); + connect(m_ui.actionEnableLogTimestamps, &QAction::triggered, this, &MainWindow::onLoggingOptionChanged); SettingWidgetBinder::BindWidgetToBoolSetting(nullptr, m_ui.actionEnableCDVDVerboseReads, "EmuCore", "CdvdVerboseReads", false); SettingWidgetBinder::BindWidgetToBoolSetting(nullptr, m_ui.actionSaveBlockDump, "EmuCore", "CdvdDumpBlocks", false); connect(m_ui.actionSaveBlockDump, &QAction::toggled, this, &MainWindow::onBlockDumpActionToggled); diff --git a/pcsx2-qt/MainWindow.ui b/pcsx2-qt/MainWindow.ui index afcb423d1f..e95a114bbf 100644 --- a/pcsx2-qt/MainWindow.ui +++ b/pcsx2-qt/MainWindow.ui @@ -137,6 +137,8 @@ + + @@ -808,6 +810,14 @@ Save CDVD Block Dump + + + true + + + Enable Log Timestamps + + diff --git a/pcsx2-qt/QtHost.cpp b/pcsx2-qt/QtHost.cpp index 7b81a095d3..3be4bd4117 100644 --- a/pcsx2-qt/QtHost.cpp +++ b/pcsx2-qt/QtHost.cpp @@ -33,6 +33,7 @@ #include "common/Path.h" #include "common/SettingsWrapper.h" #include "common/StringUtil.h" +#include "common/Timer.h" #include "pcsx2/DebugTools/Debug.h" #include "pcsx2/Frontend/GameList.h" @@ -521,6 +522,10 @@ static const char s_console_colors[][ConsoleColors_Count] = { }; #undef CC +static Common::Timer::Value s_log_start_timestamp = Common::Timer::GetCurrentValue(); +static bool s_log_timestamps = false; +static std::mutex s_log_mutex; + // Replacement for Console so we actually get output to our console window on Windows. #ifdef _WIN32 @@ -584,29 +589,10 @@ static void ConsoleQt_DoSetColor(ConsoleColors color) #endif } -static void ConsoleQt_Newline() -{ -#ifdef _WIN32 - if (s_debugger_attached) - OutputDebugStringW(L"\n"); - - if (s_console_handle != INVALID_HANDLE_VALUE) - { - DWORD written; - WriteConsoleW(s_console_handle, L"\n", 1, &written, nullptr); - } -#else - std::fputc('\n', stdout); -#endif - - if (emuLog) - { - std::fputs("\n", emuLog); - } -} - static void ConsoleQt_DoWrite(const char* fmt) { + std::unique_lock lock(s_log_mutex); + #ifdef _WIN32 if (s_console_handle != INVALID_HANDLE_VALUE || s_debugger_attached) { @@ -635,35 +621,93 @@ static void ConsoleQt_DoWrite(const char* fmt) static void ConsoleQt_DoWriteLn(const char* fmt) { -#ifdef _WIN32 - if (s_console_handle != INVALID_HANDLE_VALUE || s_debugger_attached) + std::unique_lock lock(s_log_mutex); + + // find time since start of process, but save a syscall if we're not writing timestamps + float message_time = s_log_timestamps ? + static_cast( + Common::Timer::ConvertValueToSeconds(Common::Timer::GetCurrentValue() - s_log_start_timestamp)) : + 0.0f; + + // split newlines up + const char* start = fmt; + do { - // TODO: Put this on the stack. - std::wstring wfmt(StringUtil::UTF8StringToWideString(fmt)); + const char* end = std::strchr(start, '\n'); - if (s_debugger_attached) + std::string_view line; + if (end) { - OutputDebugStringW(wfmt.c_str()); - OutputDebugStringW(L"\n"); + line = std::string_view(start, end - start); + start = end + 1; + } + else + { + line = std::string_view(start); + start = nullptr; } - if (s_console_handle != INVALID_HANDLE_VALUE) +#ifdef _WIN32 + if (s_console_handle != INVALID_HANDLE_VALUE || s_debugger_attached) { - DWORD written; - WriteConsoleW(s_console_handle, wfmt.c_str(), static_cast(wfmt.length()), &written, nullptr); - WriteConsoleW(s_console_handle, L"\n", 1, &written, nullptr); + // TODO: Put this on the stack. + std::wstring wfmt(StringUtil::UTF8StringToWideString(line)); + + if (s_debugger_attached) + { + // VS already timestamps logs (at least with the productivity power tools). + if (!wfmt.empty()) + OutputDebugStringW(wfmt.c_str()); + OutputDebugStringW(L"\n"); + } + + if (s_console_handle != INVALID_HANDLE_VALUE) + { + DWORD written; + if (s_log_timestamps) + { + wchar_t timestamp_text[128]; + const int timestamp_len = _swprintf(timestamp_text, L"[%10.4f] ", message_time); + WriteConsoleW(s_console_handle, timestamp_text, static_cast(timestamp_len), &written, nullptr); + } + + if (!wfmt.empty()) + WriteConsoleW(s_console_handle, wfmt.c_str(), static_cast(wfmt.length()), &written, nullptr); + + WriteConsoleW(s_console_handle, L"\n", 1, &written, nullptr); + } } - } #else - std::fputs(fmt, stdout); - std::fputc('\n', stdout); + if (s_log_timestamps) + { + std::fprintf(stdout, "[%10.4f] %.*s\n", message_time, static_cast(line.length()), line.data()); + } + else + { + if (!line.empty()) + std::fwrite(line.data(), line.length(), 1, stdout); + std::fputc('\n', stdout); + } #endif - if (emuLog) - { - std::fputs(fmt, emuLog); - std::fputc('\n', emuLog); - } + if (emuLog) + { + if (s_log_timestamps) + { + std::fprintf(emuLog, "[%10.4f] %.*s\n", message_time, static_cast(line.length()), line.data()); + } + else + { + std::fwrite(line.data(), line.length(), 1, emuLog); + std::fputc('\n', emuLog); + } + } + } while (start); +} + +static void ConsoleQt_Newline() +{ + ConsoleQt_DoWriteLn(""); } static const IConsoleWriter ConsoleWriter_WinQt = @@ -788,6 +832,8 @@ void QtHost::UpdateLogging() const bool system_console_enabled = Host::GetBaseBoolSettingValue("Logging", "EnableSystemConsole", false); const bool file_logging_enabled = Host::GetBaseBoolSettingValue("Logging", "EnableFileLogging", false); + s_log_timestamps = Host::GetBaseBoolSettingValue("Logging", "EnableTimestamps", true); + const bool any_logging_sinks = system_console_enabled || file_logging_enabled; DevConWriterEnabled = any_logging_sinks && (IsDevBuild || Host::GetBaseBoolSettingValue("Logging", "EnableVerbose", false)); SysConsole.eeConsole.Enabled = any_logging_sinks && Host::GetBaseBoolSettingValue("Logging", "EnableEEConsole", false); diff --git a/pcsx2/System.cpp b/pcsx2/System.cpp index a52b11a73d..b7de4fd681 100644 --- a/pcsx2/System.cpp +++ b/pcsx2/System.cpp @@ -150,9 +150,9 @@ void SysLogMachineCaps() // tagged commit - more modern implementation of dev build versioning // - there is no need to include the commit - that is associated with the tag, // - git is implied and the tag is timestamped - Console.WriteLn(Color_StrongGreen, "\nPCSX2 Nightly - %s Compiled on %s", GIT_TAG, __DATE__); + Console.WriteLn(Color_StrongGreen, "PCSX2 Nightly - %s Compiled on %s", GIT_TAG, __DATE__); } else { - Console.WriteLn(Color_StrongGreen, "\nPCSX2 %u.%u.%u-%lld" + Console.WriteLn(Color_StrongGreen, "PCSX2 %u.%u.%u-%lld" #ifndef DISABLE_BUILD_DATE "- compiled on " __DATE__ #endif