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

This commit is contained in:
archshift 2015-01-10 13:07:50 -08:00
parent 083072de56
commit 228843c43e
12 changed files with 30 additions and 57 deletions

View file

@ -11,13 +11,6 @@
#include <cstdio> #include <cstdio>
#include <cstring> #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 #define STACKALIGN
// An inheritable class to disallow the copy constructor and operator= functions // An inheritable class to disallow the copy constructor and operator= functions

View file

@ -14,7 +14,7 @@
#endif #endif
#endif #endif
#if _DEBUG #ifdef _DEBUG
#define _dbg_assert_(_t_, _a_) \ #define _dbg_assert_(_t_, _a_) \
if (!(_a_)) {\ if (!(_a_)) {\
LOG_CRITICAL(_t_, "Error...\n\n Line: %d\n File: %s\n Time: %s\n\nIgnore and continue?", \ LOG_CRITICAL(_t_, "Error...\n\n Line: %d\n File: %s\n Time: %s\n\nIgnore and continue?", \

View file

@ -73,17 +73,6 @@ enum class Class : ClassType {
Count ///< Total number of logging classes 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 * 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 * 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 } // namespace Log
#define LOG_GENERIC(log_class, log_level, ...) \ #define LOG_GENERIC(log_class, log_level, ...) \
do { \ ::Log::LogMessage(::Log::Class::log_class, ::Log::Level::log_level, \
if (::Log::Level::log_level >= ::Log::MINIMUM_LEVEL) \ __FILE__, __LINE__, __func__, __VA_ARGS__)
::Log::LogMessage(::Log::Class::log_class, ::Log::Level::log_level, \
__FILE__, __LINE__, __func__, __VA_ARGS__); \
} while (0)
#ifdef _DEBUG
#define LOG_TRACE( log_class, ...) LOG_GENERIC(log_class, Trace, __VA_ARGS__) #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_DEBUG( log_class, ...) LOG_GENERIC(log_class, Debug, __VA_ARGS__)
#define LOG_INFO( log_class, ...) LOG_GENERIC(log_class, Info, __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__) #define LOG_WARNING( log_class, ...) LOG_GENERIC(log_class, Warning, __VA_ARGS__)

View file

@ -369,14 +369,14 @@ private:
StorageType storage; StorageType storage;
ResultCode result_code; ResultCode result_code;
#if _DEBUG #ifdef _DEBUG
// The purpose of this pointer is to aid inspecting the type with a debugger, eliminating the // 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`. // need to cast `storage` to a pointer or pay attention to `result_code`.
const T* debug_ptr; const T* debug_ptr;
#endif #endif
void UpdateDebugPtr() { void UpdateDebugPtr() {
#if _DEBUG #ifdef _DEBUG
debug_ptr = empty() ? nullptr : static_cast<const T*>(static_cast<const void*>(&storage)); debug_ptr = empty() ? nullptr : static_cast<const T*>(static_cast<const void*>(&storage));
#endif #endif
} }

View file

@ -52,8 +52,6 @@ void Initialize(Service::Interface* self) {
Kernel::ReleaseMutex(lock_handle); Kernel::ReleaseMutex(lock_handle);
cmd_buff[1] = 0; // No error cmd_buff[1] = 0; // No error
LOG_DEBUG(Service_APT, "called");
} }
void GetLockHandle(Service::Interface* self) { void GetLockHandle(Service::Interface* self) {
@ -194,8 +192,6 @@ void AppletUtility(Service::Interface* self) {
* 4 : Handle to shared font memory * 4 : Handle to shared font memory
*/ */
void GetSharedFont(Service::Interface* self) { void GetSharedFont(Service::Interface* self) {
LOG_TRACE(Kernel_SVC, "called");
u32* cmd_buff = Kernel::GetCommandBuffer(); u32* cmd_buff = Kernel::GetCommandBuffer();
if (!shared_font.empty()) { if (!shared_font.empty()) {

View file

@ -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 // TODO(Link Mauve): check the behavior when cmd_buff[1] isn't 32, as per
// http://3dbrew.org/wiki/FS:Initialize#Request // http://3dbrew.org/wiki/FS:Initialize#Request
cmd_buff[1] = RESULT_SUCCESS.raw; 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[1] = 0;
cmd_buff[2] = Settings::values.use_virtual_sd ? 1 : 0; cmd_buff[2] = Settings::values.use_virtual_sd ? 1 : 0;
LOG_DEBUG(Service_FS, "called");
} }
/** /**

View file

@ -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. /// This triggers handling of the GX command written to the command buffer in shared memory.
static void TriggerCmdReqQueue(Service::Interface* self) { static void TriggerCmdReqQueue(Service::Interface* self) {
LOG_TRACE(Service_GSP, "called");
// Iterate through each thread's command queue... // Iterate through each thread's command queue...
for (unsigned thread_id = 0; thread_id < 0x4; ++thread_id) { for (unsigned thread_id = 0; thread_id < 0x4; ++thread_id) {
CommandBuffer* command_buffer = (CommandBuffer*)GetCommandBuffer(thread_id); CommandBuffer* command_buffer = (CommandBuffer*)GetCommandBuffer(thread_id);

View file

@ -163,8 +163,6 @@ static void GetIPCHandles(Service::Interface* self) {
cmd_buff[6] = event_accelerometer; cmd_buff[6] = event_accelerometer;
cmd_buff[7] = event_gyroscope; cmd_buff[7] = event_gyroscope;
cmd_buff[8] = event_debug_pad; cmd_buff[8] = event_debug_pad;
LOG_TRACE(Service_HID, "called");
} }
const Interface::FunctionInfo FunctionTable[] = { const Interface::FunctionInfo FunctionTable[] = {

View file

@ -76,8 +76,6 @@ static void GetShellState(Service::Interface* self) {
cmd_buff[1] = 0; cmd_buff[1] = 0;
cmd_buff[2] = shell_open ? 1 : 0; cmd_buff[2] = shell_open ? 1 : 0;
LOG_TRACE(Service_PTM, "PTM_U::GetShellState called");
} }
/** /**

View file

@ -33,6 +33,22 @@ class Interface : public Kernel::Session {
// processes. // processes.
friend class Manager; 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: public:
std::string GetName() const override { return GetPortName(); } std::string GetName() const override { return GetPortName(); }
@ -72,21 +88,14 @@ public:
auto itr = m_functions.find(cmd_buff[0]); auto itr = m_functions.find(cmd_buff[0]);
if (itr == m_functions.end() || itr->second.func == nullptr) { if (itr == m_functions.end() || itr->second.func == nullptr) {
// Number of params == bits 0-5 + bits 6-11 std::string function_name = (itr == m_functions.end()) ? Common::StringFromFormat("0x%08X", cmd_buff[0]) : itr->second.name;
int num_params = (cmd_buff[0] & 0x3F) + ((cmd_buff[0] >> 6) & 0x3F); LOG_ERROR(Service, "%s %s", "unknown/unimplemented", MakeFunctionString(function_name, GetPortName(), cmd_buff).c_str());
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());
// TODO(bunnei): Hack - ignore error // TODO(bunnei): Hack - ignore error
cmd_buff[1] = 0; cmd_buff[1] = 0;
return MakeResult<bool>(false); return MakeResult<bool>(false);
} else {
LOG_TRACE(Service, "%s", MakeFunctionString(itr->second.name, GetPortName(), cmd_buff).c_str());
} }
itr->second.func(this); itr->second.func(this);

View file

@ -14,16 +14,12 @@ namespace SRV {
static Handle g_event_handle = 0; static Handle g_event_handle = 0;
static void Initialize(Service::Interface* self) { static void Initialize(Service::Interface* self) {
LOG_DEBUG(Service_SRV, "called");
u32* cmd_buff = Kernel::GetCommandBuffer(); u32* cmd_buff = Kernel::GetCommandBuffer();
cmd_buff[1] = 0; // No error cmd_buff[1] = 0; // No error
} }
static void GetProcSemaphore(Service::Interface* self) { static void GetProcSemaphore(Service::Interface* self) {
LOG_TRACE(Service_SRV, "called");
u32* cmd_buff = Kernel::GetCommandBuffer(); u32* cmd_buff = Kernel::GetCommandBuffer();
// TODO(bunnei): Change to a semaphore once these have been implemented // TODO(bunnei): Change to a semaphore once these have been implemented

View file

@ -185,7 +185,6 @@ static Result WaitSynchronizationN(s32* out, Handle* handles, s32 handle_count,
/// Create an address arbiter (to allocate access to shared resources) /// Create an address arbiter (to allocate access to shared resources)
static Result CreateAddressArbiter(u32* arbiter) { static Result CreateAddressArbiter(u32* arbiter) {
LOG_TRACE(Kernel_SVC, "called");
Handle handle = Kernel::CreateAddressArbiter(); Handle handle = Kernel::CreateAddressArbiter();
*arbiter = handle; *arbiter = handle;
return 0; return 0;