Menu
▾
▴
[OMPT-svn-commit] SF.net SVN: modplug:[4408] trunk/OpenMPT
|
From: <man...@us...> - 2014-10-10 13:23:26
|
Revision: 4408
http://sourceforge.net/p/modplug/code/4408
Author: manxorist
Date: 2014-10-10 13:23:10 +0000 (Fri, 10 Oct 2014)
Log Message:
-----------
[Ref] Debug: Add a low overhead threadsafe trace logging system which gets always compiled in, even in release builds. The actual logging has to be enabled explicitely via [Debug]TraceEnable and is written out (when it had been enabled beforehand) at the same time when a crash minidump is written out, and, if a debugger is present, when an always-assert fires. When disabled, the runtime overhead is a single predicted branch per trace point. When enabled, the runtime overhead is a single predicted branch, a 32bit atomic increment, GetCurrentThreadId(), QueryPerformanceCounter() and a memcpy of less than a single cacheline. The executable size overhead is one string per file that contains trace points (the filename), one string for each function that contains trace points (the function name), and 4 bytes for each trace point (the line number). The current implementation is not suitable for very high thread counts and/or multi-socket SMP systems (because of cacheline bouncing of the atomic variable), and is not suitable to be used in innerloops in hot paths (where the overhead is no longer negligable). The runtime memory overhead, if enabled, is about 32MB by default (1000000 entries in trace buffer, can be changed via [Debug]TraceSize), and about zero otherwise. MPT_TRACE() adds a trace point.
Modified Paths:
--------------
trunk/OpenMPT/common/Logging.cpp
trunk/OpenMPT/common/Logging.h
trunk/OpenMPT/mptrack/ExceptionHandler.cpp
trunk/OpenMPT/mptrack/MainFrm.cpp
trunk/OpenMPT/mptrack/Mptrack.cpp
trunk/OpenMPT/mptrack/TrackerSettings.cpp
trunk/OpenMPT/mptrack/TrackerSettings.h
Modified: trunk/OpenMPT/common/Logging.cpp
===================================================================
--- trunk/OpenMPT/common/Logging.cpp 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/common/Logging.cpp 2014-10-10 13:23:10 UTC (rev 4408)
@@ -12,6 +12,10 @@
#include "Logging.h"
#include "mptFstream.h"
+#if defined(MODPLUG_TRACKER)
+#include "mptAtomic.h"
+#endif
+#include "version.h"
#include <iostream>
#include <cstring>
@@ -29,52 +33,28 @@
{
-#ifndef NO_LOGGING
-
-
static const std::size_t LOGBUF_SIZE = 1024;
-Context::Context(const char *file, int line, const char *function)
-//----------------------------------------------------------------
- : file(file)
- , line(line)
- , function(function)
-{
- return;
-}
-
-
-Context::Context(const Context &c)
-//--------------------------------
- : file(c.file)
- , line(c.line)
- , function(c.function)
-{
- return;
-}
-
-
#if defined(MODPLUG_TRACKER)
-
-static uint64 GetTimeMS()
-//-----------------------
+static uint64 GetTime100ns()
+//--------------------------
{
FILETIME filetime;
GetSystemTimeAsFileTime(&filetime);
- return ((uint64)filetime.dwHighDateTime << 32 | filetime.dwLowDateTime) / 10000;
+ return ((uint64)filetime.dwHighDateTime << 32 | filetime.dwLowDateTime);
}
-static std::string TimeAsAsString(uint64 ms)
-//------------------------------------------
+static std::string TimeAsString(uint64 time100ns)
+//-------------------------------------------------
{
FILETIME filetime;
SYSTEMTIME systime;
- filetime.dwHighDateTime = (DWORD)(((uint64)ms * 10000) >> 32);
- filetime.dwLowDateTime = (DWORD)((uint64)ms * 10000);
+ filetime.dwHighDateTime = (DWORD)(((uint64)time100ns) >> 32);
+ filetime.dwLowDateTime = (DWORD)((uint64)time100ns);
FileTimeToSystemTime(&filetime, &systime);
std::string result;
@@ -92,7 +72,15 @@
return result;
}
+#endif // MODPLUG_TRACKER
+
+#ifndef NO_LOGGING
+
+
+#if defined(MODPLUG_TRACKER)
+
+
static std::string TimeDiffAsString(uint64 ms)
//--------------------------------------------
{
@@ -117,9 +105,9 @@
message = mpt::String::RTrim(message, MPT_USTRING("\r\n"));
#if defined(MODPLUG_TRACKER)
static uint64_t s_lastlogtime = 0;
- uint64 cur = GetTimeMS();
- uint64 diff = cur - s_lastlogtime;
- s_lastlogtime = cur;
+ uint64 cur = GetTime100ns();
+ uint64 diff = cur/10000 - s_lastlogtime;
+ s_lastlogtime = cur/10000;
#ifdef LOG_TO_FILE
{
static FILE * s_logfile = nullptr;
@@ -129,7 +117,7 @@
}
if(s_logfile)
{
- fprintf(s_logfile, "%s+%s %s(%i): %s [%s]\n", TimeAsAsString(cur).c_str(), TimeDiffAsString(diff).c_str(), context.file, context.line, mpt::ToCharset(mpt::CharsetUTF8, message).c_str(), context.function);
+ fprintf(s_logfile, "%s+%s %s(%i): %s [%s]\n", TimeAsString(cur).c_str(), TimeDiffAsString(diff).c_str(), context.file, context.line, mpt::ToCharset(mpt::CharsetUTF8, message).c_str(), context.function);
fflush(s_logfile);
}
}
@@ -212,6 +200,211 @@
#endif // !NO_LOGGING
+
+#if defined(MODPLUG_TRACKER)
+
+namespace Trace {
+
+// Debugging functionality will use simple globals.
+
+bool volatile g_Enabled = false;
+
+static bool g_Sealed = false;
+
+struct Entry {
+ uint32 Index;
+ uint32 ThreadId;
+ uint64 Timestamp;
+ const char * Function;
+ const char * File;
+ int Line;
+};
+
+inline bool operator < (const Entry &a, const Entry &b)
+{
+/*
+ return false
+ || (a.Timestamp < b.Timestamp)
+ || (a.ThreadID < b.ThreadID)
+ || (a.File < b.File)
+ || (a.Line < b.Line)
+ || (a.Function < b.Function)
+ ;
+*/
+ return false
+ || (a.Index < b.Index)
+ ;
+}
+
+static std::vector<mpt::log::Trace::Entry> Entries;
+
+static mpt::atomic_uint32_t NextIndex = 0;
+
+static uint32 ThreadIdGUI = 0;
+static uint32 ThreadIdAudio = 0;
+static uint32 ThreadIdNotify = 0;
+
+void Enable(std::size_t numEntries)
+{
+ if(g_Sealed)
+ {
+ return;
+ }
+ Entries.clear();
+ Entries.resize(numEntries);
+ NextIndex.store(0);
+ g_Enabled = true;
+}
+
+void Disable()
+{
+ if(g_Sealed)
+ {
+ return;
+ }
+ g_Enabled = false;
+}
+
+noinline void Trace(const mpt::log::Context & context)
+{
+ // This will get called in realtime contexts and hot paths.
+ // No blocking allowed here.
+ const uint32 index = NextIndex.fetch_add(1);
+#if 1
+ LARGE_INTEGER time;
+ time.QuadPart = 0;
+ QueryPerformanceCounter(&time);
+ const uint64 timestamp = time.QuadPart;
+#else
+ FILETIME time = FILETIME();
+ GetSystemTimeAsFileTime(&time);
+ const uint64 timestamp = (static_cast<uint64>(time.dwHighDateTime) << 32) | (static_cast<uint64>(time.dwLowDateTime) << 0);
+#endif
+ const uint32 threadid = static_cast<uint32>(GetCurrentThreadId());
+ mpt::log::Trace::Entry & entry = Entries[index % Entries.size()];
+ entry.Index = index;
+ entry.ThreadId = threadid;
+ entry.Timestamp = timestamp;
+ entry.Function = context.function;
+ entry.File = context.file;
+ entry.Line = context.line;
+}
+
+void Seal()
+{
+ if(!g_Enabled)
+ {
+ return;
+ }
+ g_Enabled = false;
+ g_Sealed = true;
+ uint32 count = NextIndex.fetch_add(0);
+ if(count < Entries.size())
+ {
+ Entries.resize(count);
+ }
+}
+
+bool Dump(const mpt::PathString &filename)
+{
+ if(!g_Sealed)
+ {
+ return false;
+ }
+
+ LARGE_INTEGER qpcNow;
+ qpcNow.QuadPart = 0;
+ QueryPerformanceCounter(&qpcNow);
+ uint64 ftNow = GetTime100ns();
+
+ // sort according to index in case of overflows
+ std::stable_sort(Entries.begin(), Entries.end());
+
+ WCHAR tmp[1024];
+ GetCurrentDirectoryW(1023, tmp);
+
+ mpt::ofstream f(filename, std::ios::out);
+
+ f << "Build: OpenMPT " << MptVersion::GetVersionStringExtended() << std::endl;
+
+ bool qpcValid = false;
+
+ LARGE_INTEGER qpcFreq;
+ qpcFreq.QuadPart = 0;
+ QueryPerformanceFrequency(&qpcFreq);
+ if(qpcFreq.QuadPart > 0)
+ {
+ qpcValid = true;
+ }
+
+ f << "Dump: " << TimeAsString(ftNow) << std::endl;
+ f << "Captured events: " << Entries.size() << std::endl;
+ if(qpcValid && (Entries.size() > 0))
+ {
+ double period = static_cast<double>(Entries[Entries.size() - 1].Timestamp - Entries[0].Timestamp) / static_cast<double>(qpcFreq.QuadPart);
+ double eventsPerSecond = Entries.size() / period;
+ f << "Period [s]: " << mpt::fmt::fix(period) << std::endl;
+ f << "Events/second: " << mpt::fmt::fix(eventsPerSecond) << std::endl;
+ }
+
+ for(std::size_t i = 0; i < Entries.size(); ++i)
+ {
+ mpt::log::Trace::Entry & entry = Entries[i];
+ if(!entry.Function) entry.Function = "";
+ if(!entry.File) entry.File = "";
+ std::string time;
+ if(qpcValid)
+ {
+ time = TimeAsString( ftNow - static_cast<int64>( static_cast<double>(qpcNow.QuadPart - entry.Timestamp) * (10000000.0 / static_cast<double>(qpcFreq.QuadPart) ) ) );
+ } else
+ {
+ time = mpt::String::Print<std::string>("0x%1", mpt::fmt::hex0<16>(entry.Timestamp));
+ }
+ f << time;
+ if(entry.ThreadId == ThreadIdGUI)
+ {
+ f << " -----GUI ";
+ } else if(entry.ThreadId == ThreadIdAudio)
+ {
+ f << " ---Audio ";
+ } else if(entry.ThreadId == ThreadIdNotify)
+ {
+ f << " --Notify ";
+ } else
+ {
+ f << " " << mpt::fmt::hex0<8>(entry.ThreadId) << " ";
+ }
+ f << entry.File << "(" << entry.Line << "): " << entry.Function;
+ f << std::endl;
+ }
+ return true;
+}
+
+void SetThreadId(mpt::log::Trace::ThreadKind kind, uint32 id)
+{
+ if(id == 0)
+ {
+ return;
+ }
+ switch(kind)
+ {
+ case ThreadKindGUI:
+ ThreadIdGUI = id;
+ break;
+ case ThreadKindAudio:
+ ThreadIdAudio = id;
+ break;
+ case ThreadKindNotify:
+ ThreadIdNotify = id;
+ break;
+ }
+}
+
+} // namespace Trace
+
+#endif // MODPLUG_TRACKER
+
+
} // namespace log
} // namespace mpt
Modified: trunk/OpenMPT/common/Logging.h
===================================================================
--- trunk/OpenMPT/common/Logging.h 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/common/Logging.h 2014-10-10 13:23:10 UTC (rev 4408)
@@ -51,23 +51,32 @@
{
-#ifndef NO_LOGGING
-
-
-class Context
+struct Context
{
-public:
const char * const file;
const int line;
const char * const function;
-public:
- Context(const char *file, int line, const char *function);
- Context(const Context &c);
+ forceinline Context(const char *file, int line, const char *function)
+ : file(file)
+ , line(line)
+ , function(function)
+ {
+ return;
+ }
+ forceinline Context(const Context &c)
+ : file(c.file)
+ , line(c.line)
+ , function(c.function)
+ {
+ return;
+ }
}; // class Context
#define MPT_LOG_CURRENTCONTEXT() mpt::log::Context( __FILE__ , __LINE__ , __FUNCTION__ )
+#ifndef NO_LOGGING
+
class Logger
{
private:
@@ -85,10 +94,8 @@
#define Log mpt::log::Logger(MPT_LOG_CURRENTCONTEXT())
-
#else // !NO_LOGGING
-
class Logger
{
public:
@@ -103,10 +110,51 @@
#define Log if(true) {} else mpt::log::Logger() // completely compile out arguments to Log() so that they do not even get evaluated
-
#endif // NO_LOGGING
+
+#if defined(MODPLUG_TRACKER)
+
+namespace Trace {
+
+// This is not strictly thread safe in all corner cases because of missing barriers.
+// We do not care in order to not harm the fast path with additional barriers.
+// Enabled tracing incurs a runtime overhead with multiple threads as a global atomic variable
+// gets modified.
+// This cacheline bouncing does not matter at all
+// if there are not multiple thread adding trace points at high frequency (way greater than 1000Hz),
+// which, in OpenMPT, is only ever the case for just a single thread (the audio thread), if at all.
+extern bool volatile g_Enabled;
+
+noinline void Trace(const mpt::log::Context & contexxt);
+
+enum ThreadKind {
+ ThreadKindGUI,
+ ThreadKindAudio,
+ ThreadKindNotify,
+};
+
+void Enable(std::size_t numEntries);
+void Disable();
+
+void SetThreadId(mpt::log::Trace::ThreadKind kind, uint32 id);
+
+void Seal();
+bool Dump(const mpt::PathString &filename);
+
+#define MPT_TRACE() do { if(mpt::log::Trace::g_Enabled) { mpt::log::Trace::Trace(MPT_LOG_CURRENTCONTEXT()); } } while(0)
+
+} // namespace Trace
+
+#else // !MODPLUG_TRACKER
+
+#define MPT_TRACE() do { } while(0)
+
+#endif // MODPLUG_TRACKER
+
+
+
} // namespace log
} // namespace mpt
Modified: trunk/OpenMPT/mptrack/ExceptionHandler.cpp
===================================================================
--- trunk/OpenMPT/mptrack/ExceptionHandler.cpp 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/mptrack/ExceptionHandler.cpp 2014-10-10 13:23:10 UTC (rev 4408)
@@ -33,6 +33,10 @@
static void GenerateDump(CString &errorMessage, _EXCEPTION_POINTERS *pExceptionInfo=NULL, DumpMode mode=DumpModeCrash)
//--------------------------------------------------------------------------------------------------------------------
{
+
+ // seal the trace log as early as possible
+ mpt::log::Trace::Seal();
+
CMainFrame* pMainFrame = CMainFrame::GetMainFrame();
const mpt::PathString timestampDir = mpt::PathString::FromCStringSilent((CTime::GetCurrentTime()).Format("%Y-%m-%d %H.%M.%S\\"));
@@ -52,10 +56,28 @@
}
}
+ bool hasWrittenDebug = false;
+
// Create minidump...
- const mpt::PathString filename = baseRescuePath + MPT_PATHSTRING("crash.dmp");
- if(WriteMemoryDump(pExceptionInfo, filename.AsNative().c_str(), ExceptionHandler::fullMemDump))
{
+ const mpt::PathString filename = baseRescuePath + MPT_PATHSTRING("crash.dmp");
+ if(WriteMemoryDump(pExceptionInfo, filename.AsNative().c_str(), ExceptionHandler::fullMemDump))
+ {
+ hasWrittenDebug = true;
+ }
+ }
+
+ // Create trace log...
+ {
+ const mpt::PathString filename = baseRescuePath + MPT_PATHSTRING("trace.log");
+ if(mpt::log::Trace::Dump(filename))
+ {
+ hasWrittenDebug = true;
+ }
+ }
+
+ if(hasWrittenDebug)
+ {
errorMessage += "\n\nDebug information has been saved to\n"
+ mpt::ToCString(baseRescuePath.ToWide());
}
@@ -116,6 +138,10 @@
LONG ExceptionHandler::UnhandledExceptionFilter(_EXCEPTION_POINTERS *pExceptionInfo)
//----------------------------------------------------------------------------------
{
+
+ // seal the trace log as early as possible
+ mpt::log::Trace::Seal();
+
// Shut down audio device...
CMainFrame* pMainFrame = CMainFrame::GetMainFrame();
if(pMainFrame)
@@ -151,8 +177,12 @@
noinline void AssertHandler(const char *file, int line, const char *function, const char *expr, const char *msg)
//--------------------------------------------------------------------------------------------------------------
{
+ // seal the trace log as early as possible
+ mpt::log::Trace::Seal();
+
if(IsDebuggerPresent())
{
+ mpt::log::Trace::Dump(MPT_PATHSTRING("mptrack.trace.log"));
OutputDebugString("ASSERT(");
OutputDebugString(expr);
OutputDebugString(") failed\n");
Modified: trunk/OpenMPT/mptrack/MainFrm.cpp
===================================================================
--- trunk/OpenMPT/mptrack/MainFrm.cpp 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/mptrack/MainFrm.cpp 2014-10-10 13:23:10 UTC (rev 4408)
@@ -674,6 +674,7 @@
CriticalSection cs;
ALWAYS_ASSERT(m_pSndFile != nullptr);
m_AudioThreadId = GetCurrentThreadId();
+ mpt::log::Trace::SetThreadId(mpt::log::Trace::ThreadKindAudio, m_AudioThreadId);
callback.FillAudioBuffer();
m_AudioThreadId = 0;
}
Modified: trunk/OpenMPT/mptrack/Mptrack.cpp
===================================================================
--- trunk/OpenMPT/mptrack/Mptrack.cpp 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/mptrack/Mptrack.cpp 2014-10-10 13:23:10 UTC (rev 4408)
@@ -651,7 +651,8 @@
#endif
m_GuiThreadId = GetCurrentThreadId();
-
+ mpt::log::Trace::SetThreadId(mpt::log::Trace::ThreadKindGUI, m_GuiThreadId);
+
ExceptionHandler::Register();
m_bPortableMode = false;
@@ -901,6 +902,13 @@
m_pTrackerSettings = new TrackerSettings(*m_pSettings);
+ // enable debug features (as early as possible after reading the settings)
+ if(TrackerSettings::Instance().DebugTraceEnable)
+ {
+ mpt::log::Trace::Enable(TrackerSettings::Instance().DebugTraceSize);
+ }
+ MPT_TRACE();
+
m_pPluginCache = new IniFileSettingsContainer(m_szPluginCacheFileName);
LoadStdProfileSettings(0); // Load standard INI file options (without MRU)
Modified: trunk/OpenMPT/mptrack/TrackerSettings.cpp
===================================================================
--- trunk/OpenMPT/mptrack/TrackerSettings.cpp 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/mptrack/TrackerSettings.cpp 2014-10-10 13:23:10 UTC (rev 4408)
@@ -225,6 +225,8 @@
, mruListLength(conf, "Misc", "MRUListLength", 10)
// Plugins
, bridgeAllPlugins(conf, "VST Plugins", "BridgeAllPlugins", false)
+ , DebugTraceEnable(conf, "Debug", "TraceEnable", false)
+ , DebugTraceSize(conf, "Debug", "TraceSize", 1000000)
{
// Effects
#ifndef NO_DSP
Modified: trunk/OpenMPT/mptrack/TrackerSettings.h
===================================================================
--- trunk/OpenMPT/mptrack/TrackerSettings.h 2014-10-09 08:13:13 UTC (rev 4407)
+++ trunk/OpenMPT/mptrack/TrackerSettings.h 2014-10-10 13:23:10 UTC (rev 4408)
@@ -468,18 +468,27 @@
// Paths
mpt::PathString m_szKbdFile;
+
// Default template
+
Setting<mpt::PathString> defaultTemplateFile;
Setting<uint32> mruListLength;
std::vector<mpt::PathString> mruFiles;
// Chords
+
MPTChords Chords;
// Plugins
+
Setting<bool> bridgeAllPlugins;
+ // Debug
+
+ Setting<bool> DebugTraceEnable;
+ Setting<uint32> DebugTraceSize;
+
public:
TrackerSettings(SettingsContainer &conf);
This was sent by the SourceForge.net collaborative development platform, the world's largest Open Source development site.
|
