Logging: Log all called service functions (under trace). Compile out all trace logs under release for performance.

12 files changed, 30 insertions, 57 deletions

diff --git a/src/common/common.h b/src/common/common.h
index bf48ae66..3246c779 100644
--- a/src/common/common.h
+++ b/src/common/common.h
@@ -11,13 +11,6 @@
 #include <cstdio>
 #include <cstring>
 
-// 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 667f2fbb..b397cf14 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 bda3d633..3d94bf0d 100644
--- a/src/common/logging/log.h
+++ b/src/common/logging/log.h
@@ -74,17 +74,6 @@ enum class Class : ClassType {
 };
 
 /**
- * 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
  * messages, reducing unecessary recompilations.
@@ -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 0e9c213e..82dcf5bb 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<const T*>(static_cast<const void*>(&storage));
 #endif
     }
diff --git a/src/core/hle/service/apt_u.cpp b/src/core/hle/service/apt_u.cpp
index d8b261ba..d0ff4e58 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 7eb32146..40dd0df2 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 26a43217..2b115240 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 8ef9af9d..1403b1de 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 fd79cd8a..753180ad 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 41ba1e55..e75d5008 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<bool>(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 912b52ad..ac5f30a2 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 ba620bd0..d3b4483c 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;