From 228843c43e21ce4d3ca5fe0adc96fcb34505446b Mon Sep 17 00:00:00 2001 From: archshift Date: Sat, 10 Jan 2015 13:07:50 -0800 Subject: [PATCH 1/2] Logging: Log all called service functions (under trace). Compile out all trace logs under release for performance. --- src/common/common.h | 7 ------- src/common/log.h | 2 +- src/common/logging/log.h | 23 +++++++-------------- src/core/hle/result.h | 4 ++-- src/core/hle/service/apt_u.cpp | 4 ---- src/core/hle/service/fs/fs_user.cpp | 4 ---- src/core/hle/service/gsp_gpu.cpp | 3 --- src/core/hle/service/hid_user.cpp | 2 -- src/core/hle/service/ptm_u.cpp | 2 -- src/core/hle/service/service.h | 31 +++++++++++++++++++---------- src/core/hle/service/srv.cpp | 4 ---- src/core/hle/svc.cpp | 1 - 12 files changed, 30 insertions(+), 57 deletions(-) diff --git a/src/common/common.h b/src/common/common.h index bf48ae667e..3246c77975 100644 --- a/src/common/common.h +++ b/src/common/common.h @@ -11,13 +11,6 @@ #include #include -// Force enable logging in the right modes. For some reason, something had changed -// so that debugfast no longer logged. -#if defined(_DEBUG) || defined(DEBUGFAST) -#undef LOGGING -#define LOGGING 1 -#endif - #define STACKALIGN // An inheritable class to disallow the copy constructor and operator= functions diff --git a/src/common/log.h b/src/common/log.h index 667f2fbb94..b397cf14df 100644 --- a/src/common/log.h +++ b/src/common/log.h @@ -14,7 +14,7 @@ #endif #endif -#if _DEBUG +#ifdef _DEBUG #define _dbg_assert_(_t_, _a_) \ if (!(_a_)) {\ LOG_CRITICAL(_t_, "Error...\n\n Line: %d\n File: %s\n Time: %s\n\nIgnore and continue?", \ diff --git a/src/common/logging/log.h b/src/common/logging/log.h index bda3d633ac..3d94bf0d90 100644 --- a/src/common/logging/log.h +++ b/src/common/logging/log.h @@ -73,17 +73,6 @@ enum class Class : ClassType { Count ///< Total number of logging classes }; -/** - * Level below which messages are simply discarded without buffering regardless of the display - * settings. - */ -const Level MINIMUM_LEVEL = -#ifdef _DEBUG - Level::Trace; -#else - Level::Debug; -#endif - /** * Logs a message to the global logger. This proxy exists to avoid exposing the details of the * Logger class, including the ConcurrentRingBuffer template, to all files that desire to log @@ -103,13 +92,15 @@ void LogMessage(Class log_class, Level log_level, } // namespace Log #define LOG_GENERIC(log_class, log_level, ...) \ - do { \ - if (::Log::Level::log_level >= ::Log::MINIMUM_LEVEL) \ - ::Log::LogMessage(::Log::Class::log_class, ::Log::Level::log_level, \ - __FILE__, __LINE__, __func__, __VA_ARGS__); \ - } while (0) + ::Log::LogMessage(::Log::Class::log_class, ::Log::Level::log_level, \ + __FILE__, __LINE__, __func__, __VA_ARGS__) +#ifdef _DEBUG #define LOG_TRACE( log_class, ...) LOG_GENERIC(log_class, Trace, __VA_ARGS__) +#else +#define LOG_TRACE( log_class, ...) (void(0)) +#endif + #define LOG_DEBUG( log_class, ...) LOG_GENERIC(log_class, Debug, __VA_ARGS__) #define LOG_INFO( log_class, ...) LOG_GENERIC(log_class, Info, __VA_ARGS__) #define LOG_WARNING( log_class, ...) LOG_GENERIC(log_class, Warning, __VA_ARGS__) diff --git a/src/core/hle/result.h b/src/core/hle/result.h index 0e9c213e06..82dcf5bba7 100644 --- a/src/core/hle/result.h +++ b/src/core/hle/result.h @@ -369,14 +369,14 @@ private: StorageType storage; ResultCode result_code; -#if _DEBUG +#ifdef _DEBUG // The purpose of this pointer is to aid inspecting the type with a debugger, eliminating the // need to cast `storage` to a pointer or pay attention to `result_code`. const T* debug_ptr; #endif void UpdateDebugPtr() { -#if _DEBUG +#ifdef _DEBUG debug_ptr = empty() ? nullptr : static_cast(static_cast(&storage)); #endif } diff --git a/src/core/hle/service/apt_u.cpp b/src/core/hle/service/apt_u.cpp index d8b261ba73..d0ff4e5850 100644 --- a/src/core/hle/service/apt_u.cpp +++ b/src/core/hle/service/apt_u.cpp @@ -52,8 +52,6 @@ void Initialize(Service::Interface* self) { Kernel::ReleaseMutex(lock_handle); cmd_buff[1] = 0; // No error - - LOG_DEBUG(Service_APT, "called"); } void GetLockHandle(Service::Interface* self) { @@ -194,8 +192,6 @@ void AppletUtility(Service::Interface* self) { * 4 : Handle to shared font memory */ void GetSharedFont(Service::Interface* self) { - LOG_TRACE(Kernel_SVC, "called"); - u32* cmd_buff = Kernel::GetCommandBuffer(); if (!shared_font.empty()) { diff --git a/src/core/hle/service/fs/fs_user.cpp b/src/core/hle/service/fs/fs_user.cpp index 7eb32146d0..40dd0df2c8 100644 --- a/src/core/hle/service/fs/fs_user.cpp +++ b/src/core/hle/service/fs/fs_user.cpp @@ -27,8 +27,6 @@ static void Initialize(Service::Interface* self) { // TODO(Link Mauve): check the behavior when cmd_buff[1] isn't 32, as per // http://3dbrew.org/wiki/FS:Initialize#Request cmd_buff[1] = RESULT_SUCCESS.raw; - - LOG_DEBUG(Service_FS, "called"); } /** @@ -408,8 +406,6 @@ static void IsSdmcDetected(Service::Interface* self) { cmd_buff[1] = 0; cmd_buff[2] = Settings::values.use_virtual_sd ? 1 : 0; - - LOG_DEBUG(Service_FS, "called"); } /** diff --git a/src/core/hle/service/gsp_gpu.cpp b/src/core/hle/service/gsp_gpu.cpp index 26a43217e0..2b115240f1 100644 --- a/src/core/hle/service/gsp_gpu.cpp +++ b/src/core/hle/service/gsp_gpu.cpp @@ -331,9 +331,6 @@ static void ExecuteCommand(const Command& command, u32 thread_id) { /// This triggers handling of the GX command written to the command buffer in shared memory. static void TriggerCmdReqQueue(Service::Interface* self) { - - LOG_TRACE(Service_GSP, "called"); - // Iterate through each thread's command queue... for (unsigned thread_id = 0; thread_id < 0x4; ++thread_id) { CommandBuffer* command_buffer = (CommandBuffer*)GetCommandBuffer(thread_id); diff --git a/src/core/hle/service/hid_user.cpp b/src/core/hle/service/hid_user.cpp index 8ef9af9d20..1403b1de90 100644 --- a/src/core/hle/service/hid_user.cpp +++ b/src/core/hle/service/hid_user.cpp @@ -163,8 +163,6 @@ static void GetIPCHandles(Service::Interface* self) { cmd_buff[6] = event_accelerometer; cmd_buff[7] = event_gyroscope; cmd_buff[8] = event_debug_pad; - - LOG_TRACE(Service_HID, "called"); } const Interface::FunctionInfo FunctionTable[] = { diff --git a/src/core/hle/service/ptm_u.cpp b/src/core/hle/service/ptm_u.cpp index fd79cd8ab3..753180add1 100644 --- a/src/core/hle/service/ptm_u.cpp +++ b/src/core/hle/service/ptm_u.cpp @@ -76,8 +76,6 @@ static void GetShellState(Service::Interface* self) { cmd_buff[1] = 0; cmd_buff[2] = shell_open ? 1 : 0; - - LOG_TRACE(Service_PTM, "PTM_U::GetShellState called"); } /** diff --git a/src/core/hle/service/service.h b/src/core/hle/service/service.h index 41ba1e554d..e75d5008bb 100644 --- a/src/core/hle/service/service.h +++ b/src/core/hle/service/service.h @@ -33,6 +33,22 @@ class Interface : public Kernel::Session { // processes. friend class Manager; + + /** + * Creates a function string for logging, complete with the name (or header code, depending + * on what's passed in) the port name, and all the cmd_buff arguments. + */ + std::string MakeFunctionString(const std::string& name, const std::string& port_name, const u32* cmd_buff) { + // Number of params == bits 0-5 + bits 6-11 + int num_params = (cmd_buff[0] & 0x3F) + ((cmd_buff[0] >> 6) & 0x3F); + + std::string function_string = Common::StringFromFormat("function '%s': port=%s", name.c_str(), port_name.c_str()); + for (int i = 1; i <= num_params; ++i) { + function_string += Common::StringFromFormat(", cmd_buff[%i]=%u", i, cmd_buff[i]); + } + return function_string; + } + public: std::string GetName() const override { return GetPortName(); } @@ -72,21 +88,14 @@ public: auto itr = m_functions.find(cmd_buff[0]); if (itr == m_functions.end() || itr->second.func == nullptr) { - // Number of params == bits 0-5 + bits 6-11 - int num_params = (cmd_buff[0] & 0x3F) + ((cmd_buff[0] >> 6) & 0x3F); - - std::string error = "unknown/unimplemented function '%s': port=%s"; - for (int i = 1; i <= num_params; ++i) { - error += Common::StringFromFormat(", cmd_buff[%i]=%u", i, cmd_buff[i]); - } - - std::string name = (itr == m_functions.end()) ? Common::StringFromFormat("0x%08X", cmd_buff[0]) : itr->second.name; - - LOG_ERROR(Service, error.c_str(), name.c_str(), GetPortName().c_str()); + std::string function_name = (itr == m_functions.end()) ? Common::StringFromFormat("0x%08X", cmd_buff[0]) : itr->second.name; + LOG_ERROR(Service, "%s %s", "unknown/unimplemented", MakeFunctionString(function_name, GetPortName(), cmd_buff).c_str()); // TODO(bunnei): Hack - ignore error cmd_buff[1] = 0; return MakeResult(false); + } else { + LOG_TRACE(Service, "%s", MakeFunctionString(itr->second.name, GetPortName(), cmd_buff).c_str()); } itr->second.func(this); diff --git a/src/core/hle/service/srv.cpp b/src/core/hle/service/srv.cpp index 912b52adf7..ac5f30a282 100644 --- a/src/core/hle/service/srv.cpp +++ b/src/core/hle/service/srv.cpp @@ -14,16 +14,12 @@ namespace SRV { static Handle g_event_handle = 0; static void Initialize(Service::Interface* self) { - LOG_DEBUG(Service_SRV, "called"); - u32* cmd_buff = Kernel::GetCommandBuffer(); cmd_buff[1] = 0; // No error } static void GetProcSemaphore(Service::Interface* self) { - LOG_TRACE(Service_SRV, "called"); - u32* cmd_buff = Kernel::GetCommandBuffer(); // TODO(bunnei): Change to a semaphore once these have been implemented diff --git a/src/core/hle/svc.cpp b/src/core/hle/svc.cpp index ba620bd0f0..d3b4483ca6 100644 --- a/src/core/hle/svc.cpp +++ b/src/core/hle/svc.cpp @@ -185,7 +185,6 @@ static Result WaitSynchronizationN(s32* out, Handle* handles, s32 handle_count, /// Create an address arbiter (to allocate access to shared resources) static Result CreateAddressArbiter(u32* arbiter) { - LOG_TRACE(Kernel_SVC, "called"); Handle handle = Kernel::CreateAddressArbiter(); *arbiter = handle; return 0; From 95be6ad7aead770666d97309e2e1aef9cfd808ec Mon Sep 17 00:00:00 2001 From: archshift Date: Sat, 10 Jan 2015 13:21:01 -0800 Subject: [PATCH 2/2] Added Archive ID to fs:USER debug logs involving opening the archive. --- src/core/hle/service/fs/fs_user.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/core/hle/service/fs/fs_user.cpp b/src/core/hle/service/fs/fs_user.cpp index 40dd0df2c8..56f3117f49 100644 --- a/src/core/hle/service/fs/fs_user.cpp +++ b/src/core/hle/service/fs/fs_user.cpp @@ -102,8 +102,8 @@ static void OpenFileDirectly(Service::Interface* self) { FileSys::Path archive_path(archivename_type, archivename_size, archivename_ptr); FileSys::Path file_path(filename_type, filename_size, filename_ptr); - LOG_DEBUG(Service_FS, "archive_path=%s file_path=%s, mode=%u attributes=%d", - archive_path.DebugStr().c_str(), file_path.DebugStr().c_str(), mode.hex, attributes); + LOG_DEBUG(Service_FS, "archive_id=0x%08X archive_path=%s file_path=%s, mode=%u attributes=%d", + archive_id, archive_path.DebugStr().c_str(), file_path.DebugStr().c_str(), mode.hex, attributes); ResultVal archive_handle = OpenArchive(archive_id, archive_path); if (archive_handle.Failed()) { @@ -365,7 +365,7 @@ static void OpenArchive(Service::Interface* self) { u32 archivename_ptr = cmd_buff[5]; FileSys::Path archive_path(archivename_type, archivename_size, archivename_ptr); - LOG_DEBUG(Service_FS, "archive_path=%s", archive_path.DebugStr().c_str()); + LOG_DEBUG(Service_FS, "archive_id=0x%08X archive_path=%s", archive_id, archive_path.DebugStr().c_str()); ResultVal handle = OpenArchive(archive_id, archive_path); cmd_buff[1] = handle.Code().raw;