From 1f866d2c3bac3dcd3e8f4cf20452db162a2d5832 Mon Sep 17 00:00:00 2001 From: Peter Sollich Date: Thu, 25 Feb 2021 14:37:24 +0100 Subject: [PATCH] Dprintf optimization (#47046) This is support for putting the stress log into a memory mapped file and piping the dprintf calls in the GC codebase to the stress log. It's much faster than the dprintf implementation we used before and doesn't take a lock for each dprintf call - only when it needs to get a new buffer. It also works for clrgc.dll, which accounts for some complications, because now calls can come from either coreclr.dll or clrgc.dll. There is logic inside src/coreclr/util/StressLog.cpp to switch to the memory mapped file when the new environment variable COMPLUS_StressLogFilename is set. Here's a set of environment variables I've used: COMPLUS_StressLogFilename=GCPerfSimStresslog.log COMPLUS_gcServer=1 COMPLUS_LogLevel=9 COMPlus_StressLog=1 COMPlus_StressLogSize=10000000 COMPlus_TotalStressLogSize=1000000000 So this creates a max of 64 GB of stress log. There is an analyzer tool to go with this under src/coreclr/tools/StressLogAnalyzer that is also part of this checkin. The tool is expected to become more sophisticated over time. The tool is itself multithreaded and uses a plugin dll for the actual analysis which makes it possible to change the plugin, rebuild and re-run the analysis on the in-memory log datastructure without reloading the log file. The stresslog mechanism had a limit of 7 arguments so far, which seemed too small, so I've increased that to 12 currently. It can easily be increased up to 63, which is the limit in the format. The higher number of arguments is only supported when putting the stress log into a file, it is not yet supported when building the stress log in memory the traditional way. Supporting it would call for changes in SOS that I haven't done yet. However, stress logs containing no calls of more than 7 arguments would be dumped correctly by the current SOS - SOS would crash though with stress logs containing calls with more arguments. To catch this early, the logic in StressLog.cpp does a debug break when a call with more than 7 arguments is attempted without the memory-mapped file. Note that for the purposes of GC logging, the logging level specified in the dprintf call is also persisted in the stress log. This makes it possible to selectively dump messages from specific subsystems. --- src/coreclr/gc/env/gcenv.ee.h | 1 + src/coreclr/gc/env/gcenv.h | 472 ++++++- src/coreclr/gc/gc.cpp | 49 +- src/coreclr/gc/gcenv.ee.standalone.inl | 7 + src/coreclr/gc/gcinterface.ee.h | 5 + src/coreclr/gc/gcpriv.h | 4 +- src/coreclr/gc/sample/gcenv.h | 2 +- src/coreclr/inc/clrconfigvalues.h | 1 + src/coreclr/inc/stresslog.h | 447 +++++- .../tools/StressLogAnalyzer/StressLogAnalyzer.cpp | 187 +++ .../tools/StressLogAnalyzer/StressLogAnalyzer.sln | 44 + .../StressLogAnalyzer/StressLogAnalyzer.vcxproj | 149 ++ .../StressLogAnalyzer.vcxproj.filters | 22 + .../StressLogAnalyzer.vcxproj.users | 11 + .../StressLogPlugin/StressLogPlugin.cpp | 1417 ++++++++++++++++++++ .../StressLogPlugin/StressLogPlugin.vcxproj | 174 +++ .../StressLogPlugin.vcxproj.filters | 36 + .../StressLogAnalyzer/StressLogPlugin/framework.h | 8 + .../StressLogAnalyzer/StressLogPlugin/pch.cpp | 6 + .../tools/StressLogAnalyzer/StressLogPlugin/pch.h | 8 + .../StressLogPlugin/staticcontract.h | 6 + .../StressLogPlugin/stressLogDump.cpp | 564 ++++++++ .../StressLogAnalyzer/StressLogPlugin/strike.h | 67 + .../tools/StressLogAnalyzer/StressLogPlugin/util.h | 159 +++ src/coreclr/utilcode/stresslog.cpp | 299 ++++- src/coreclr/vm/ceemain.cpp | 5 +- src/coreclr/vm/gcenv.ee.cpp | 6 + src/coreclr/vm/gcenv.ee.h | 2 + src/coreclr/vm/gcheaputilities.cpp | 2 + 29 files changed, 4040 insertions(+), 120 deletions(-) create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.cpp create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.sln create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.filters create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.users create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.cpp create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj.filters create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/framework.h create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.cpp create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.h create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/staticcontract.h create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/stressLogDump.cpp create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/strike.h create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/util.h diff --git a/src/coreclr/gc/env/gcenv.ee.h b/src/coreclr/gc/env/gcenv.ee.h index d596575..aa08054 100644 --- a/src/coreclr/gc/env/gcenv.ee.h +++ b/src/coreclr/gc/env/gcenv.ee.h @@ -90,6 +90,7 @@ public: static void VerifySyncTableEntry(); static void UpdateGCEventStatus(int publicLevel, int publicKeywords, int privateLevel, int privateKeywords); + static void LogStressMsg(unsigned level, unsigned facility, const StressLogMsg &msg); }; #endif // __GCENV_EE_H__ diff --git a/src/coreclr/gc/env/gcenv.h b/src/coreclr/gc/env/gcenv.h index d874d30..6a6b1c3 100644 --- a/src/coreclr/gc/env/gcenv.h +++ b/src/coreclr/gc/env/gcenv.h @@ -40,6 +40,474 @@ #define POP_WARNING_STATE #endif // _MSC_VER +#define STRESS_LOG +#ifdef STRESS_LOG +/* STRESS_LOG_VA was added to allow sendign GC trace output to the stress log. msg must be enclosed + in ()'s and contain a format string followed by 0 - 4 arguments. The arguments must be numbers or + string literals. LogMsgOL is overloaded so that all of the possible sets of parameters are covered. + This was done becasue GC Trace uses dprintf which dosen't contain info on how many arguments are + getting passed in and using va_args would require parsing the format string during the GC +*/ +#define STRESS_LOG_VA(level, msg) do { \ + if (StressLog::LogOn(LF_GC, LL_ALWAYS)) \ + StressLog::LogMsg(level, StressLogMsg msg); \ + LOGALWAYS(msg); \ + } while(0) + +#define STRESS_LOG0(facility, level, msg) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, StressLogMsg(msg)); \ + LOG((facility, level, msg)); \ + } while(0) + +#define STRESS_LOG1(facility, level, msg, data1) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, \ + StressLogMsg(msg, (void*)(size_t)(data1))); \ + LOG((facility, level, msg, data1)); \ + } while(0) + +#define STRESS_LOG2(facility, level, msg, data1, data2) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, \ + StressLogMsg(msg, (void*)(size_t)(data1), (void*)(size_t)(data2))); \ + LOG((facility, level, msg, data1, data2)); \ + } while(0) + +#define STRESS_LOG2_CHECK_EE_STARTED(facility, level, msg, data1, data2) do { \ + if (g_fEEStarted) \ + STRESS_LOG2(facility, level, msg, data1, data2); \ + else \ + LOG((facility, level, msg, data1, data2)); \ + } while(0) + +#define STRESS_LOG3(facility, level, msg, data1, data2, data3) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, \ + StressLogMsg(msg, \ + (void*)(size_t)(data1),(void*)(size_t)(data2),(void*)(size_t)(data3))); \ + LOG((facility, level, msg, data1, data2, data3)); \ + } while(0) + +#define STRESS_LOG4(facility, level, msg, data1, data2, data3, data4) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, \ + StressLogMsg(msg, (void*)(size_t)(data1),(void*)(size_t)(data2), \ + (void*)(size_t)(data3),(void*)(size_t)(data4))); \ + LOG((facility, level, msg, data1, data2, data3, data4)); \ + } while(0) + +#define STRESS_LOG5(facility, level, msg, data1, data2, data3, data4, data5) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, 5, msg, (void*)(size_t)(data1), \ + (void*)(size_t)(data2),(void*)(size_t)(data3),(void*)(size_t)(data4), \ + (void*)(size_t)(data5)); \ + LOG((facility, level, msg, data1, data2, data3, data4, data5)); \ + } while(0) + +#define STRESS_LOG6(facility, level, msg, data1, data2, data3, data4, data5, data6) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, 6, msg, (void*)(size_t)(data1), \ + (void*)(size_t)(data2),(void*)(size_t)(data3),(void*)(size_t)(data4), \ + (void*)(size_t)(data5), (void*)(size_t)(data6)); \ + LOG((facility, level, msg, data1, data2, data3, data4, data5, data6)); \ + } while(0) + +#define STRESS_LOG7(facility, level, msg, data1, data2, data3, data4, data5, data6, data7) do { \ + if (StressLog::LogOn(facility, level)) \ + StressLog::LogMsg(level, facility, 7, msg, (void*)(size_t)(data1), \ + (void*)(size_t)(data2),(void*)(size_t)(data3),(void*)(size_t)(data4), \ + (void*)(size_t)(data5), (void*)(size_t)(data6), (void*)(size_t)(data7)); \ + LOG((facility, level, msg, data1, data2, data3, data4, data5, data6, data7)); \ + } while(0) + +#define LOGALWAYS(msg) + +#define static_assert_no_msg( cond ) static_assert( cond, #cond ) + +enum LogFacility +{ + LF_GC = 0x00000001, + LF_GCALLOC = 0x00000100, + LF_GCROOTS = 0x00080000, + LF_ALWAYS = 0x80000000, +}; + +enum LogLevel +{ + LL_ALWAYS, + LL_FATALERROR, + LL_ERROR, + LL_WARNING, + LL_INFO10, // can be expected to generate 10 logs per small but not trival run + LL_INFO100, // can be expected to generate 100 logs per small but not trival run + LL_INFO1000, // can be expected to generate 1,000 logs per small but not trival run + LL_INFO10000, // can be expected to generate 10,000 logs per small but not trival run + LL_INFO100000, // can be expected to generate 100,000 logs per small but not trival run + LL_INFO1000000, // can be expected to generate 1,000,000 logs per small but not trival run + LL_EVERYTHING, +}; + +#define STRESS_LOG_PLUG_MOVE(plug_start, plug_end, plug_delta) do { \ + if (StressLog::LogOn(LF_GC, LL_INFO1000)) \ + StressLog::LogMsg(LL_INFO1000, LF_GC, \ + StressLogMsg(ThreadStressLog::gcPlugMoveMsg(), \ + (void*)(size_t)(plug_start), (void*)(size_t)(plug_end), (void*)(size_t)(plug_delta))); \ + LOG((LF_GC, LL_INFO10000, ThreadStressLog::gcPlugMoveMsg(), (plug_start), (plug_end), (plug_delta))); \ + } while(0) + +#define STRESS_LOG_ROOT_PROMOTE(root_addr, objPtr, methodTable) do { \ + if (StressLog::LogOn(LF_GC|LF_GCROOTS, LL_INFO1000)) \ + StressLog::LogMsg(LL_INFO1000, LF_GC|LF_GCROOTS, \ + StressLogMsg(ThreadStressLog::gcRootPromoteMsg(), \ + (void*)(size_t)(root_addr), (void*)(size_t)(objPtr), (void*)(size_t)(methodTable))); \ + LOG((LF_GC|LF_GCROOTS, LL_INFO1000000, ThreadStressLog::gcRootPromoteMsg(), (root_addr), (objPtr), (methodTable))); \ + } while(0) + +#define STRESS_LOG_ROOT_RELOCATE(root_addr, old_value, new_value, methodTable) do { \ + if (StressLog::LogOn(LF_GC|LF_GCROOTS, LL_INFO1000) && ((size_t)(old_value) != (size_t)(new_value))) \ + StressLog::LogMsg(LL_INFO1000, LF_GC|LF_GCROOTS, \ + StressLogMsg(ThreadStressLog::gcRootMsg(), \ + (void*)(size_t)(root_addr), (void*)(size_t)(old_value), \ + (void*)(size_t)(new_value), (void*)(size_t)(methodTable))); \ + LOG((LF_GC|LF_GCROOTS, LL_INFO10000, ThreadStressLog::gcRootMsg(), (root_addr), (old_value), (new_value), (methodTable))); \ + } while(0) + +#define STRESS_LOG_GC_START(gcCount, Gen, collectClasses) do { \ + if (StressLog::LogOn(LF_GCROOTS|LF_GC|LF_GCALLOC, LL_INFO10)) \ + StressLog::LogMsg(LL_INFO10, LF_GCROOTS|LF_GC|LF_GCALLOC, \ + StressLogMsg(ThreadStressLog::gcStartMsg(), \ + (void*)(size_t)(gcCount), (void*)(size_t)(Gen), (void*)(size_t)(collectClasses))); \ + LOG((LF_GCROOTS|LF_GC|LF_GCALLOC, LL_INFO10, ThreadStressLog::gcStartMsg(), (gcCount), (Gen), (collectClasses))); \ + } while(0) + +#define STRESS_LOG_GC_END(gcCount, Gen, collectClasses) do { \ + if (StressLog::LogOn(LF_GCROOTS|LF_GC|LF_GCALLOC, LL_INFO10)) \ + StressLog::LogMsg(LL_INFO10, LF_GCROOTS|LF_GC|LF_GCALLOC, \ + StressLogMsg(ThreadStressLog::gcEndMsg(), \ + (void*)(size_t)(gcCount), (void*)(size_t)(Gen), (void*)(size_t)(collectClasses), 0)); \ + LOG((LF_GCROOTS|LF_GC|LF_GCALLOC, LL_INFO10, ThreadStressLog::gcEndMsg(), (gcCount), (Gen), (collectClasses))); \ + } while(0) + +#define STRESS_LOG_OOM_STACK(size) +#define STRESS_LOG_GC_STACK + +class ThreadStressLog +{ +public: + static const char* gcStartMsg() + { + STATIC_CONTRACT_LEAF; + return "{ =========== BEGINGC %d, (requested generation = %lu, collect_classes = %lu) ==========\n"; + } + + static const char* gcEndMsg() + { + STATIC_CONTRACT_LEAF; + return "========== ENDGC %d (gen = %lu, collect_classes = %lu) ===========}\n"; + } + + static const char* gcRootMsg() + { + STATIC_CONTRACT_LEAF; + return " GC Root %p RELOCATED %p -> %p MT = %pT\n"; + } + + static const char* gcRootPromoteMsg() + { + STATIC_CONTRACT_LEAF; + return " IGCHeap::Promote: Promote GC Root *%p = %p MT = %pT\n"; + } + + static const char* gcPlugMoveMsg() + { + STATIC_CONTRACT_LEAF; + return "GC_HEAP RELOCATING Objects in heap within range [%p %p) by -0x%x bytes\n"; + } + + static const char* gcServerThread0StartMsg() + { + STATIC_CONTRACT_LEAF; + return "%d gc thread waiting..."; + } + + static const char* gcServerThreadNStartMsg() + { + STATIC_CONTRACT_LEAF; + return "%d gc thread waiting... Done"; + } + + static const char* gcDetailedStartMsg() + { + STATIC_CONTRACT_LEAF; + return "*GC* %d(gen0:%d)(%d)(alloc: %Id)(%s)(%d)"; + } + + static const char* gcDetailedEndMsg() + { + STATIC_CONTRACT_LEAF; + return "*EGC* %Id(gen0:%Id)(%Id)(%d)(%s)(%s)(%s)(ml: %d->%d)"; + } + + static const char* gcStartMarkMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Mark Phase on heap %d condemning %d ----"; + } + + static const char* gcStartPlanMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Plan Phase on heap %d ---- Condemned generation %d, promotion: %d"; + } + + static const char* gcStartRelocateMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Relocate phase on heap %d -----"; + } + + static const char* gcEndRelocateMsg() + { + STATIC_CONTRACT_LEAF; + return "---- End of Relocate phase on heap %d ----"; + } + + static const char* gcStartCompactMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Compact Phase on heap %d: %Ix(%Ix)----"; + } + + static const char* gcEndCompactMsg() + { + STATIC_CONTRACT_LEAF; + return "---- End of Compact phase on heap %d ----"; + } + + static const char* gcMemCopyMsg() + { + STATIC_CONTRACT_LEAF; + return " mc: [%Ix->%Ix, %Ix->%Ix["; + } + + static const char* gcPlanPlugMsg() + { + STATIC_CONTRACT_LEAF; + return "(%Ix)[%Ix->%Ix, NA: [%Ix(%Id), %Ix[: %Ix(%d), x: %Ix (%s)"; + } + + static const char* gcPlanPinnedPlugMsg() + { + STATIC_CONTRACT_LEAF; + return "(%Ix)PP: [%Ix, %Ix[%Ix](m:%d)"; + } + + static const char* gcDesiredNewAllocationMsg() + { + STATIC_CONTRACT_LEAF; + return "h%d g%d surv: %Id current: %Id alloc: %Id (%d%%) f: %d%% new-size: %Id new-alloc: %Id"; + } + + static const char* gcMakeUnusedArrayMsg() + { + STATIC_CONTRACT_LEAF; + return "Making unused array [%Ix, %Ix["; + } + + static const char* gcStartBgcThread() + { + STATIC_CONTRACT_LEAF; + return "beginning of bgc on heap %d: gen2 FL: %d, FO: %d, frag: %d"; + } +}; + +struct StressLogMsg +{ + int m_cArgs; + const char* m_format; + void* m_args[16]; + + StressLogMsg(const char* format) : m_cArgs(0), m_format(format) + { + } + + template < typename T1 > + StressLogMsg(const char* format, T1 data1) : m_cArgs(1), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + } + + template < typename T1, typename T2 > + StressLogMsg(const char* format, T1 data1, T2 data2) : m_cArgs(2), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + } + + template < typename T1, typename T2, typename T3 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3) : m_cArgs(3), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + } + + template < typename T1, typename T2, typename T3, typename T4 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4) : m_cArgs(4), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5) : m_cArgs(5), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6) : m_cArgs(6), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7) : m_cArgs(7), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8) : m_cArgs(8), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9) : m_cArgs(9), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10) : m_cArgs(10), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + m_args[9] = (void*)(size_t)data10; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10, typename T11 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10, T11 data11) : m_cArgs(11), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*) && sizeof(T11) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + m_args[9] = (void*)(size_t)data10; + m_args[10] = (void*)(size_t)data11; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10, typename T11, typename T12 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10, T11 data11, T12 data12) : m_cArgs(12), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*) && sizeof(T11) <= sizeof(void*) && sizeof(T12) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + m_args[9] = (void*)(size_t)data10; + m_args[10] = (void*)(size_t)data11; + m_args[11] = (void*)(size_t)data12; + } +}; + +class StressLog +{ +public: + static bool LogOn(unsigned, unsigned) + { + return true; + } + + static BOOL StressLogOn(unsigned facility, unsigned level) + { + return true; + } + + static void LogMsg(unsigned dprintfLevel, const StressLogMsg& msg) + { + GCToEEInterface::LogStressMsg(LL_ALWAYS, LF_ALWAYS|(dprintfLevel<<16)|LF_GC, msg); + } + + static void LogMsg(unsigned level, unsigned facility, const StressLogMsg& msg) + { + GCToEEInterface::LogStressMsg(level, facility, msg); + } + +}; +#else #define WHILE_0 \ SUPPRESS_WARNING_4127 \ while(0) \ @@ -47,7 +515,7 @@ #define LL_INFO10 4 -#define STRESS_LOG_VA(msg) do { } WHILE_0 +#define STRESS_LOG_VA(level,msg) do { } WHILE_0 #define STRESS_LOG0(facility, level, msg) do { } WHILE_0 #define STRESS_LOG1(facility, level, msg, data1) do { } WHILE_0 #define STRESS_LOG2(facility, level, msg, data1, data2) do { } WHILE_0 @@ -65,6 +533,8 @@ #define STRESS_LOG_RESERVE_MEM(numChunks) do {} while (0) #define STRESS_LOG_GC_STACK +#endif // USE_STRESS_LOG + #define LOG(x) #define SVAL_IMPL_INIT(type, cls, var, init) \ diff --git a/src/coreclr/gc/gc.cpp b/src/coreclr/gc/gc.cpp index 73dd3f6..873b238 100644 --- a/src/coreclr/gc/gc.cpp +++ b/src/coreclr/gc/gc.cpp @@ -6325,12 +6325,12 @@ void gc_heap::gc_thread_function () settings.init_mechanisms(); gc_start_event.Set(); } - dprintf (3, ("%d gc thread waiting...", heap_number)); + dprintf (3, (ThreadStressLog::gcServerThread0StartMsg(), heap_number)); } else { gc_start_event.Wait(INFINITE, FALSE); - dprintf (3, ("%d gc thread waiting... Done", heap_number)); + dprintf (3, (ThreadStressLog::gcServerThreadNStartMsg(), heap_number)); } assert ((heap_number == 0) || proceed_with_gc_p); @@ -22858,7 +22858,7 @@ void gc_heap::mark_phase (int condemned_gen_number, BOOL mark_only_p) sc.promotion = TRUE; sc.concurrent = FALSE; - dprintf(2,("---- Mark Phase condemning %d ----", condemned_gen_number)); + dprintf (2, (ThreadStressLog::gcStartMarkMsg(), heap_number, condemned_gen_number)); BOOL full_p = (condemned_gen_number == max_generation); int gen_to_init = condemned_gen_number; @@ -25185,7 +25185,7 @@ void gc_heap::plan_phase (int condemned_gen_number) assert (settings.concurrent == FALSE); - dprintf (2,("---- Plan Phase ---- Condemned generation %d, promotion: %d", + dprintf (2,(ThreadStressLog::gcStartPlanMsg(), heap_number, condemned_gen_number, settings.promotion ? 1 : 0)); generation* condemned_gen1 = generation_of (condemned_gen_number); @@ -25936,14 +25936,12 @@ void gc_heap::plan_phase (int condemned_gen_number) } else { -#ifdef SIMPLE_DPRINTF - dprintf (3, ("(%Ix)[%Ix->%Ix, NA: [%Ix(%Id), %Ix[: %Ix(%d), x: %Ix (%s)", + dprintf (3, (ThreadStressLog::gcPlanPlugMsg(), (size_t)(node_gap_size (plug_start)), plug_start, plug_end, (size_t)new_address, (size_t)(plug_start - new_address), (size_t)new_address + ps, ps, (is_plug_padded (plug_start) ? 1 : 0), x, (allocated_in_older_p ? "O" : "C"))); -#endif //SIMPLE_DPRINTF #ifdef SHORT_PLUGS if (is_plug_padded (plug_start)) @@ -25976,7 +25974,7 @@ void gc_heap::plan_phase (int condemned_gen_number) new_address = plug_start; - dprintf (3, ( "(%Ix)PP: [%Ix, %Ix[%Ix](m:%d)", + dprintf (3, (ThreadStressLog::gcPlanPinnedPlugMsg(), (size_t)(node_gap_size (plug_start)), (size_t)plug_start, (size_t)plug_end, ps, (merge_with_last_pin_p ? 1 : 0))); @@ -27592,7 +27590,6 @@ void gc_heap::make_free_lists (int condemned_gen_number) } // We need to get a new region for the new gen0. - assert (num_free_regions > 0); generation* gen_gen0 = generation_of (0); heap_segment* gen0_region = get_free_region (0); thread_start_region (gen_gen0, gen0_region); @@ -27764,7 +27761,7 @@ void gc_heap::uoh_thread_gap_front (uint8_t* gap_start, size_t size, generation* void gc_heap::make_unused_array (uint8_t* x, size_t size, BOOL clearp, BOOL resetp) { - dprintf (3, ("Making unused array [%Ix, %Ix[", + dprintf (3, (ThreadStressLog::gcMakeUnusedArrayMsg(), (size_t)x, (size_t)(x+size))); assert (size >= Align (min_obj_size)); @@ -28799,7 +28796,7 @@ void gc_heap::relocate_phase (int condemned_gen_number, } #endif //MULTIPLE_HEAPS - dprintf (2,("---- Relocate phase -----")); + dprintf (2, (ThreadStressLog::gcStartRelocateMsg(), heap_number)); dprintf(3,("Relocating roots")); GCScan::GcScanRoots(GCHeap::Relocate, @@ -28942,7 +28939,7 @@ void gc_heap::relocate_phase (int condemned_gen_number, } #endif // MULTIPLE_HEAPS && FEATURE_CARD_MARKING_STEALING - dprintf(2,( "---- End of Relocate phase ----")); + dprintf(2, (ThreadStressLog::gcEndRelocateMsg(), heap_number)); } // This compares to see if tree is the current pinned plug and returns info @@ -29045,7 +29042,7 @@ void gc_heap::gcmemcopy (uint8_t* dest, uint8_t* src, size_t len, BOOL copy_car #endif //DOUBLY_LINKED_FL //dprintf(3,(" Memcopy [%Ix->%Ix, %Ix->%Ix[", (size_t)src, (size_t)dest, (size_t)src+len, (size_t)dest+len)); - dprintf(3,(" mc: [%Ix->%Ix, %Ix->%Ix[", (size_t)src, (size_t)dest, (size_t)src+len, (size_t)dest+len)); + dprintf(3,(ThreadStressLog::gcMemCopyMsg(), (size_t)src, (size_t)dest, (size_t)src+len, (size_t)dest+len)); memcopy (dest - plug_skew, src - plug_skew, len); #ifdef DOUBLY_LINKED_FL @@ -29375,7 +29372,7 @@ void gc_heap::compact_phase (int condemned_gen_number, } #endif //MULTIPLE_HEAPS - dprintf (2,("---- Compact Phase: %Ix(%Ix)----", + dprintf (2, (ThreadStressLog::gcStartCompactMsg(), heap_number, first_condemned_address, brick_of (first_condemned_address))); #ifdef FEATURE_LOH_COMPACTION @@ -29496,7 +29493,7 @@ void gc_heap::compact_phase (int condemned_gen_number, concurrent_print_time_delta ("compact end"); - dprintf(2,("---- End of Compact phase ----")); + dprintf (2, (ThreadStressLog::gcEndCompactMsg(), heap_number)); } #ifdef MULTIPLE_HEAPS @@ -31516,7 +31513,7 @@ void gc_heap::bgc_thread_function() break; } gc_background_running = TRUE; - dprintf (2, ("beginning of bgc: gen2 FL: %d, FO: %d, frag: %d", + dprintf (2, (ThreadStressLog::gcStartBgcThread(), heap_number, generation_free_list_space (generation_of (max_generation)), generation_free_obj_space (generation_of (max_generation)), dd_fragmentation (dynamic_data_of (max_generation)))); @@ -35588,16 +35585,9 @@ size_t gc_heap::desired_new_allocation (dynamic_data* dd, dd_surv (dd) = cst; -#ifdef SIMPLE_DPRINTF - dprintf (1, ("h%d g%d surv: %Id current: %Id alloc: %Id (%d%%) f: %d%% new-size: %Id new-alloc: %Id", + dprintf (1, (ThreadStressLog::gcDesiredNewAllocationMsg(), heap_number, gen_number, out, current_size, (dd_desired_allocation (dd) - dd_gc_new_allocation (dd)), (int)(cst*100), (int)(f*100), current_size + new_allocation, new_allocation)); -#else - dprintf (1,("gen: %d in: %Id out: %Id ", gen_number, generation_allocation_size (generation_of (gen_number)), out)); - dprintf (1,("current: %Id alloc: %Id ", current_size, (dd_desired_allocation (dd) - dd_gc_new_allocation (dd)))); - dprintf (1,(" surv: %d%% f: %d%% new-size: %Id new-alloc: %Id", - (int)(cst*100), (int)(f*100), current_size + new_allocation, new_allocation)); -#endif //SIMPLE_DPRINTF return new_allocation_ret; } @@ -38618,9 +38608,8 @@ void gc_heap::descr_generations (const char* msg) (settings.heap_expansion ? "(EX)" : " "), (settings.promotion ? "Promotion" : "NoPromotion"))); #else - dprintf (2, ( "Generation %d: gap size: %d, generation size: %Id, fragmentation: %Id", + dprintf (2, ( "Generation %d: generation size: %Id, fragmentation: %Id", curr_gen_number, - size (generation_allocation_start (generation_of (curr_gen_number))), total_gen_size, dd_fragmentation (dynamic_data_of (curr_gen_number)))); #endif //SIMPLE_DPRINTF @@ -41243,7 +41232,7 @@ void gc_heap::do_pre_gc() #ifdef TRACE_GC size_t total_allocated_since_last_gc = get_total_allocated_since_last_gc(); #ifdef BACKGROUND_GC - dprintf (1, ("*GC* %d(gen0:%d)(%d)(alloc: %Id)(%s)(%d)", + dprintf (1, (ThreadStressLog::gcDetailedStartMsg(), VolatileLoad(&settings.gc_index), dd_collection_count (hp->dynamic_data_of (0)), settings.condemned_generation, @@ -41660,8 +41649,7 @@ void gc_heap::do_post_gc() } #endif //BGC_SERVO_TUNING -#ifdef SIMPLE_DPRINTF - dprintf (1, ("*EGC* %Id(gen0:%Id)(%Id)(%d)(%s)(%s)(%s)(ml: %d->%d)", + dprintf (1, (ThreadStressLog::gcDetailedEndMsg(), VolatileLoad(&settings.gc_index), dd_collection_count(hp->dynamic_data_of(0)), (size_t)(GetHighPrecisionTimeStamp() / 1000), @@ -41671,7 +41659,6 @@ void gc_heap::do_post_gc() (settings.promotion ? "P" : "S"), settings.entry_memory_load, current_memory_load)); -#endif //SIMPLE_DPRINTF // Now record the gc info. last_recorded_gc_info* last_gc_info = 0; @@ -42792,7 +42779,7 @@ CFinalize::RegisterForFinalization (int gen, Object* obj, size_t size) { // If the object is uninitialized, a valid size should have been passed. assert (size >= Align (min_obj_size)); - dprintf (3, ("Making unused array [%Ix, %Ix[", (size_t)obj, (size_t)(obj+size))); + dprintf (3, (ThreadStressLog::gcMakeUnusedArrayMsg(), (size_t)obj, (size_t)(obj+size))); ((CObjectHeader*)obj)->SetFree(size); } STRESS_LOG_OOM_STACK(0); diff --git a/src/coreclr/gc/gcenv.ee.standalone.inl b/src/coreclr/gc/gcenv.ee.standalone.inl index f14b327..e9c51c9 100644 --- a/src/coreclr/gc/gcenv.ee.standalone.inl +++ b/src/coreclr/gc/gcenv.ee.standalone.inl @@ -11,6 +11,8 @@ // will be fowarded to this interface instance. extern IGCToCLR* g_theGCToCLR; +struct StressLogMsg; + // When we are building the GC in a standalone environment, we // will be dispatching virtually against g_theGCToCLR to call // into the EE. This class provides an identical API to the existing @@ -294,4 +296,9 @@ inline void GCToEEInterface::UpdateGCEventStatus(int publicLevel, int publicKeyw #endif // __linux__ } +inline void GCToEEInterface::LogStressMsg(unsigned level, unsigned facility, const StressLogMsg & msg) +{ + g_theGCToCLR->LogStressMsg(level, facility, msg); +} + #endif // __GCTOENV_EE_STANDALONE_INL__ diff --git a/src/coreclr/gc/gcinterface.ee.h b/src/coreclr/gc/gcinterface.ee.h index f61fdf5..3639085 100644 --- a/src/coreclr/gc/gcinterface.ee.h +++ b/src/coreclr/gc/gcinterface.ee.h @@ -20,6 +20,8 @@ enum EtwGCRootKind kEtwGCRootKindOther = 3, }; +struct StressLogMsg; + // This interface provides functions that the GC can use to fire events. // Events fired on this interface are split into two categories: "known" // events and "dynamic" events. Known events are events that are baked-in @@ -421,6 +423,9 @@ public: virtual void UpdateGCEventStatus(int publicLevel, int publicKeywords, int privateLEvel, int privateKeywords) = 0; + + virtual + void LogStressMsg(unsigned level, unsigned facility, const StressLogMsg& msg) = 0; }; #endif // _GCINTERFACE_EE_H_ diff --git a/src/coreclr/gc/gcpriv.h b/src/coreclr/gc/gcpriv.h index 53b3c1b..937f265 100644 --- a/src/coreclr/gc/gcpriv.h +++ b/src/coreclr/gc/gcpriv.h @@ -269,8 +269,8 @@ void GCLog (const char *fmt, ... ); // Nobody used the logging mechanism that used to be here. If we find ourselves // wanting to inspect GC logs on unmodified builds, we can use this define here // to do so. -#define dprintf(l, x) -//#define dprintf(l,x) STRESS_LOG_VA(x); +//#define dprintf(l, x) +#define dprintf(l,x) STRESS_LOG_VA(l,x); #endif //SIMPLE_DPRINTF diff --git a/src/coreclr/gc/sample/gcenv.h b/src/coreclr/gc/sample/gcenv.h index 2c8f5ab..33be21e 100644 --- a/src/coreclr/gc/sample/gcenv.h +++ b/src/coreclr/gc/sample/gcenv.h @@ -60,7 +60,7 @@ #define LL_INFO10 4 -#define STRESS_LOG_VA(msg) do { } WHILE_0 +#define STRESS_LOG_VA(level,msg) do { } WHILE_0 #define STRESS_LOG0(facility, level, msg) do { } WHILE_0 #define STRESS_LOG1(facility, level, msg, data1) do { } WHILE_0 #define STRESS_LOG2(facility, level, msg, data1, data2) do { } WHILE_0 diff --git a/src/coreclr/inc/clrconfigvalues.h b/src/coreclr/inc/clrconfigvalues.h index 74f5ac2..c6fc463 100644 --- a/src/coreclr/inc/clrconfigvalues.h +++ b/src/coreclr/inc/clrconfigvalues.h @@ -547,6 +547,7 @@ CONFIG_DWORD_INFO_EX(INTERNAL_StressCOMCall, W("StressCOMCall"), 0, "", CLRConfi RETAIL_CONFIG_DWORD_INFO_DIRECT_ACCESS(UNSUPPORTED_StressLog, W("StressLog"), "Turns on the stress log.") RETAIL_CONFIG_DWORD_INFO_DIRECT_ACCESS(UNSUPPORTED_ForceEnc, W("ForceEnc"), "Forces Edit and Continue to be on for all eligible modules.") RETAIL_CONFIG_DWORD_INFO_DIRECT_ACCESS(UNSUPPORTED_StressLogSize, W("StressLogSize"), "Stress log size in bytes per thread.") +RETAIL_CONFIG_STRING_INFO_DIRECT_ACCESS(UNSUPPORTED_StressLogFilename, W("StressLogFilename"), "Stress log filename for memory mapped stress log.") CONFIG_DWORD_INFO_EX(INTERNAL_stressSynchronized, W("stressSynchronized"), 0, "Unknown if or where this is used; unless a test is specifically depending on this, it can be removed.", CLRConfig::EEConfig_default) RETAIL_CONFIG_DWORD_INFO_DIRECT_ACCESS(EXTERNAL_StressThreadCount, W("StressThreadCount"), "") diff --git a/src/coreclr/inc/stresslog.h b/src/coreclr/inc/stresslog.h index 4858f6f..706f3c9 100644 --- a/src/coreclr/inc/stresslog.h +++ b/src/coreclr/inc/stresslog.h @@ -31,6 +31,7 @@ #include "log.h" #if defined(STRESS_LOG) && !defined(FEATURE_NO_STRESSLOG) +#ifndef STRESS_LOG_ANALYZER #include "holder.h" #include "staticcontract.h" #include "mscoree.h" @@ -44,6 +45,7 @@ #ifndef _ASSERTE #define _ASSERTE(expr) #endif +#endif // STRESS_LOG_ANALYZER /* The STRESS_LOG* macros work like printf. In fact the use printf in their implementation so all printf format specifications work. In addition the Stress log dumper knows @@ -61,10 +63,10 @@ This was done becasue GC Trace uses dprintf which dosen't contain info on how many arguments are getting passed in and using va_args would require parsing the format string during the GC */ -#define STRESS_LOG_VA(msg) do { \ - if (StressLog::LogOn(LF_GC, LL_ALWAYS)) \ - StressLog::LogMsgOL msg; \ - LOGALWAYS(msg); \ +#define STRESS_LOG_VA(dprintfLevel,msg) do { \ + if (StressLog::LogOn(LF_GC, LL_ALWAYS)) \ + StressLog::LogMsg(LL_ALWAYS, LF_ALWAYS|(dprintfLevel<<16)|LF_GC, StressLogMsg msg); \ + LOGALWAYS(msg); \ } while(0) #define STRESS_LOG0(facility, level, msg) do { \ @@ -257,15 +259,18 @@ class ThreadStressLog; +struct StressLogMsg; + /*************************************************************************************/ /* a log is a circular queue of messages */ class StressLog { public: static void Initialize(unsigned facilities, unsigned level, unsigned maxBytesPerThread, - unsigned maxBytesTotal, void* moduleBase); + ULONGLONG maxBytesTotal, void* moduleBase, LPWSTR logFilename = nullptr); static void Terminate(BOOL fProcessDetach=FALSE); static void ThreadDetach(); // call at DllMain THREAD_DETACH if you want to recycle thread logs +#ifndef STRESS_LOG_ANALYZER static int NewChunk () { return InterlockedIncrement (&theLog.totalChunk); @@ -274,8 +279,9 @@ public: { return InterlockedDecrement (&theLog.totalChunk); } +#endif //STRESS_LOG_ANALYZER - //the result is not 100% accurate. If multiple threads call this funciton at the same time, + //the result is not 100% accurate. If multiple threads call this function at the same time, //we could allow the total size be bigger than required. But the memory won't grow forever //and this is not critical so we don't try to fix the race static BOOL AllowNewChunk (LONG numChunksInCurThread); @@ -298,8 +304,8 @@ public: unsigned facilitiesToLog; // Bitvector of facilities to log (see loglf.h) unsigned levelToLog; // log level (see log.h) unsigned MaxSizePerThread; // maximum number of bytes each thread should have before wrapping - unsigned MaxSizeTotal; //maximum memory allowed for stress log - Volatile totalChunk; //current number of total chunks allocated + unsigned MaxSizeTotal; // maximum memory allowed for stress log + Volatile totalChunk; // current number of total chunks allocated Volatile logs; // the list of logs for every thread. unsigned padding; // Preserve the layout for SOS Volatile deadCount; // count of dead threads in the log @@ -308,6 +314,39 @@ public: unsigned __int64 startTimeStamp; // start time from when tick counter started FILETIME startTime; // time the application started SIZE_T moduleOffset; // Used to compute format strings. +#if defined(HOST_WINDOWS) && defined(HOST_64BIT) +#define MEMORY_MAPPED_STRESSLOG +#endif + +#ifdef MEMORY_MAPPED_STRESSLOG + MapViewHolder hMapView; + static void* AllocMemoryMapped(size_t n); + + struct ModuleDesc + { + uint8_t* baseAddress; + size_t size; + }; + static const size_t MAX_MODULES = 5; + struct StressLogHeader + { + size_t headerSize; // size of this header including size field and moduleImage + uint32_t magic; // must be 'STRL' + uint32_t version; // must be 0x00010001 + uint8_t* memoryBase; // base address of the memory mapped file + uint8_t* memoryCur; // highest address currently used + uint8_t* memoryLimit; // limit that can be used + Volatile logs; // the list of logs for every thread. + uint64_t tickFrequency; // number of ticks per second + uint64_t startTimeStamp; // start time from when tick counter started + uint64_t threadsWithNoLog; // threads that didn't get a log + uint64_t reserved[15]; // for future expansion + ModuleDesc modules[MAX_MODULES]; // descriptor of the modules images + uint8_t moduleImage[64*1024*1024];// copy of the module images described by modules field + }; + + StressLogHeader* stressLogHeader; // header to find things in the memory mapped file +#endif // MEMORY_MAPPED_STRESSLOG static thread_local ThreadStressLog* t_pCurrentThreadLog; @@ -322,6 +361,10 @@ public: static void LogMsg(unsigned level, unsigned facility, int cArgs, const char* format, ... ); + static void LogMsg(unsigned level, unsigned facility, const StressLogMsg& msg); + + static void AddModule(uint8_t* moduleBase); + // Support functions for STRESS_LOG_VA // We disable the warning "conversion from 'type' to 'type' of greater size" since everything will // end up on the stack, and LogMsg will know the size of the variable based on the format string. @@ -381,6 +424,41 @@ public: LogMsg(LL_ALWAYS, LF_GC, 7, format, (void*)(size_t)data1, (void*)(size_t)data2, (void*)(size_t)data3, (void*)(size_t)data4, (void*)(size_t)data5, (void*)(size_t)data6, (void*)(size_t)data7); } + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8 > + static void LogMsgOL(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*)); + LogMsg(LL_ALWAYS, LF_GC, 8, format, (void*)(size_t)data1, (void*)(size_t)data2, (void*)(size_t)data3, (void*)(size_t)data4, (void*)(size_t)data5, (void*)(size_t)data6, (void*)(size_t)data7, (void*)(size_t)data8); + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9 > + static void LogMsgOL(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*)); + LogMsg(LL_ALWAYS, LF_GC, 9, format, (void*)(size_t)data1, (void*)(size_t)data2, (void*)(size_t)data3, (void*)(size_t)data4, (void*)(size_t)data5, (void*)(size_t)data6, (void*)(size_t)data7, (void*)(size_t)data8, (void*)(size_t)data9); + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10 > + static void LogMsgOL(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*)); + LogMsg(LL_ALWAYS, LF_GC, 10, format, (void*)(size_t)data1, (void*)(size_t)data2, (void*)(size_t)data3, (void*)(size_t)data4, (void*)(size_t)data5, (void*)(size_t)data6, (void*)(size_t)data7, (void*)(size_t)data8, (void*)(size_t)data9, (void*)(size_t)data10); + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10, typename T11 > + static void LogMsgOL(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10, T11 data11) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*) && sizeof(T11) <= sizeof(void*)); + LogMsg(LL_ALWAYS, LF_GC, 11, format, (void*)(size_t)data1, (void*)(size_t)data2, (void*)(size_t)data3, (void*)(size_t)data4, (void*)(size_t)data5, (void*)(size_t)data6, (void*)(size_t)data7, (void*)(size_t)data8, (void*)(size_t)data9, (void*)(size_t)data10, (void*)(size_t)data11); + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10, typename T11, typename T12 > + static void LogMsgOL(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10, T11 data11, T12 data12) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*) && sizeof(T11) <= sizeof(void*) && sizeof(T12) <= sizeof(void*)); + LogMsg(LL_ALWAYS, LF_GC, 12, format, (void*)(size_t)data1, (void*)(size_t)data2, (void*)(size_t)data3, (void*)(size_t)data4, (void*)(size_t)data5, (void*)(size_t)data6, (void*)(size_t)data7, (void*)(size_t)data8, (void*)(size_t)data9, (void*)(size_t)data10, (void*)(size_t)data11, (void*)(size_t)data12); + } + #ifdef _MSC_VER #pragma warning( pop ) #endif @@ -403,7 +481,9 @@ typedef USHORT static StressLog theLog; // We only have one log, and this is it }; +#ifndef STRESS_LOG_ANALYZER typedef Holder> StressLogLockHolder; +#endif //!STRESS_LOG_ANALYZER #if defined(DACCESS_COMPILE) inline BOOL StressLog::LogOn(unsigned facility, unsigned level) @@ -427,10 +507,12 @@ inline BOOL StressLog::LogOn(unsigned facility, unsigned level) // And make sure the timeStamp field is naturally alligned, so we don't waste // space on 32-bit platforms struct StressMsg { + static const size_t formatOffsetBits = 26; union { struct { - uint32_t numberOfArgs : 3; // at most 7 arguments - uint32_t formatOffset : 29; // offset of string in mscorwks + uint32_t numberOfArgs : 3; // at most 7 arguments here + uint32_t formatOffset : formatOffsetBits; // offset of string in mscorwks + uint32_t numberOfArgsX : 3; // extend number of args in a backward compat way }; uint32_t fmtOffsCArgs; // for optimized access }; @@ -438,8 +520,8 @@ struct StressMsg { uint64_t timeStamp; // time when mssg was logged void* args[0]; // size given by numberOfArgs - static const size_t maxArgCnt = 7; - static const size_t maxOffset = 0x20000000; + static const size_t maxArgCnt = 63; + static const size_t maxOffset = 1 << formatOffsetBits; static size_t maxMsgSize () { return sizeof(StressMsg) + maxArgCnt*sizeof(void*); } @@ -473,15 +555,25 @@ struct StressLogChunk return NULL; } - _ASSERTE (s_LogChunkHeap != NULL); - //no need to zero memory because we could handle garbage contents - return HeapAlloc (s_LogChunkHeap, 0, size); + if (s_LogChunkHeap != NULL) + { + //no need to zero memory because we could handle garbage contents + return HeapAlloc(s_LogChunkHeap, 0, size); + } + else + { +#ifdef MEMORY_MAPPED_STRESSLOG + return StressLog::AllocMemoryMapped(size); +#else + return nullptr; +#endif //MEMORY_MAPPED_STRESSLOG + } } void operator delete (void * chunk) { - _ASSERTE (s_LogChunkHeap != NULL); - HeapFree (s_LogChunkHeap, 0, chunk); + if (s_LogChunkHeap != NULL) + HeapFree (s_LogChunkHeap, 0, chunk); } #else void* operator new (size_t size) throw() @@ -534,11 +626,14 @@ struct StressLogChunk // readPtr / curPtr fields. thecaller is responsible for reading/writing // to the corresponding field class ThreadStressLog { +#ifdef STRESS_LOG_ANALYZER +public: +#endif ThreadStressLog* next; // we keep a linked list of these uint64_t threadId; // the id for the thread using this buffer uint8_t isDead; // Is this thread dead - uint8_t readHasWrapped; // set when read ptr has passed chunListTail - uint8_t writeHasWrapped; // set when write ptr has passed chunListHead + uint8_t readHasWrapped; // set when read ptr has passed chunkListTail + uint8_t writeHasWrapped; // set when write ptr has passed chunkListHead StressMsg* curPtr; // where packets are being put on the queue StressMsg* readPtr; // where we are reading off the queue (used during dumping) StressLogChunk * chunkListHead; //head of a list of stress log chunks @@ -562,7 +657,7 @@ class ThreadStressLog { #endif //STRESS_LOG_READONLY friend class StressLog; -#ifndef STRESS_LOG_READONLY +#if !defined(STRESS_LOG_READONLY) && !defined(STRESS_LOG_ANALYZER) FORCEINLINE BOOL GrowChunkList () { _ASSERTE (chunkListLength >= 1); @@ -583,14 +678,14 @@ class ThreadStressLog { return TRUE; } -#endif //!STRESS_LOG_READONLY +#endif //!STRESS_LOG_READONLY && !STRESS_LOG_ANALYZER public: -#ifndef STRESS_LOG_READONLY +#if !defined(STRESS_LOG_READONLY) && !defined(STRESS_LOG_ANALYZER) ThreadStressLog () { chunkListHead = chunkListTail = curWriteChunk = NULL; - StressLogChunk * newChunk =new StressLogChunk; + StressLogChunk * newChunk = new StressLogChunk; //OOM or in cantalloc region if (newChunk == NULL) { @@ -614,7 +709,12 @@ public: chunkListLength = 1; } -#endif //!STRESS_LOG_READONLY +#endif //!STRESS_LOG_READONLY && !STRESS_LOG_ANALYZER + +#if defined(MEMORY_MAPPED_STRESSLOG) && !defined(STRESS_LOG_ANALYZER) + void* __cdecl operator new(size_t n, const NoThrow&) NOEXCEPT; +#endif + ~ThreadStressLog () { //no thing to do if the list is empty (failed to initialize) @@ -622,9 +722,9 @@ public: { return; } -#ifndef STRESS_LOG_READONLY +#if !defined(STRESS_LOG_READONLY) && !defined(STRESS_LOG_ANALYZER) _ASSERTE (chunkListLength >= 1 && chunkListLength <= StressLog::theLog.totalChunk); -#endif //!STRESS_LOG_READONLY +#endif //!STRESS_LOG_READONLY && !STRESS_LOG_ANALYZER StressLogChunk * chunk = chunkListHead; do @@ -632,9 +732,9 @@ public: StressLogChunk * tmp = chunk; chunk = chunk->next; delete tmp; -#ifndef STRESS_LOG_READONLY +#if !defined(STRESS_LOG_READONLY) && !defined(STRESS_LOG_ANALYZER) StressLog::ChunkDeleted (); -#endif //!STRESS_LOG_READONLY +#endif //!STRESS_LOG_READONLY && !STRESS_LOG_ANALYZER } while (chunk != chunkListHead); } @@ -715,20 +815,111 @@ public: return "GC_HEAP RELOCATING Objects in heap within range [%p %p) by -0x%x bytes\n"; } - static const char* TaskSwitchMsg() + static const char* gcServerThread0StartMsg() { STATIC_CONTRACT_LEAF; - return "StressLog TaskSwitch Marker\n"; + return "%d gc thread waiting..."; + } + + static const char* gcServerThreadNStartMsg() + { + STATIC_CONTRACT_LEAF; + return "%d gc thread waiting... Done"; + } + + static const char* gcDetailedStartMsg() + { + STATIC_CONTRACT_LEAF; + return "*GC* %d(gen0:%d)(%d)(alloc: %Id)(%s)(%d)"; + } + + static const char* gcDetailedEndMsg() + { + STATIC_CONTRACT_LEAF; + return "*EGC* %Id(gen0:%Id)(%Id)(%d)(%s)(%s)(%s)(ml: %d->%d)"; + } + + static const char* gcStartMarkMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Mark Phase on heap %d condemning %d ----"; + } + + static const char* gcStartPlanMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Plan Phase on heap %d ---- Condemned generation %d, promotion: %d"; + } + + static const char* gcStartRelocateMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Relocate phase on heap %d -----"; + } + + static const char* gcEndRelocateMsg() + { + STATIC_CONTRACT_LEAF; + return "---- End of Relocate phase on heap %d ----"; + } + + static const char* gcStartCompactMsg() + { + STATIC_CONTRACT_LEAF; + return "---- Compact Phase on heap %d: %Ix(%Ix)----"; + } + + static const char* gcEndCompactMsg() + { + STATIC_CONTRACT_LEAF; + return "---- End of Compact phase on heap %d ----"; + } + + static const char* gcMemCopyMsg() + { + STATIC_CONTRACT_LEAF; + return " mc: [%Ix->%Ix, %Ix->%Ix["; } - void LogMsg (unsigned facility, int cArgs, const char* format, ... ) + static const char* gcPlanPlugMsg() { - va_list Args; - va_start(Args, format); - LogMsg (facility, cArgs, format, Args); - va_end(Args); + STATIC_CONTRACT_LEAF; + return "(%Ix)[%Ix->%Ix, NA: [%Ix(%Id), %Ix[: %Ix(%d), x: %Ix (%s)"; + } + + static const char* gcPlanPinnedPlugMsg() + { + STATIC_CONTRACT_LEAF; + return "(%Ix)PP: [%Ix, %Ix[%Ix](m:%d)"; + } + + static const char* gcDesiredNewAllocationMsg() + { + STATIC_CONTRACT_LEAF; + return "h%d g%d surv: %Id current: %Id alloc: %Id (%d%%) f: %d%% new-size: %Id new-alloc: %Id"; + } + + static const char* gcMakeUnusedArrayMsg() + { + STATIC_CONTRACT_LEAF; + return "Making unused array [%Ix, %Ix["; + } + + static const char* gcStartBgcThread() + { + STATIC_CONTRACT_LEAF; + return "beginning of bgc on heap %d: gen2 FL: %d, FO: %d, frag: %d"; } - void LogMsg (unsigned facility, int cArgs, const char* format, va_list Args); + + static const char* TaskSwitchMsg() + { + STATIC_CONTRACT_LEAF; + return "StressLog TaskSwitch Marker\n"; + } + + void LogMsg(unsigned facility, int cArgs, const char* format, ...); + + FORCEINLINE void LogMsg (unsigned facility, int cArgs, const char* format, va_list Args); #ifdef STRESS_LOG_READONLY static size_t OffsetOfNext () {return offsetof (ThreadStressLog, next);} static size_t OffsetOfListHead () {return offsetof (ThreadStressLog, chunkListHead);} @@ -801,14 +992,12 @@ inline StressMsg* ThreadStressLog::AdvanceWrite(int cArgs) { //wrap around if we need to if (p < (StressMsg*)curWriteChunk->StartPtr ()) { - curPtr = AdvWritePastBoundary(cArgs); + return AdvWritePastBoundary(cArgs); } else { - curPtr = p; + return p; } - - return curPtr; } // It's the factored-out slow codepath for AdvanceWrite() and @@ -817,8 +1006,8 @@ inline StressMsg* ThreadStressLog::AdvanceWrite(int cArgs) { // In addition it writes NULLs b/w the startPtr and curPtr inline StressMsg* ThreadStressLog::AdvWritePastBoundary(int cArgs) { STATIC_CONTRACT_WRAPPER; -#ifndef STRESS_LOG_READONLY - //zeroed out remaining buffer +#if !defined(STRESS_LOG_READONLY) && !defined(STRESS_LOG_ANALYZER) + //zeroed out remaining buffer memset (curWriteChunk->StartPtr (), 0, (BYTE *)curPtr - (BYTE *)curWriteChunk->StartPtr ()); //if we are already at head of the list, try to grow the list @@ -826,22 +1015,182 @@ inline StressMsg* ThreadStressLog::AdvWritePastBoundary(int cArgs) { { GrowChunkList (); } -#endif //!STRESS_LOG_READONLY +#endif //!STRESS_LOG_READONLY && !STRESS_LOG_ANALYZER curWriteChunk = curWriteChunk->prev; #ifndef STRESS_LOG_READONLY - if (curWriteChunk == chunkListTail) - { + if (curWriteChunk == chunkListTail) + { writeHasWrapped = TRUE; - } + } #endif //STRESS_LOG_READONLY - curPtr = (StressMsg*)((char*)curWriteChunk->EndPtr () - sizeof(StressMsg) - cArgs * sizeof(void*)); - return curPtr; + return (StressMsg*)((char*)curWriteChunk->EndPtr () - sizeof(StressMsg) - cArgs * sizeof(void*)); } +struct StressLogMsg +{ + int m_cArgs; + const char* m_format; + void* m_args[16]; + + StressLogMsg(const char* format) : m_cArgs(0), m_format(format) + { + } + + template < typename T1 > + StressLogMsg(const char* format, T1 data1) : m_cArgs(1), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + } + + template < typename T1, typename T2 > + StressLogMsg(const char* format, T1 data1, T2 data2) : m_cArgs(2), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + } + + template < typename T1, typename T2, typename T3 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3) : m_cArgs(3), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + } + + template < typename T1, typename T2, typename T3, typename T4 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4) : m_cArgs(4), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5) : m_cArgs(5), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6) : m_cArgs(6), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7) : m_cArgs(7), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8) : m_cArgs(8), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9) : m_cArgs(9), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10) : m_cArgs(10), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + m_args[9] = (void*)(size_t)data10; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10, typename T11 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10, T11 data11) : m_cArgs(11), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*) && sizeof(T11) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + m_args[9] = (void*)(size_t)data10; + m_args[10] = (void*)(size_t)data11; + } + + template < typename T1, typename T2, typename T3, typename T4, typename T5, typename T6, typename T7, typename T8, typename T9, typename T10, typename T11, typename T12 > + StressLogMsg(const char* format, T1 data1, T2 data2, T3 data3, T4 data4, T5 data5, T6 data6, T7 data7, T8 data8, T9 data9, T10 data10, T11 data11, T12 data12) : m_cArgs(12), m_format(format) + { + static_assert_no_msg(sizeof(T1) <= sizeof(void*) && sizeof(T2) <= sizeof(void*) && sizeof(T3) <= sizeof(void*) && sizeof(T4) <= sizeof(void*) && sizeof(T5) <= sizeof(void*) && sizeof(T6) <= sizeof(void*) && sizeof(T7) <= sizeof(void*) && sizeof(T8) <= sizeof(void*) && sizeof(T9) <= sizeof(void*) && sizeof(T10) <= sizeof(void*) && sizeof(T11) <= sizeof(void*) && sizeof(T12) <= sizeof(void*)); + m_args[0] = (void*)(size_t)data1; + m_args[1] = (void*)(size_t)data2; + m_args[2] = (void*)(size_t)data3; + m_args[3] = (void*)(size_t)data4; + m_args[4] = (void*)(size_t)data5; + m_args[5] = (void*)(size_t)data6; + m_args[6] = (void*)(size_t)data7; + m_args[7] = (void*)(size_t)data8; + m_args[8] = (void*)(size_t)data9; + m_args[9] = (void*)(size_t)data10; + m_args[10] = (void*)(size_t)data11; + m_args[11] = (void*)(size_t)data12; + } +}; + #else // STRESS_LOG -#define STRESS_LOG_VA(msg) do { } while(0) +#define STRESS_LOG_VA(level,msg) do { } while(0) #define STRESS_LOG0(facility, level, msg) do { } while(0) #define STRESS_LOG1(facility, level, msg, data1) do { } while(0) #define STRESS_LOG2(facility, level, msg, data1, data2) do { } while(0) diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.cpp new file mode 100644 index 0000000..466a536 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.cpp @@ -0,0 +1,187 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#include +#include +#include +#include + +#include "assert.h" + +#define MEMORY_MAPPED_STRESSLOG + +int ParseCommandLine(wchar_t* s, wchar_t** argv, int maxArgc) +{ + int argc = 0; + bool prevWasSpace = true; + bool insideString = false; + while (*s) + { + if (!insideString) + { + if (isspace(*s)) + { + *s = '\0'; + prevWasSpace = true; + } + else if (prevWasSpace) + { + // argument begins here + if (argc < maxArgc - 1) + { + argv[argc++] = s; + } + prevWasSpace = false; + } + } + if (*s == '"') + { + insideString = !insideString; + } + else if (*s == '\\' && s[1] != '\0') + { + s++; + } + s++; + } + if (argc > 0) + { + argv[argc] = nullptr; + } + return argc; +} + +int wmain(int argc, wchar_t *argv[]) +{ + if (argc < 2 || wcscmp(argv[1], L"-?") == 0) + { + printf("Usage: StressLog \n"); + printf(" StressLog -? for list of options\n"); + return 1; + } + + HANDLE file = CreateFile(argv[1], GENERIC_READ, FILE_SHARE_WRITE, NULL, OPEN_EXISTING, FILE_ATTRIBUTE_NORMAL, NULL); + if (file == INVALID_HANDLE_VALUE) + { + printf("file not found\n"); + return 1; + } + LARGE_INTEGER lsize; + if (!GetFileSizeEx(file, &lsize)) + { + printf("could not get file size\n"); + return 1; + } + size_t size = lsize.QuadPart; +#define USE_FILE_MAPPING +#ifdef USE_FILE_MAPPING + HANDLE map = CreateFileMapping(file, NULL, PAGE_READONLY, (DWORD)(size >> 32), (DWORD)size, NULL); + if (map == nullptr) + { + printf("could not create file mapping\n"); + return 1; + } + void* baseAddress = MapViewOfFileEx(map, FILE_MAP_READ, 0, 0, size, (void*)0x400000000000); + if (baseAddress == nullptr) + { + printf("could not map view of file\n"); + return 1; + } +#else + void* baseAddress = VirtualAlloc((void*)0x400000000000, size, MEM_COMMIT | MEM_RESERVE, PAGE_READWRITE); + size_t remainingSize = size; + const size_t maxReadSize = 0x80000000; + char* readPtr = (char*)baseAddress; + while (remainingSize >= maxReadSize) + { + DWORD sizeRead = 0; + BOOL success = ReadFile(file, readPtr, maxReadSize, &sizeRead, NULL); + if (!success || sizeRead != maxReadSize) + { + printf("oops, reading the file didn't work\n"); + return 1; + } + remainingSize -= maxReadSize; + readPtr += maxReadSize; + } + if (remainingSize > 0) + { + DWORD sizeRead = 0; + BOOL success = ReadFile(file, readPtr, remainingSize, &sizeRead, NULL); + if (!success || sizeRead != remainingSize) + { + printf("oops, reading the file didn't work\n"); + return 1; + } + } +#endif + argc -= 2; + argv += 2; + wchar_t* largv[128]; + memset(largv, 0, sizeof(largv)); + while (true) + { + typedef int ProcessStresslog(void* baseAddress, int argc, wchar_t* argv[]); + + HMODULE plugin = LoadLibrary(L"StressLogPlugin.dll"); + + if (plugin == nullptr) + { + printf("could not load StressLogPlugin.dll"); + return 1; + } + + ProcessStresslog* processStressLog = (ProcessStresslog*)GetProcAddress(plugin, "ProcessStresslog"); + if (processStressLog == nullptr) + { + printf("could not find entry point ProcessStresslog in StressLogPlugin.dll"); + return 1; + } + + int error = processStressLog(baseAddress, argc, argv); + + FreeLibrary(plugin); + + if (error != 0) + { + printf("error %d occurred\n", error); + } + + bool runAgain = false; + wchar_t s[1024]; + while (true) + { + printf("'q' to quit, 'r' to run again\n>"); + if (fgetws(s, 1023, stdin) == nullptr) + continue; + switch (s[0]) + { + case 'r': + case 'R': + runAgain = true; + break; + + case 'q': + case 'Q': + break; + + default: + continue; + } + break; + } + if (runAgain) + { + int largc = ParseCommandLine(&s[1], largv, _countof(largv)); + if (largc > 0) + { + argc = largc; + argv = largv; + } + } + else + { + break; + } + } +} diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.sln b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.sln new file mode 100644 index 0000000..2ba0ed1 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.sln @@ -0,0 +1,44 @@ + +Microsoft Visual Studio Solution File, Format Version 12.00 +# Visual Studio Version 16 +VisualStudioVersion = 16.0.30717.126 +MinimumVisualStudioVersion = 10.0.40219.1 +Project("{8BC9CEB8-8B4A-11D0-8D11-00A0C91BC942}") = "StressLogAnalyzer", "StressLogAnalyzer.vcxproj", "{C6955B43-4176-4259-8831-9A60596E373D}" + ProjectSection(ProjectDependencies) = postProject + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA} = {6BADDA84-5ED3-40EF-B4A5-553C446D43AA} + EndProjectSection +EndProject +Project("{8BC9CEB8-8B4A-11D0-8D11-00A0C91BC942}") = "StressLogPlugin", "StressLogPlugin\StressLogPlugin.vcxproj", "{6BADDA84-5ED3-40EF-B4A5-553C446D43AA}" +EndProject +Global + GlobalSection(SolutionConfigurationPlatforms) = preSolution + Debug|x64 = Debug|x64 + Debug|x86 = Debug|x86 + Release|x64 = Release|x64 + Release|x86 = Release|x86 + EndGlobalSection + GlobalSection(ProjectConfigurationPlatforms) = postSolution + {C6955B43-4176-4259-8831-9A60596E373D}.Debug|x64.ActiveCfg = Debug|x64 + {C6955B43-4176-4259-8831-9A60596E373D}.Debug|x64.Build.0 = Debug|x64 + {C6955B43-4176-4259-8831-9A60596E373D}.Debug|x86.ActiveCfg = Debug|Win32 + {C6955B43-4176-4259-8831-9A60596E373D}.Debug|x86.Build.0 = Debug|Win32 + {C6955B43-4176-4259-8831-9A60596E373D}.Release|x64.ActiveCfg = Release|x64 + {C6955B43-4176-4259-8831-9A60596E373D}.Release|x64.Build.0 = Release|x64 + {C6955B43-4176-4259-8831-9A60596E373D}.Release|x86.ActiveCfg = Release|Win32 + {C6955B43-4176-4259-8831-9A60596E373D}.Release|x86.Build.0 = Release|Win32 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Debug|x64.ActiveCfg = Debug|x64 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Debug|x64.Build.0 = Debug|x64 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Debug|x86.ActiveCfg = Debug|Win32 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Debug|x86.Build.0 = Debug|Win32 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Release|x64.ActiveCfg = Release|x64 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Release|x64.Build.0 = Release|x64 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Release|x86.ActiveCfg = Release|Win32 + {6BADDA84-5ED3-40EF-B4A5-553C446D43AA}.Release|x86.Build.0 = Release|Win32 + EndGlobalSection + GlobalSection(SolutionProperties) = preSolution + HideSolutionNode = FALSE + EndGlobalSection + GlobalSection(ExtensibilityGlobals) = postSolution + SolutionGuid = {BB9CFD6B-BEF2-43F8-A459-AD8B42CF37A9} + EndGlobalSection +EndGlobal diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj new file mode 100644 index 0000000..a193e29 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj @@ -0,0 +1,149 @@ + + + + + Debug + Win32 + + + Release + Win32 + + + Debug + x64 + + + Release + x64 + + + + 16.0 + Win32Proj + {c6955b43-4176-4259-8831-9a60596e373d} + StressLog + 10.0 + StressLogAnalyzer + + + + Application + true + v142 + Unicode + + + Application + false + v142 + true + Unicode + + + Application + true + v142 + Unicode + + + Application + false + v142 + true + Unicode + + + + + + + + + + + + + + + + + + + + + true + + + false + + + true + + + false + true + + + + Level3 + true + WIN32;_DEBUG;_CONSOLE;%(PreprocessorDefinitions) + true + + + Console + true + + + + + Level3 + true + true + true + WIN32;NDEBUG;_CONSOLE;%(PreprocessorDefinitions) + true + + + Console + true + true + true + + + + + Level3 + true + _DEBUG;_CONSOLE;%(PreprocessorDefinitions) + true + + + Console + true + + + + + Level3 + true + true + true + NDEBUG;_CONSOLE;%(PreprocessorDefinitions) + true + + + Console + true + true + true + + + + + + + + + \ No newline at end of file diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.filters b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.filters new file mode 100644 index 0000000..81f2a77 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.filters @@ -0,0 +1,22 @@ + + + + + {4FC737F1-C7A5-4376-A066-2A32D752A2FF} + cpp;c;cc;cxx;c++;cppm;ixx;def;odl;idl;hpj;bat;asm;asmx + + + {93995380-89BD-4b04-88EB-625FBE52EBFB} + h;hh;hpp;hxx;h++;hm;inl;inc;ipp;xsd + + + {67DA6AB6-F800-4c08-8B7A-83BB121AAD01} + rc;ico;cur;bmp;dlg;rc2;rct;bin;rgs;gif;jpg;jpeg;jpe;resx;tiff;tif;png;wav;mfcribbon-ms + + + + + Quelldateien + + + \ No newline at end of file diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.users b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.users new file mode 100644 index 0000000..0568ca6 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogAnalyzer.vcxproj.users @@ -0,0 +1,11 @@ + + + + I:\Issue_41928\Fix_2\Stresslog1749.log -e + WindowsLocalDebugger + + + i:\gcperfsim\gcperfsimstresslog.log + WindowsLocalDebugger + + \ No newline at end of file diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.cpp new file mode 100644 index 0000000..3c0086a --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.cpp @@ -0,0 +1,1417 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#include "pch.h" + +#include +#include +#include +#include + +#include "strike.h" +#include "util.h" + +#include "assert.h" + +#define STRESS_LOG +#define STRESS_LOG_ANALYZER +#define MEMORY_MAPPED_STRESSLOG + +class MapViewHolder +{ + void* whatever; +}; + +typedef unsigned char uint8_t; +typedef unsigned int uint32_t; +typedef long long int64_t; +typedef size_t uint64_t; + +bool IsInCantAllocStressLogRegion() +{ + return true; +} + +#include "../../../inc/stresslog.h" + +BOOL g_bDacBroken; +WCHAR g_mdName[1]; +SYMBOLS* g_ExtSymbols; +SOS* g_sos; + +HRESULT OutputVaList(ULONG mask, PCSTR format, va_list args) +{ + return vprintf(format, args); +} + +void ExtOut(PCSTR format, ...) +{ + va_list args; + va_start(args, format); + vprintf(format, args); +} + +void GcHistClear() +{ +} + +void GcHistAddLog(LPCSTR msg, StressMsg* stressMsg) +{ +} + +// this is just to read string literals out of the coreclr and clrgc images +struct CorClrData : IDebugDataSpaces +{ + StressLog::StressLogHeader* hdr; + CorClrData(StressLog::StressLogHeader* h) : hdr(h) { } + + virtual HRESULT ReadVirtual(void* src, void* dest, size_t size, int) + { + size_t cumSize = 0; + for (int moduleIndex = 0; moduleIndex < StressLog::MAX_MODULES; moduleIndex++) + { + ptrdiff_t offs = (uint8_t*)src - hdr->modules[moduleIndex].baseAddress; + if ((size_t)offs < hdr->modules[moduleIndex].size && (size_t)offs + size < hdr->modules[moduleIndex].size) + { + memcpy(dest, &hdr->moduleImage[offs + cumSize], size); + return S_OK; + } + cumSize += hdr->modules[moduleIndex].size; + } + return E_FAIL; + } +}; + +const int MAX_NUMBER_OF_HEAPS = 1024; +static volatile int64_t s_maxHeapNumberSeen = -1; +static volatile uint64_t s_threadIdOfHeap[MAX_NUMBER_OF_HEAPS][2]; + +enum GcThreadKind +{ + GC_THREAD_FG, + GC_THREAD_BG, +}; + +struct GcThread +{ + GcThreadKind kind; + int heapNumber; +}; + +bool LookupGcThread(uint64_t threadId, GcThread *gcThread) +{ + for (int i = 0; i <= s_maxHeapNumberSeen; i++) + { + if (s_threadIdOfHeap[i][GC_THREAD_FG] == threadId) + { + gcThread->heapNumber = i; + gcThread->kind = GC_THREAD_FG; + return true; + } + if (s_threadIdOfHeap[i][GC_THREAD_BG] == threadId) + { + gcThread->heapNumber = i; + gcThread->kind = GC_THREAD_BG; + return true; + } + } + return false; +} + +#define InterestingStrings \ +d(IS_UNKNOWN, "") \ +d(IS_THREAD_WAIT, ThreadStressLog::gcServerThread0StartMsg()) \ +d(IS_THREAD_WAIT_DONE, ThreadStressLog::gcServerThreadNStartMsg()) \ +d(IS_GCSTART, ThreadStressLog::gcDetailedStartMsg()) \ +d(IS_GCEND, ThreadStressLog::gcDetailedEndMsg()) \ +d(IS_MARK_START, ThreadStressLog::gcStartMarkMsg()) \ +d(IS_PLAN_START, ThreadStressLog::gcStartPlanMsg()) \ +d(IS_RELOCATE_START, ThreadStressLog::gcStartRelocateMsg()) \ +d(IS_RELOCATE_END, ThreadStressLog::gcEndRelocateMsg()) \ +d(IS_COMPACT_START, ThreadStressLog::gcStartCompactMsg()) \ +d(IS_COMPACT_END, ThreadStressLog::gcEndCompactMsg()) \ +d(IS_GCROOT, ThreadStressLog::gcRootMsg()) \ +d(IS_PLUG_MOVE, ThreadStressLog::gcPlugMoveMsg()) \ +d(IS_GCMEMCOPY, ThreadStressLog::gcMemCopyMsg()) \ +d(IS_GCROOT_PROMOTE, ThreadStressLog::gcRootPromoteMsg()) \ +d(IS_PLAN_PLUG, ThreadStressLog::gcPlanPlugMsg()) \ +d(IS_PLAN_PINNED_PLUG, ThreadStressLog::gcPlanPinnedPlugMsg()) \ +d(IS_DESIRED_NEW_ALLOCATION, ThreadStressLog::gcDesiredNewAllocationMsg()) \ +d(IS_MAKE_UNUSED_ARRAY, ThreadStressLog::gcMakeUnusedArrayMsg()) \ +d(IS_START_BGC_THREAD, ThreadStressLog::gcStartBgcThread()) \ +d(IS_UNINTERESTING, "") + +enum InterestingStringId : unsigned char +{ +#define d(a,b) a, + InterestingStrings + IS_INTERESTING +#undef d +}; + +const int MAX_INTERESTING_STRINGS = 1024; +int s_interestingStringCount = IS_INTERESTING; +const char* s_interestingStringTable[MAX_INTERESTING_STRINGS] = +{ +#define d(a,b) b, + InterestingStrings +#undef d +}; + +bool s_interestingStringFilter[MAX_INTERESTING_STRINGS]; + +static void AddInterestingString(const char* s) +{ + for (int i = 0; i < s_interestingStringCount; i++) + { + if (strcmp(s_interestingStringTable[i], s) == 0) + { + s_interestingStringFilter[i] = true; + return; + } + } + int i = s_interestingStringCount++; + s_interestingStringTable[i] = s; + s_interestingStringFilter[IS_INTERESTING] = true; +} + + +InterestingStringId mapImageToStringId[sizeof(StressLog::StressLogHeader::moduleImage)]; + +InterestingStringId FindStringId(StressLog::StressLogHeader* hdr, char* format) +{ + size_t offset = format - (char*)hdr->moduleImage; + assert(offset < sizeof(mapImageToStringId)); + InterestingStringId id = mapImageToStringId[offset]; + if (id != IS_UNKNOWN) + return id; + for (int i = 1; s_interestingStringTable[i] != nullptr; i++) + { + if (strcmp(format, s_interestingStringTable[i]) == 0) + { + id = (InterestingStringId)i; + if (id > IS_INTERESTING) + id = IS_INTERESTING; + mapImageToStringId[offset] = id; + return id; + } + } + mapImageToStringId[offset] = IS_UNINTERESTING; + return IS_UNINTERESTING; +} + +const int MAX_LEVEL_FILTERS = 100; +static int s_levelFilterCount; +struct LevelFilter +{ + int minLevel; + int maxLevel; +}; + +static LevelFilter s_levelFilter[MAX_LEVEL_FILTERS]; + +struct GcStartEnd +{ + double startTime; + double endTime; +}; + +const int MAX_GC_INDEX = 1024 * 1024; +static GcStartEnd s_gcStartEnd[MAX_GC_INDEX]; + +static int s_gcFilterStart; +static int s_gcFilterEnd; + +const int MAX_VALUE_FILTERS = 100; +static int s_valueFilterCount; + +struct ValueFilter +{ + ULONGLONG start; + ULONGLONG end; +}; + +static ValueFilter s_valueFilter[MAX_VALUE_FILTERS]; + +const int MAX_THREAD_FILTERS = 1024; +static int s_threadFilterCount; +static uint64_t s_threadFilter[MAX_THREAD_FILTERS]; + +static bool s_gcThreadFilter[MAX_NUMBER_OF_HEAPS][2]; +static bool s_hadGcThreadFilters; + +static bool s_printHexTidForGcThreads; + +static uint32_t s_facilityIgnore; + +static bool s_printEarliestMessages; +static int s_printEarliestMessageFromThreadCount; +static uint64_t s_printEarliestMessageFromThread[MAX_THREAD_FILTERS]; +static bool s_printEarliestMessageFromGcThread[MAX_NUMBER_OF_HEAPS][2]; + +static bool FilterThread(ThreadStressLog* tsl) +{ + // return tsl->threadId == 0x6ff8; + if (s_hadGcThreadFilters) + { + GcThread gcThread; + if (!LookupGcThread(tsl->threadId, &gcThread)) + { + // this may or may not be a GC thread - we don't know yet + // include its messages to be conservative - we will have + // a filter later to remove these messages + return true; + } + return s_gcThreadFilter[gcThread.heapNumber][gcThread.kind]; + } + else + { + if (s_threadFilterCount == 0) + return true; + // we can filter now + for (int i = 0; i < s_threadFilterCount; i++) + { + if (s_threadFilter[i] == tsl->threadId) + return true; + } + return false; + } +} + + +int GcLogLevel(uint32_t facility) +{ + if ((facility & (LF_ALWAYS | 0xfffe | LF_GC)) == (LF_ALWAYS | LF_GC)) + { + return (facility >> 16) & 0x7fff; + } + return 0; +} + +static void RememberThreadForHeap(uint64_t threadId, int64_t heapNumber, GcThreadKind threadKind) +{ + if (s_maxHeapNumberSeen == -1 && heapNumber == 0) + { + // we don't want to remember these associations for WKS GC, + // which can execute on any thread - as soon as we see + // a heap number != 0, we assume SVR GC and remember it + return; + } + + if (heapNumber < MAX_NUMBER_OF_HEAPS) + { + s_threadIdOfHeap[heapNumber][threadKind] = threadId; + int64_t maxHeapNumberSeen = s_maxHeapNumberSeen; + while (maxHeapNumberSeen < heapNumber) + { + maxHeapNumberSeen = InterlockedCompareExchange64((volatile LONG64*)&s_maxHeapNumberSeen, heapNumber, maxHeapNumberSeen); + } + } +} + +bool FilterMessage(StressLog::StressLogHeader* hdr, ThreadStressLog* tsl, uint32_t facility, char* format, double deltaTime, int argCount, void** args) +{ + bool fLevelFilter = false; + if (s_levelFilterCount > 0) + { + int gcLogLevel = GcLogLevel(facility); + for (int i = 0; i < s_levelFilterCount; i++) + { + if (s_levelFilter[i].minLevel <= gcLogLevel && gcLogLevel <= s_levelFilter[i].maxLevel) + { + fLevelFilter = true; + break; + } + } + } + + if (s_facilityIgnore != 0) + { + if ((facility & (LF_ALWAYS | 0xfffe | LF_GC)) == (LF_ALWAYS | LF_GC)) + { + // specially encoded GC message including dprintf level + if ((s_facilityIgnore & LF_GC) != 0) + { + return false; + } + } + else if ((s_facilityIgnore & facility) != 0) + { + return false; + } + } + + InterestingStringId isd = FindStringId(hdr, format); + switch (isd) + { + case IS_THREAD_WAIT: + case IS_THREAD_WAIT_DONE: + RememberThreadForHeap(tsl->threadId, (int64_t)args[0], GC_THREAD_FG); + break; + + case IS_DESIRED_NEW_ALLOCATION: + { + int genNumber = (int)(int64_t)args[1]; + if (genNumber <= 1) + { + // do this only for gen 0 and 1, because otherwise it + // may be background GC + RememberThreadForHeap(tsl->threadId, (int64_t)args[0], GC_THREAD_FG); + } + break; + } + + case IS_GCSTART: + { + int gcIndex = (int)(size_t)args[0]; + if (gcIndex < MAX_GC_INDEX) + { + s_gcStartEnd[gcIndex].startTime = deltaTime; + } + return true; + } + + case IS_GCEND: + { + int gcIndex = (int)(size_t)args[0]; + if (gcIndex < MAX_GC_INDEX) + { + s_gcStartEnd[gcIndex].endTime = deltaTime; + } + return true; + } + + case IS_MARK_START: + case IS_PLAN_START: + case IS_RELOCATE_START: + case IS_RELOCATE_END: + case IS_COMPACT_START: + case IS_COMPACT_END: + RememberThreadForHeap(tsl->threadId, (int64_t)args[0], GC_THREAD_FG); + return true; + + case IS_PLAN_PLUG: + case IS_PLAN_PINNED_PLUG: + if (s_valueFilterCount > 0) + { + // print this message if the plug or the gap before it contain (part of) the range we're looking for + size_t gapSize = (size_t)args[0]; + size_t plugStart = (size_t)args[1]; + size_t gapStart = plugStart - gapSize; + size_t plugEnd = (size_t)args[2]; + for (int i = 0; i < s_valueFilterCount; i++) + { + if (s_valueFilter[i].end < gapStart || plugEnd < s_valueFilter[i].start) + { + // empty intersection with the gap+plug + continue; + } + return true; + } + } + break; + + case IS_GCMEMCOPY: + if (s_valueFilterCount > 0) + { + // print this message if the source or destination range contain (part of) the range we're looking for + size_t srcStart = (size_t)args[0]; + size_t dstStart = (size_t)args[1]; + size_t srcEnd = (size_t)args[2]; + size_t dstEnd = (size_t)args[3]; + for (int i = 0; i < s_valueFilterCount; i++) + { + if ((s_valueFilter[i].end < srcStart || srcEnd < s_valueFilter[i].start) && + (s_valueFilter[i].end < dstStart || dstEnd < s_valueFilter[i].start)) + { + // empty intersection with both the source and the destination + continue; + } + return true; + } + } + break; + + case IS_MAKE_UNUSED_ARRAY: + if (s_valueFilterCount > 0) + { + // print this message if the source or destination range contain (part of) the range we're looking for + size_t start = (size_t)args[0]; + size_t end = (size_t)args[1]; + for (int i = 0; i < s_valueFilterCount; i++) + { + if ((s_valueFilter[i].end < start || end < s_valueFilter[i].start)) + { + // empty intersection with the unused array + continue; + } + return true; + } + } + break; + + case IS_GCROOT: + case IS_PLUG_MOVE: + case IS_GCROOT_PROMOTE: + case IS_INTERESTING: + break; + + case IS_START_BGC_THREAD: + RememberThreadForHeap(tsl->threadId, (int64_t)args[0], GC_THREAD_BG); + break; + } + return fLevelFilter || s_interestingStringFilter[isd]; +} + +struct StressThreadAndMsg +{ + uint64_t threadId; + StressMsg* msg; + uint64_t msgId; +}; + +int CmpMsg(const void* p1, const void* p2) +{ + const StressThreadAndMsg* msg1 = (const StressThreadAndMsg*)p1; + const StressThreadAndMsg* msg2 = (const StressThreadAndMsg*)p2; + + if (msg1->msg->timeStamp < msg2->msg->timeStamp) + return 1; + if (msg1->msg->timeStamp > msg2->msg->timeStamp) + return -11; + + if (msg1->threadId < msg2->threadId) + return -1; + if (msg1->threadId > msg2->threadId) + return 1; + + if (msg1->msgId < msg2->msgId) + return -1; + if (msg1->msgId > msg2->msgId) + return 1; + + assert(!"unreachable"); + return 0; +} + +struct ThreadStressLogDesc +{ + volatile unsigned workStarted; + volatile unsigned workFinished; + ThreadStressLog* tsl; + StressMsg* earliestMessage; + + ThreadStressLogDesc() : workStarted(0), workFinished(0), tsl(nullptr), earliestMessage(nullptr) + { + } +}; + +static const int MAX_THREADSTRESSLOGS = 64 * 1024; +static ThreadStressLogDesc s_threadStressLogDesc[MAX_THREADSTRESSLOGS]; +static int s_threadStressLogCount; +static LONG s_wrappedWriteThreadCount; + +static const LONG MAX_MESSAGE_COUNT = 1024 * 1024 * 1024; +static StressThreadAndMsg* s_threadMsgBuf; +static volatile LONG s_msgCount = 0; +static volatile LONG s_totalMsgCount = 0; +static double s_timeFilterStart = 0; +static double s_timeFilterEnd = 0; +static wchar_t* s_outputFileName = nullptr; + +static StressLog::StressLogHeader* s_hdr; + +static bool s_fPrintFormatStrings; + +void Usage() +{ + printf("\n"); + printf("Usage:\n"); + printf("\n"); + printf(" -o:: write output to a text file instead of the console\n"); + printf("\n"); + printf(" -v:: look for a specific hex value (often used to look for addresses)\n"); + printf(" -v:-: look for values >= hexlower and <= hexupper\n"); + printf(" -v:+: look for values >= hexlower and <= hexlower+hexsize\n"); + printf("\n"); + printf(" -t:: don't consider messages before start time\n"); + printf(" -t:-: only consider messages >= start time and <= end time\n"); + printf(" -t:-: only consider messages in the last seconds\n"); + printf("\n"); + printf(" -l:,,... : print messages at dprint level1,level2,...\n"); + printf("\n"); + printf(" -g:: only print messages occuring during GC#gc_index\n"); + printf(" -g:-: as above, for a range of GC indices\n"); + printf("\n"); + printf(" -f: print the raw format strings along with the message\n"); + printf(" (useful to search for the format string in the source code)\n"); + printf(" -f:: search for a specific format string\n"); + printf(" e.g. '-f:\"<%%Ix>:%%Ix\"'\n"); + printf("\n"); + printf(" -i:: ignore messages from log facilities\n"); + printf(" e.g. '-i:7ffe' means ignore messages from anything but LF_GC\n"); + printf("\n"); + printf(" -tid: print hex thread ids, e.g. 2a08 instead of GC12\n"); + printf(" -tid:,,...: only print messages from the listed\n"); + printf(" threads. Thread ids are in hex, given as GC,\n"); + printf(" or BG\n"); + printf(" e.g. '-tid:2bc8,GC3,BG14' would print messages from thread 2bc8, the gc thread\n"); + printf(" associated with heap 3, and the background GC thread for heap 14\n"); + printf("\n"); + printf(" -e: printf earliest messages from all threads\n"); + printf(" -e:,,...: print earliest messages from the listed\n"); + printf(" threads. Thread ids are in hex, given as GC,\n"); + printf(" or BG\n"); + printf(" e.g. '-e:2bc8,GC3,BG14' would print the earliest messages from thread 2bc8,\n"); + printf(" the gc thread associated with heap 3, and the background GC thread for heap 14\n"); + printf("\n"); +} + +// Translate escape sequences like "\n" - only common ones are handled +static void InterpretEscapeSequences(char* s) +{ + char* d = s; + char c = *s++; + while (c != '\0') + { + if (c == '\\') + { + c = *s++; + switch (c) + { + case 'n': *d++ = '\n'; break; + case 't': *d++ = '\t'; break; + case 'r': *d++ = '\r'; break; + default: *d++ = c; break; + } + } + else + { + *d++ = c; + } + c = *s++; + } + *d = '\0'; +} + +bool ParseOptions(int argc, wchar_t* argv[]) +{ + int i = 0; + while (i < argc) + { + wchar_t* arg = argv[i]; + if (arg[0] == '-') + { + switch (arg[1]) + { + case 'v': + case 'V': + if (s_valueFilterCount >= MAX_VALUE_FILTERS) + { + printf("too many value filters - max is %d\n", MAX_VALUE_FILTERS); + return false; + } + if (arg[2] == ':') + { + int i = s_valueFilterCount++; + wchar_t* end = nullptr; + s_valueFilter[i].start = _wcstoui64(&arg[3], &end, 16); + if (*end == '-') + { + s_valueFilter[i].end = _wcstoui64(end + 1, &end, 16); + } + else if (*end == '+') + { + s_valueFilter[i].end = s_valueFilter[i].start + _wcstoui64(end + 1, &end, 16); + } + else if (*end != '\0') + { + printf("expected '-' or '+'\n"); + return false; + } + else + { + s_valueFilter[i].end = s_valueFilter[i].start; + } + if (*end != '\0') + { + printf("could not parse option %S\n", arg); + return false; + } + } + else + { + printf("expected '-v:'\n"); + return false; + } + break; + + case 't': + case 'T': + if (arg[2] == ':') + { + wchar_t* end = nullptr; + s_timeFilterStart = wcstod(&arg[3], &end); + if (*end == '-') + { + s_timeFilterEnd = wcstod(end + 1, &end); + } + else if (*end == '+') + { + s_timeFilterEnd = s_timeFilterStart + wcstod(end + 1, &end); + } + else + { + s_timeFilterEnd = INFINITY; + } + if (*end != '\0') + { + printf("could not parse option %S\n", arg); + return false; + } + } + else if (_wcsnicmp(arg, L"-tid:", 5) == 0) + { + arg = arg + 5; + while (true) + { + if (s_threadFilterCount >= MAX_THREAD_FILTERS) + { + printf("too many thread filters - max is %d\n", MAX_THREAD_FILTERS); + return false; + } + wchar_t* end = nullptr; + if (_wcsnicmp(arg, L"gc", 2) == 0 || _wcsnicmp(arg, L"bg", 2) == 0) + { + int gcHeapNumber = wcstol(arg+2, &end, 10); + GcThreadKind kind = _wcsnicmp(arg, L"gc", 2) == 0 ? GC_THREAD_FG : GC_THREAD_BG; + if (gcHeapNumber < MAX_NUMBER_OF_HEAPS) + { + s_gcThreadFilter[gcHeapNumber][kind] = true; + s_hadGcThreadFilters = true; + } + else + { + printf("expected heap number < %d\n", MAX_NUMBER_OF_HEAPS); + return false; + } + } + else + { + int i = s_threadFilterCount++; + s_threadFilter[i] = _wcstoui64(arg, &end, 16); + } + if (*end == ',') + { + arg = end + 1; + } + else if (*end != '\0') + { + printf("could not parse %S\n", arg); + return false; + } + else + { + break; + } + } + } + else if (_wcsicmp(arg, L"-tid") == 0) + { + s_printHexTidForGcThreads = true; + } + else + { + printf("-t: or -t:<-last seconds> or -t:- or\n"); + printf("-tid:,,... expected\n"); + return false; + } + break; + + case 'o': + case 'O': + if (arg[2] == ':') + { + s_outputFileName = &arg[3]; + } + else + { + printf("expected '-o:'\n"); + return false; + } + break; + + case 'l': + case 'L': + if (arg[2] == ':') + { + arg = arg + 3; + while (true) + { + if (s_levelFilterCount >= MAX_LEVEL_FILTERS) + { + printf("too many level filters - max is %d\n", MAX_LEVEL_FILTERS); + return false; + } + int i = s_levelFilterCount++; + wchar_t* end = nullptr; + if (*arg == '*') + { + s_levelFilter[i].minLevel = 0; + s_levelFilter[i].maxLevel = 0x7fffffff; + end = arg + 1; + } + else + { + s_levelFilter[i].minLevel = wcstol(arg, &end, 10); + if (*end == '-') + { + s_levelFilter[i].maxLevel = wcstol(end + 1, &end, 10); + } + else + { + s_levelFilter[i].maxLevel = s_levelFilter[i].minLevel; + } + } + if (*end == ',') + { + arg = end + 1; + } + else if (*end != '\0') + { + printf("could not parse option %S\n", arg); + return false; + } + else + { + break; + } + } + } + else + { + printf("expected '-l:'\n"); + return false; + } + break; + + case 'f': + case 'F': + if (arg[2] == '\0') + { + s_fPrintFormatStrings = true; + } + else if (arg[2] == ':') + { + if (s_interestingStringCount >= MAX_INTERESTING_STRINGS) + { + printf("too format string filters - max is %d\n", MAX_INTERESTING_STRINGS - IS_INTERESTING); + return false; + } + arg = &arg[3]; + size_t requiredSize = 0; + if (wcstombs_s(&requiredSize, nullptr, 0, arg, 0) != 0) + return false; + char* buf = new char[requiredSize]; + size_t actualSize = 0; + if (wcstombs_s(&actualSize, buf, requiredSize, arg, requiredSize) != 0) + return false; + if (actualSize <= 1) + { + printf("-f: expected\n"); + return false; + } + assert(actualSize == requiredSize); + // remove double quotes around the string, if given + if (actualSize >= 2 && buf[0] == '"' && buf[actualSize - 2] == '"') + { + buf[actualSize - 2] = '\0'; + buf++; + } + InterpretEscapeSequences(buf); + AddInterestingString(buf); + } + break; + + case 'g': + case 'G': + if (arg[2] == ':') + { + wchar_t* end = nullptr; + s_gcFilterStart = wcstol(arg+3, &end, 10); + if (*end == '-') + { + s_gcFilterEnd = wcstol(end+1, &end, 10); + } + else + { + s_gcFilterEnd = s_gcFilterStart; + } + if (*end != '\0') + { + printf("could not parse option %S\n", arg); + return false; + } + } + else + { + printf("-g: or -g:- expected\n"); + return false; + } + break; + + case 'i': + case 'I': + if (arg[2] == ':') + { + wchar_t* end = nullptr; + s_facilityIgnore = wcstoul(arg + 3, &end, 16); + if (*end != '\0') + { + printf("could not parse option %S\n", arg); + return false; + } + } + else + { + printf("-i: expected\n"); + return false; + } + break; + + case 'e': + case 'E': + if (arg[2] == '\0') + { + s_printEarliestMessages = true; + } + else if (arg[2] == ':') + { + arg = arg + 3; + while (true) + { + if (s_printEarliestMessageFromThreadCount >= MAX_THREAD_FILTERS) + { + printf("too many threads - max is %d\n", MAX_THREAD_FILTERS); + return false; + } + wchar_t* end = nullptr; + if (_wcsnicmp(arg, L"gc", 2) == 0 || _wcsnicmp(arg, L"bg", 2) == 0) + { + int gcHeapNumber = wcstol(arg + 2, &end, 10); + GcThreadKind kind = _wcsnicmp(arg, L"gc", 2) == 0 ? GC_THREAD_FG : GC_THREAD_BG; + if (gcHeapNumber < MAX_NUMBER_OF_HEAPS) + { + s_printEarliestMessageFromGcThread[gcHeapNumber][kind] = true; + } + else + { + printf("expected heap number < %d\n", MAX_NUMBER_OF_HEAPS); + return false; + } + } + else + { + int i = s_printEarliestMessageFromThreadCount++; + s_printEarliestMessageFromThread[i] = _wcstoui64(arg, &end, 16); + } + if (*end == ',') + { + arg = end + 1; + } + else if (*end != '\0') + { + printf("could not parse %S\n", arg); + return false; + } + else + { + break; + } + } + } + else + { + printf("could not parse option %S\n", arg); + return false; + } + break; + + case '?': + Usage(); + return false; + + default: + printf("unrecognized option %S\n", arg); + return false; + } + } + i++; + } + return true; +} + +static void IncludeMessage(uint64_t threadId, StressMsg* msg) +{ + LONG msgCount = _InterlockedIncrement(&s_msgCount) - 1; + if (msgCount < MAX_MESSAGE_COUNT) + { + s_threadMsgBuf[msgCount].threadId = threadId; + s_threadMsgBuf[msgCount].msg = msg; + s_threadMsgBuf[msgCount].msgId = msgCount; + } +} + +DWORD WINAPI ProcessStresslogWorker(LPVOID) +{ + StressLog::StressLogHeader* hdr = s_hdr; + LONG totalMsgCount = 0; + int wrappedWriteThreadCount = 0; + bool fTimeFilter = s_timeFilterStart != 0.0 || s_timeFilterEnd != 0.0; + for (int threadStressLogIndex = 0; threadStressLogIndex < s_threadStressLogCount; threadStressLogIndex++) + { + // is another thread already working on this thread stress log? + if (s_threadStressLogDesc[threadStressLogIndex].workStarted != 0 || InterlockedIncrement(&s_threadStressLogDesc[threadStressLogIndex].workStarted) != 1) + continue; + + ThreadStressLog* tsl = s_threadStressLogDesc[threadStressLogIndex].tsl; + if (!tsl->IsValid()) + continue; + if (!FilterThread(tsl)) + continue; + if (tsl->writeHasWrapped) + { + wrappedWriteThreadCount++; + } + // printf("thread: %Ix\n", tsl->threadId); + StressMsg* msg = tsl->curPtr; + StressLogChunk* slc = tsl->curWriteChunk; + int chunkCount = 0; + StressMsg* prevMsg = nullptr; + while (true) + { + // printf("stress log chunk %Ix\n", (size_t)slc); + if (!slc->IsValid()) + { + printf("oops, invalid stress log chunk\n"); + slc = slc->next; + if (slc == tsl->curWriteChunk) + break; + chunkCount++; + if (chunkCount >= tsl->chunkListLength) + { + printf("oops, more chunks on list than expected\n"); + break; + } + msg = nullptr; + } + assert(slc->next->prev == slc); + assert(slc->prev->next == slc); +#ifdef _DEBUG + int chunkCount1 = 0; + for (StressLogChunk* slc1 = tsl->curWriteChunk; slc1 != slc; slc1 = slc1->next) + { + chunkCount1++; + } + if (chunkCount != chunkCount1) + { + printf("oops, we have a loop\n"); + break; + } +#endif //_DEBUG + + size_t* p = (size_t*)slc->StartPtr(); + size_t* end = (size_t*)slc->EndPtr(); + if (p <= (size_t*)msg && (size_t*)msg < end) + { + ; // fine + } + else + { + while (p < end && *p == 0) + p++; + msg = (StressMsg*)p; + } + StressMsg* endMsg = (StressMsg*)end; + while (msg < endMsg) + { + totalMsgCount++; + char* format = (char*)(hdr->moduleImage + msg->formatOffset); + double deltaTime = ((double)(msg->timeStamp - hdr->startTimeStamp)) / hdr->tickFrequency; + bool fIgnoreMessage = false; + if (fTimeFilter) + { + if (deltaTime < s_timeFilterStart) + { + // we know the times will only get smaller, so can stop here + break; + } + if (deltaTime > s_timeFilterEnd) + { + fIgnoreMessage = true; + } + } + int numberOfArgs = (msg->numberOfArgsX << 3) + msg->numberOfArgs; + if (!fIgnoreMessage) + { + bool fIncludeMessage = FilterMessage(hdr, tsl, msg->facility, format, deltaTime, numberOfArgs, msg->args); + if (!fIncludeMessage && s_valueFilterCount > 0) + { + for (int i = 0; i < numberOfArgs; i++) + { + for (int j = 0; j < s_valueFilterCount; j++) + { + if (s_valueFilter[j].start <= (size_t)msg->args[i] && (size_t)msg->args[i] <= s_valueFilter[j].end) + { + fIncludeMessage = true; + break; + } + } + if (fIncludeMessage) + break; + } + } + if (fIncludeMessage) + { + IncludeMessage(tsl->threadId, msg); + } + } + prevMsg = msg; + msg = (StressMsg*)&msg->args[numberOfArgs]; + } + if (slc == tsl->chunkListTail && !tsl->writeHasWrapped) + break; + slc = slc->next; + if (slc == tsl->curWriteChunk) + break; + if (s_hadGcThreadFilters && !FilterThread(tsl)) + break; + chunkCount++; + if (chunkCount >= tsl->chunkListLength) + { + printf("oops, more chunks on list than expected\n"); + break; + } + msg = nullptr; + } + s_threadStressLogDesc[threadStressLogIndex].earliestMessage = prevMsg; + s_threadStressLogDesc[threadStressLogIndex].workFinished = 1; + } + + InterlockedAdd(&s_totalMsgCount, totalMsgCount); + InterlockedAdd(&s_wrappedWriteThreadCount, wrappedWriteThreadCount); + + return 0; +} + +static double FindLatestTime(StressLog::StressLogHeader* hdr) +{ + double latestTime = 0.0; + for (ThreadStressLog* tsl = hdr->logs.t; tsl != nullptr; tsl = tsl->next) + { + StressMsg* msg = tsl->curPtr; + double deltaTime = ((double)(msg->timeStamp - hdr->startTimeStamp)) / hdr->tickFrequency; + latestTime = max(latestTime, deltaTime); + } + return latestTime; +} + +static void PrintFriendlyNumber(int n) +{ + if (n < 1000) + printf("%d", n); + else if (n < 1000 * 1000) + printf("%5.3f thousand", n / 1000.0); + else if (n < 1000 * 1000 * 1000) + printf("%8.6f million", n / 1000000.0); + else + printf("%11.9f billion", n / 1000000000.0); +} + +static void PrintMessage(CorClrData& corClrData, FILE *outputFile, uint64_t threadId, StressMsg* msg) +{ + void* argBuffer[StressMsg::maxArgCnt]; + char* format = (char*)(s_hdr->moduleImage + msg->formatOffset); + int numberOfArgs = (msg->numberOfArgsX << 3) + msg->numberOfArgs; + for (int i = 0; i < numberOfArgs; i++) + { + argBuffer[i] = msg->args[i]; + } + double deltaTime = ((double)(msg->timeStamp - s_hdr->startTimeStamp)) / s_hdr->tickFrequency; + if (!s_printHexTidForGcThreads) + { + GcThread gcThread; + if (LookupGcThread(threadId, &gcThread)) + { + threadId = gcThread.heapNumber; + if (gcThread.kind == GC_THREAD_FG) + threadId |= 0x8000000000000000; + else + threadId |= 0x4000000000000000; + } + } + formatOutput(&corClrData, outputFile, format, threadId, deltaTime, msg->facility, argBuffer, s_fPrintFormatStrings); +} + +extern "C" int __declspec(dllexport) ProcessStresslog(void* baseAddress, int argc, wchar_t* argv[]) +{ + if (!ParseOptions(argc, argv)) + return 1; + + StressLog::StressLogHeader* hdr = (StressLog::StressLogHeader*)baseAddress; + if (hdr->headerSize != sizeof(*hdr) || + hdr->magic != 'STRL' || + hdr->version != 0x00010001) + { + printf("Unrecognized file format\n"); + return 1; + } + s_hdr = hdr; + s_threadMsgBuf = new StressThreadAndMsg[MAX_MESSAGE_COUNT]; + int threadStressLogIndex = 0; + double latestTime = FindLatestTime(hdr); + if (s_timeFilterStart < 0) + { + s_timeFilterStart = max(latestTime + s_timeFilterStart, 0); + s_timeFilterEnd = latestTime; + } + for (ThreadStressLog* tsl = hdr->logs.t; tsl != nullptr; tsl = tsl->next) + { + if (!tsl->IsValid()) + continue; + if (!FilterThread(tsl)) + continue; + if (threadStressLogIndex >= MAX_THREADSTRESSLOGS) + { + printf("too many threads\n"); + return 1; + } + s_threadStressLogDesc[threadStressLogIndex].tsl = tsl; + threadStressLogIndex++; + } + s_threadStressLogCount = threadStressLogIndex; + s_wrappedWriteThreadCount = 0; + + SYSTEM_INFO systemInfo; + GetSystemInfo(&systemInfo); + + DWORD threadCount = min(systemInfo.dwNumberOfProcessors, MAXIMUM_WAIT_OBJECTS); + HANDLE threadHandle[64]; + for (DWORD i = 0; i < threadCount; i++) + { + threadHandle[i] = CreateThread(NULL, 0, ProcessStresslogWorker, nullptr, 0, nullptr); + if (threadHandle[i] == 0) + { + printf("CreateThread failed\n"); + return 1; + } + } + WaitForMultipleObjects(threadCount, threadHandle, TRUE, INFINITE); + + // the interlocked increment may have increased s_msgCount beyond MAX_MESSAGE_COUNT - + // make sure we don't go beyond the end of the buffer + s_msgCount = min(s_msgCount, MAX_MESSAGE_COUNT); + + if (s_gcFilterStart != 0) + { + // find the time interval that includes the GCs in question + double startTime = INFINITY; + double endTime = 0.0; + for (int i = s_gcFilterStart; i <= s_gcFilterEnd; i++) + { + startTime = min(startTime, s_gcStartEnd[i].startTime); + if (s_gcStartEnd[i].endTime != 0.0) + { + endTime = max(endTime, s_gcStartEnd[i].endTime); + } + else + { + // haven't seen the end - assume it's still in progress + endTime = latestTime; + } + } + + // remove all messages outside of this time interval + int remMsgCount = 0; + for (int msgIndex = 0; msgIndex < s_msgCount; msgIndex++) + { + StressMsg* msg = s_threadMsgBuf[msgIndex].msg; + double deltaTime = ((double)(msg->timeStamp - hdr->startTimeStamp)) / hdr->tickFrequency; + if (startTime <= deltaTime && deltaTime <= endTime) + { + s_threadMsgBuf[remMsgCount] = s_threadMsgBuf[msgIndex]; + remMsgCount++; + } + } + s_msgCount = remMsgCount; + } + + if (s_hadGcThreadFilters) + { + for (int k = GC_THREAD_FG; k <= GC_THREAD_BG; k++) + { + for (int heap = 0; heap <= s_maxHeapNumberSeen; heap++) + { + if (s_gcThreadFilter[heap][k]) + { + uint64_t threadId = s_threadIdOfHeap[heap][k]; + if (threadId != 0) + { + if (s_threadFilterCount < MAX_THREAD_FILTERS) + { + int i = s_threadFilterCount++; + s_threadFilter[i] = threadId; + } + else + { + printf("too many thread filters, max = %d\n", MAX_THREAD_FILTERS); + } + } + else + { + printf("don't know thread id for GC%d, ignoring\n", heap); + } + } + } + } + } + + if (s_threadFilterCount > 0) + { + // remove all messages from other threads + int remMsgCount = 0; + for (int msgIndex = 0; msgIndex < s_msgCount; msgIndex++) + { + uint64_t threadId = s_threadMsgBuf[msgIndex].threadId; + for (int i = 0; i < s_threadFilterCount; i++) + { + if (threadId == s_threadFilter[i]) + { + s_threadMsgBuf[remMsgCount] = s_threadMsgBuf[msgIndex]; + remMsgCount++; + break; + } + } + } + s_msgCount = remMsgCount; + } + + // if the sort becomes a bottleneck, we can do a bucket sort by time + // (say fractions of a second), then sort the individual buckets, + // perhaps on multiple threads + qsort(s_threadMsgBuf, s_msgCount, sizeof(s_threadMsgBuf[0]), CmpMsg); + + CorClrData corClrData(hdr); + FILE* outputFile = stdout; + if (s_outputFileName != nullptr) + { + if (_wfopen_s(&outputFile, s_outputFileName, L"w") != 0) + { + printf("could not create output file %S\n", s_outputFileName); + outputFile = stdout; + } + } + + for (size_t i = 0; i < s_msgCount; i++) + { + uint64_t threadId = (unsigned)s_threadMsgBuf[i].threadId; + StressMsg* msg = s_threadMsgBuf[i].msg; + PrintMessage(corClrData, outputFile, threadId, msg); + } + + for (int k = GC_THREAD_FG; k <= GC_THREAD_BG; k++) + { + for (int heap = 0; heap <= s_maxHeapNumberSeen; heap++) + { + uint64_t threadId = s_threadIdOfHeap[heap][k]; + if (threadId != 0) + { + if (s_printEarliestMessageFromGcThread[heap][k]) + { + if (s_printEarliestMessageFromThreadCount < MAX_THREAD_FILTERS) + { + int i = s_printEarliestMessageFromThreadCount++; + s_printEarliestMessageFromThread[i] = threadId; + } + else + { + printf("too many threads, max = %d\n", MAX_THREAD_FILTERS); + } + } + } + else + { + printf("don't know thread id for GC%d, ignoring\n", heap); + } + } + } + + if (s_printEarliestMessages || s_printEarliestMessageFromThreadCount > 0) + { + fprintf(outputFile, "\nEarliestMessages:\n"); + LONG earliestStartCount = s_msgCount; + for (int threadStressLogIndex = 0; threadStressLogIndex < s_threadStressLogCount; threadStressLogIndex++) + { + StressMsg* msg = s_threadStressLogDesc[threadStressLogIndex].earliestMessage; + if (msg == nullptr) + continue; + bool fIncludeMessage = s_printEarliestMessages; + uint64_t threadId = s_threadStressLogDesc[threadStressLogIndex].tsl->threadId; + if (!fIncludeMessage) + { + for (int i = 0; i < s_printEarliestMessageFromThreadCount; i++) + { + if (threadId == s_printEarliestMessageFromThread[i]) + { + fIncludeMessage = true; + break; + } + } + } + if (fIncludeMessage) + { + IncludeMessage(threadId, msg); + } + } + qsort(&s_threadMsgBuf[earliestStartCount], s_msgCount - earliestStartCount, sizeof(s_threadMsgBuf[0]), CmpMsg); + for (size_t i = earliestStartCount; i < s_msgCount; i++) + { + uint64_t threadId = (unsigned)s_threadMsgBuf[i].threadId; + StressMsg* msg = s_threadMsgBuf[i].msg; + PrintMessage(corClrData, outputFile, threadId, msg); + } + } + + if (outputFile != stdout) + fclose(outputFile); + + ptrdiff_t usedSize = hdr->memoryCur - hdr->memoryBase; + ptrdiff_t availSize = hdr->memoryLimit - hdr->memoryCur; + printf("Used file size: %6.3f GB, still available: %6.3f GB, %d threads total, %d overwrote earlier messages\n", + (double)usedSize / (1024 * 1024 * 1024), (double)availSize/ (1024 * 1024 * 1024), + s_threadStressLogCount, s_wrappedWriteThreadCount); + if (hdr->threadsWithNoLog != 0) + printf("%Id threads did not get a log!\n", hdr->threadsWithNoLog); + printf("Number of messages examined: "); PrintFriendlyNumber(s_totalMsgCount); printf(", printed: "); PrintFriendlyNumber(s_msgCount); printf("\n"); + + delete[] s_threadMsgBuf; + + return 0; +} + +BOOL APIENTRY DllMain( HMODULE hModule, + DWORD ul_reason_for_call, + LPVOID lpReserved + ) +{ + switch (ul_reason_for_call) + { + case DLL_PROCESS_ATTACH: + case DLL_THREAD_ATTACH: + case DLL_THREAD_DETACH: + case DLL_PROCESS_DETACH: + break; + } + return TRUE; +} + diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj new file mode 100644 index 0000000..1fe578f --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj @@ -0,0 +1,174 @@ + + + + + Debug + Win32 + + + Release + Win32 + + + Debug + x64 + + + Release + x64 + + + + 16.0 + Win32Proj + {6badda84-5ed3-40ef-b4a5-553c446d43aa} + StressLogPlugin + 10.0 + + + + DynamicLibrary + true + v142 + Unicode + + + DynamicLibrary + false + v142 + true + Unicode + + + DynamicLibrary + true + v142 + Unicode + + + DynamicLibrary + false + v142 + true + Unicode + + + + + + + + + + + + + + + + + + + + + true + + + false + + + true + + + false + true + + + $(BaseOutputPath)..\StressLogAnalyzer\$(Platform)\$(Configuration)\ + + + + Level3 + true + WIN32;_DEBUG;STRESSLOGPLUGIN_EXPORTS;_WINDOWS;_USRDLL;%(PreprocessorDefinitions) + true + Use + pch.h + + + Windows + true + false + + + + + Level3 + true + true + true + WIN32;NDEBUG;STRESSLOGPLUGIN_EXPORTS;_WINDOWS;_USRDLL;%(PreprocessorDefinitions) + true + Use + pch.h + + + Windows + true + true + true + false + + + + + Level3 + true + _DEBUG;STRESSLOGPLUGIN_EXPORTS;_WINDOWS;_USRDLL;%(PreprocessorDefinitions) + true + Use + pch.h + + + Windows + true + false + + + + + Level3 + true + true + true + NDEBUG;STRESSLOGPLUGIN_EXPORTS;_WINDOWS;_USRDLL;%(PreprocessorDefinitions) + true + Use + pch.h + + + Windows + true + true + true + false + + + + + + + + + + + Create + Create + Create + Create + + + + + + \ No newline at end of file diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj.filters b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj.filters new file mode 100644 index 0000000..e2dabc4 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/StressLogPlugin.vcxproj.filters @@ -0,0 +1,36 @@ + + + + + {4FC737F1-C7A5-4376-A066-2A32D752A2FF} + cpp;c;cc;cxx;c++;cppm;ixx;def;odl;idl;hpj;bat;asm;asmx + + + {93995380-89BD-4b04-88EB-625FBE52EBFB} + h;hh;hpp;hxx;h++;hm;inl;inc;ipp;xsd + + + {67DA6AB6-F800-4c08-8B7A-83BB121AAD01} + rc;ico;cur;bmp;dlg;rc2;rct;bin;rgs;gif;jpg;jpeg;jpe;resx;tiff;tif;png;wav;mfcribbon-ms + + + + + Headerdateien + + + Headerdateien + + + + + Quelldateien + + + Quelldateien + + + Quelldateien + + + \ No newline at end of file diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/framework.h b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/framework.h new file mode 100644 index 0000000..8f61743 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/framework.h @@ -0,0 +1,8 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#pragma once + +#define WIN32_LEAN_AND_MEAN // Selten verwendete Komponenten aus Windows-Headern ausschließen +// Windows-Headerdateien +#include diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.cpp new file mode 100644 index 0000000..997542f --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.cpp @@ -0,0 +1,6 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#include "pch.h" + +// Bei der Verwendung vorkompilierter Header ist diese Quelldatei für eine erfolgreiche Kompilierung erforderlich. diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.h b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.h new file mode 100644 index 0000000..8ea9a9f --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/pch.h @@ -0,0 +1,8 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#ifndef PCH_H +#define PCH_H + +// Fügen Sie hier Header hinzu, die vorkompiliert werden sollen. +#endif //PCH_H diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/staticcontract.h b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/staticcontract.h new file mode 100644 index 0000000..31fa681 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/staticcontract.h @@ -0,0 +1,6 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#define _ASSERTE(a) +#define STATIC_CONTRACT_LEAF +#define STATIC_CONTRACT_WRAPPER diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/stressLogDump.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/stressLogDump.cpp new file mode 100644 index 0000000..6d903e6 --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/stressLogDump.cpp @@ -0,0 +1,564 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +// ==++== +// + +// +// ==--== +#include "pch.h" + +#include "strike.h" +#include "util.h" +#include +#include + +#ifndef STRESS_LOG +#define STRESS_LOG +#endif // STRESS_LOG +#define STRESS_LOG_READONLY +#include "../../../inc/stresslog.h" + + +void GcHistClear(); +void GcHistAddLog(LPCSTR msg, StressMsg* stressMsg); + + +/*********************************************************************************/ +static const WCHAR* getTime(const FILETIME* time, __out_ecount (buffLen) WCHAR* buff, int buffLen) +{ + SYSTEMTIME systemTime; + static const WCHAR badTime[] = W("BAD TIME"); + + if (!FileTimeToSystemTime(time, &systemTime)) + return badTime; + +#ifdef FEATURE_PAL + int length = _snwprintf_s(buff, buffLen, _TRUNCATE, W("%02d:%02d:%02d"), systemTime.wHour, systemTime.wMinute, systemTime.wSecond); + if (length <= 0) + return badTime; +#else // FEATURE_PAL + static const WCHAR format[] = W("HH:mm:ss"); + + SYSTEMTIME localTime; + SystemTimeToTzSpecificLocalTime(NULL, &systemTime, &localTime); + + // we want a non null buff for the following + int ret = GetTimeFormatW(LOCALE_USER_DEFAULT, 0, &localTime, format, buff, buffLen); + if (ret == 0) + return badTime; +#endif // FEATURE_PAL else + + return buff; +} + +/*********************************************************************************/ +static inline __int64& toInt64(FILETIME& t) +{ + return *((__int64 *) &t); +} + +/*********************************************************************************/ +ThreadStressLog* ThreadStressLog::FindLatestThreadLog() const +{ + const ThreadStressLog* latestLog = 0; + for (const ThreadStressLog* ptr = this; ptr != NULL; ptr = ptr->next) + { + if (ptr->readPtr != NULL) + if (latestLog == 0 || ptr->readPtr->timeStamp > latestLog->readPtr->timeStamp) + latestLog = ptr; + } + return const_cast(latestLog); +} + +const char *getFacilityName(DWORD_PTR lf) +{ + struct FacilityName_t { size_t lf; const char* lfName; }; + #define DEFINE_LOG_FACILITY(logname, value) {logname, #logname}, + static FacilityName_t facilities[] = + { + #include "../../../inc/loglf.h" + { LF_ALWAYS, "LF_ALWAYS" } + }; + static char buff[1024] = "`"; + if ( lf == LF_ALL ) + { + return "`ALL`"; + } + else if ((((DWORD)lf) & (LF_ALWAYS | 0xfffe | LF_GC)) == (LF_ALWAYS | LF_GC)) + { + sprintf_s<_countof(buff)>(buff, "`GC l=%d`", (lf >> 16) & 0x7fff); + return buff; + } + else + { + buff[1] = '\0'; + for ( int i = 0; i < 32; ++i ) + { + if ( lf & 0x1 ) + { + strcat_s ( buff, _countof(buff), &(facilities[i].lfName[3]) ); + strcat_s ( buff, _countof(buff), "`" ); + } + lf >>= 1; + } + return buff; + } +} + +/***********************************************************************************/ +/* recognize special pretty printing instructions in the format string */ +/* Note that this function might have side effect such that args array value might */ +/* be altered if format string contains %s */ +// TODO: This function assumes the pointer size of the target equals the pointer size of the host +// TODO: replace uses of void* with appropriate TADDR or CLRDATA_ADDRESS +void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, uint64_t threadId, double timeStamp, DWORD_PTR facility, ___in void** args, bool fPrintFormatString) +{ + if (threadId & 0x8000000000000000) + fprintf(file, "GC%2d %13.9f : ", (unsigned)threadId, timeStamp); + else if (threadId & 0x4000000000000000) + fprintf(file, "BG%2d %13.9f : ", (unsigned)threadId, timeStamp); + else + fprintf(file, "%4x %13.9f : ", threadId, timeStamp); + fprintf(file, "%-20s ", getFacilityName ( facility )); + + if (fPrintFormatString) + { + fprintf(file, "***|\"%s\"|*** ", format); + } + CQuickBytes fullname; + void** argsPtr = args; + const SIZE_T capacity_buff = 2048; + LPWSTR buff = (LPWSTR)alloca(capacity_buff * sizeof(WCHAR)); + static char formatCopy[256]; + + int iArgCount = 0; + + strcpy_s(formatCopy, _countof(formatCopy), format); + char* ptr = formatCopy; + format = formatCopy; + for(;;) + { + char c = *ptr++; + if (c == 0) + break; + if (c == '{') // Reverse the '{' 's because the log is displayed backwards + ptr[-1] = '}'; + else if (c == '}') + ptr[-1] = '{'; + else if (c == '%') + { + argsPtr++; // This format will consume one of the args + if (*ptr == '%') + { + ptr++; // skip the whole %% + --argsPtr; // except for a %% + } + else if (*ptr == 'p') + { // It is a %p + ptr++; + if (isalpha(*ptr)) + { // It is a special %p formatter + // Print the string up to that point + c = *ptr; + *ptr = 0; // Terminate the string temporarily + vfprintf(file, format, (va_list)args); + *ptr = c; // Put it back + + // move the argument pointers past the part the was printed + format = ptr + 1; + args = argsPtr; + iArgCount = -1; + DWORD_PTR arg = DWORD_PTR(argsPtr[-1]); + + switch (c) + { + case 'M': // format as a method Desc + if (g_bDacBroken) + { + fprintf(file," (MethodDesc: %p)",arg); + } + else + { + if (!IsMethodDesc(arg)) + { + if (arg != 0) + fprintf(file, " (BAD Method)"); + } + else + { + DacpMethodDescData MethodDescData; + MethodDescData.Request(g_sos,(CLRDATA_ADDRESS)arg); + + static WCHAR wszNameBuffer[1024]; // should be large enough + if (g_sos->GetMethodDescName(arg, 1024, wszNameBuffer, NULL) != S_OK) + { + wcscpy_s(wszNameBuffer, _countof(wszNameBuffer), W("UNKNOWN METHODDESC")); + } + + wcscpy_s(buff, capacity_buff, wszNameBuffer); + fprintf(file, " (%S)", wszNameBuffer); + } + } + break; + + // fall through + case 'T': // format as a MethodTable + if (g_bDacBroken) + { + fprintf(file, "(MethodTable: %p)",arg); + } + else + { + if (arg & 3) + { + arg &= ~3; // GC steals the lower bits for its own use during GC. + fprintf(file, " Low Bit(s) Set"); + } + if (!IsMethodTable(arg)) + { + fprintf(file, " (BAD MethodTable)"); + } + else + { + NameForMT_s (arg, g_mdName, mdNameLen); + fprintf(file, " (%S)", g_mdName); + } + } + break; + + case 'V': + { // format as a C vtable pointer + char Symbol[1024]; + ULONG64 Displacement; + HRESULT hr = g_ExtSymbols->GetNameByOffset(TO_CDADDR(arg), Symbol, 1024, NULL, &Displacement); + if (SUCCEEDED(hr) && Symbol[0] != '\0' && Displacement == 0) + fprintf(file, " (%s)", Symbol); + else + fprintf(file, " (Unknown VTable)"); + } + break; + case 'K': + { // format a frame in stack trace + char Symbol[1024]; + ULONG64 Displacement; + HRESULT hr = g_ExtSymbols->GetNameByOffset (TO_CDADDR(arg), Symbol, 1024, NULL, &Displacement); + if (SUCCEEDED (hr) && Symbol[0] != '\0') + { + fprintf (file, " (%s", Symbol); + if (Displacement) + { + fprintf (file, "+%#x", Displacement); + } + fprintf (file, ")"); + } + else + fprintf (file, " (Unknown function)"); + } + break; + default: + format = ptr; // Just print the character. + } + } + } + else if (*ptr == 's' || (*ptr == 'h' && *(ptr+1) == 's' && ++ptr)) + { + HRESULT hr; + + // need to _alloca, instead of declaring a local buffer + // since we may have more than one %s in the format + ULONG cbStrBuf = 256; + char* strBuf = (char *)_alloca(cbStrBuf); + + hr = memCallBack->ReadVirtual(TO_CDADDR((char* )args[iArgCount]), strBuf, cbStrBuf, 0); + if (hr != S_OK) + { + strcpy_s(strBuf, cbStrBuf, "(#Could not read address of string#)"); + } + + args[iArgCount] = strBuf; + } + else if (*ptr == 'S' || (*ptr == 'l' && *(ptr+1) == 's' && ++ptr)) + { + HRESULT hr; + + // need to _alloca, instead of declaring a local buffer + // since we may have more than one %s in the format + ULONG cbWstrBuf = 256 * sizeof(WCHAR); + WCHAR* wstrBuf = (WCHAR *)_alloca(cbWstrBuf); + + hr = memCallBack->ReadVirtual(TO_CDADDR((char* )args[iArgCount]), wstrBuf, cbWstrBuf, 0); + if (hr != S_OK) + { + wcscpy_s(wstrBuf, cbWstrBuf/sizeof(WCHAR), W("(#Could not read address of string#)")); + } + + args[iArgCount] = wstrBuf; + } + iArgCount++; + } + } + // Print anything after the last special format instruction. + vfprintf(file, format, (va_list)args); + fprintf(file, "\n"); +} + +void __cdecl +vDoOut(BOOL bToConsole, FILE* file, PCSTR Format, ...) +{ + va_list Args; + + va_start(Args, Format); + + if (bToConsole) + { + OutputVaList(DEBUG_OUTPUT_NORMAL, Format, Args); + } + else + { + vfprintf(file, Format, Args); + } + + va_end(Args); +} + + +/*********************************************************************************/ +HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugDataSpaces* memCallBack) +{ + ULONG64 g_hThisInst; + BOOL bDoGcHist = (fileName == NULL); + FILE* file = NULL; + + // Fetch the circular buffer bookkeeping data + StressLog inProcLog; + HRESULT hr = memCallBack->ReadVirtual(UL64_TO_CDA(outProcLog), &inProcLog, sizeof(StressLog), 0); + if (hr != S_OK) + { + return hr; + } + if (inProcLog.logs.Load() == NULL || inProcLog.moduleOffset == 0) + { + ExtOut ( "----- No thread logs in the image: The stress log was probably not initialized correctly. -----\n"); + return S_FALSE; + } + + g_hThisInst = (ULONG64) inProcLog.moduleOffset; + + if (bDoGcHist) + { + GcHistClear(); + } + else + { + ExtOut("Writing to file: %s\n", fileName); + ExtOut("Stress log in module 0x%p\n", SOS_PTR(g_hThisInst)); + ExtOut("Stress log address = 0x%p\n", SOS_PTR(outProcLog)); + } + // Fetch the circular buffers for each thread into the 'logs' list + ThreadStressLog* logs = 0; + + CLRDATA_ADDRESS outProcPtr = TO_CDADDR(inProcLog.logs.Load()); + ThreadStressLog* inProcPtr; + ThreadStressLog** logsPtr = &logs; + int threadCtr = 0; + unsigned __int64 lastTimeStamp = 0;// timestamp of last log entry + + while(outProcPtr != 0) { + inProcPtr = new ThreadStressLog; + hr = memCallBack->ReadVirtual(outProcPtr, inProcPtr, sizeof (*inProcPtr), 0); + if (hr != S_OK || inProcPtr->chunkListHead == NULL) + { + delete inProcPtr; + goto FREE_MEM; + } + + CLRDATA_ADDRESS outProcListHead = TO_CDADDR(inProcPtr->chunkListHead); + CLRDATA_ADDRESS outProcChunkPtr = outProcListHead; + StressLogChunk ** chunksPtr = &inProcPtr->chunkListHead; + StressLogChunk * inProcPrevChunkPtr = NULL; + BOOL curPtrInitialized = FALSE; + do + { + StressLogChunk * inProcChunkPtr = new StressLogChunk; + hr = memCallBack->ReadVirtual (outProcChunkPtr, inProcChunkPtr, sizeof (*inProcChunkPtr), NULL); + if (hr != S_OK || !inProcChunkPtr->IsValid ()) + { + if (hr != S_OK) + ExtOut ("ReadVirtual failed with code hr = %x.\n", hr ); + else + ExtOut ("Invalid stress log chunk: %p", SOS_PTR(outProcChunkPtr)); + + // Now cleanup + delete inProcChunkPtr; + // if this is the first time through, inProcPtr->chunkListHead may still contain + // the out-of-process value for the chunk pointer. NULL it to avoid AVs + if (TO_CDADDR(inProcPtr->chunkListHead) == outProcListHead) + inProcPtr->chunkListHead = NULL; + delete inProcPtr; + goto FREE_MEM; + } + + if (!curPtrInitialized && outProcChunkPtr == TO_CDADDR(inProcPtr->curWriteChunk)) + { + inProcPtr->curPtr = (StressMsg *)((BYTE *)inProcChunkPtr + ((BYTE *)inProcPtr->curPtr - (BYTE *)inProcPtr->curWriteChunk)); + inProcPtr->curWriteChunk = inProcChunkPtr; + curPtrInitialized = TRUE; + } + + outProcChunkPtr = TO_CDADDR(inProcChunkPtr->next); + *chunksPtr = inProcChunkPtr; + chunksPtr = &inProcChunkPtr->next; + inProcChunkPtr->prev = inProcPrevChunkPtr; + inProcPrevChunkPtr = inProcChunkPtr; + + if (outProcChunkPtr == outProcListHead) + { + inProcChunkPtr->next = inProcPtr->chunkListHead; + inProcPtr->chunkListHead->prev = inProcChunkPtr; + inProcPtr->chunkListTail = inProcChunkPtr; + } + } while (outProcChunkPtr != outProcListHead); + + if (!curPtrInitialized) + { + delete inProcPtr; + goto FREE_MEM; + } + + // TODO: fix on 64 bit + inProcPtr->Activate (); + if (inProcPtr->readPtr->timeStamp > lastTimeStamp) + { + lastTimeStamp = inProcPtr->readPtr->timeStamp; + } + + outProcPtr = TO_CDADDR(inProcPtr->next); + *logsPtr = inProcPtr; + logsPtr = &inProcPtr->next; + threadCtr++; + } + + if (!bDoGcHist && ((fopen_s(&file, fileName, "w")) != 0)) + { + hr = GetLastError(); + goto FREE_MEM; + } + hr = S_FALSE; // return false if there are no message to print to the log + + vDoOut(bDoGcHist, file, "STRESS LOG:\n" + " facilitiesToLog = 0x%x\n" + " levelToLog = %d\n" + " MaxLogSizePerThread = 0x%x (%d)\n" + " MaxTotalLogSize = 0x%x (%d)\n" + " CurrentTotalLogChunk = %d\n" + " ThreadsWithLogs = %d\n", + inProcLog.facilitiesToLog, inProcLog.levelToLog, inProcLog.MaxSizePerThread, inProcLog.MaxSizePerThread, + inProcLog.MaxSizeTotal, inProcLog.MaxSizeTotal, inProcLog.totalChunk.Load(), threadCtr); + + FILETIME endTime; + double totalSecs; + totalSecs = ((double) (lastTimeStamp - inProcLog.startTimeStamp)) / inProcLog.tickFrequency; + toInt64(endTime) = toInt64(inProcLog.startTime) + ((__int64) (totalSecs * 1.0E7)); + + WCHAR timeBuff[64]; + vDoOut(bDoGcHist, file, " Clock frequency = %5.3f GHz\n", inProcLog.tickFrequency / 1.0E9); + vDoOut(bDoGcHist, file, " Start time %S\n", getTime(&inProcLog.startTime, timeBuff, 64)); + vDoOut(bDoGcHist, file, " Last message time %S\n", getTime(&endTime, timeBuff, 64)); + vDoOut(bDoGcHist, file, " Total elapsed time %5.3f sec\n", totalSecs); + + if (!bDoGcHist) + { + fprintf(file, "\nTHREAD TIMESTAMP FACILITY MESSAGE\n"); + fprintf(file, " ID (sec from start)\n"); + fprintf(file, "--------------------------------------------------------------------------------------\n"); + } + char format[257]; + format[256] = format[0] = 0; + void** args; + unsigned msgCtr; + msgCtr = 0; + for (;;) + { + ThreadStressLog* latestLog = logs->FindLatestThreadLog(); + + if (IsInterrupt()) + { + vDoOut(bDoGcHist, file, "----- Interrupted by user -----\n"); + break; + } + + if (latestLog == 0) + { + break; + } + + StressMsg* latestMsg = latestLog->readPtr; + if (latestMsg->formatOffset != 0 && !latestLog->CompletedDump()) + { + TADDR taFmt = (latestMsg->formatOffset) + TO_TADDR(g_hThisInst); + hr = memCallBack->ReadVirtual(TO_CDADDR(taFmt), format, 256, 0); + if (hr != S_OK) + strcpy_s(format, _countof(format), "Could not read address of format string"); + + double deltaTime = ((double) (latestMsg->timeStamp - inProcLog.startTimeStamp)) / inProcLog.tickFrequency; + if (bDoGcHist) + { + if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0) + { + latestLog->threadId = (unsigned)(size_t)latestMsg->args[0]; + } + GcHistAddLog(format, latestMsg); + } + else + { + if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0) + { + fprintf (file, "Task was switched from %x\n", (unsigned)(size_t)latestMsg->args[0]); + latestLog->threadId = (unsigned)(size_t)latestMsg->args[0]; + } + else + { + args = latestMsg->args; + formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg->facility, args); + } + } + msgCtr++; + } + + latestLog->readPtr = latestLog->AdvanceRead(); + if (latestLog->CompletedDump()) + { + latestLog->readPtr = NULL; + if (!bDoGcHist) + { + fprintf(file, "------------ Last message from thread %x -----------\n", latestLog->threadId); + } + } + + if (msgCtr % 64 == 0) + { + ExtOut("."); // to indicate progress + if (msgCtr % (64*64) == 0) + ExtOut("\n"); + } + } + ExtOut("\n"); + + vDoOut(bDoGcHist, file, "---------------------------- %d total entries ------------------------------------\n", msgCtr); + if (!bDoGcHist) + { + fclose(file); + } + +FREE_MEM: + // clean up the 'logs' list + while (logs) { + ThreadStressLog* temp = logs; + logs = logs->next; + delete temp; + } + + return hr; +} + diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/strike.h b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/strike.h new file mode 100644 index 0000000..c627b7a --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/strike.h @@ -0,0 +1,67 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#include +#include + +#define HOST_64BIT + +typedef unsigned char uint8_t; +typedef unsigned int uint32_t; +typedef size_t uint64_t; +typedef void* TADDR; +extern BOOL g_bDacBroken; + +#define IsMethodDesc(m) FALSE +#define IsMethodTable(mt) FALSE +#define IsInterrupt() FALSE + +#define NameForMT_s(a,b,c) +#define DEBUG_OUTPUT_NORMAL 0x00000001 + +extern WCHAR g_mdName[1]; + +struct SOS +{ + HRESULT GetMethodDescName(DWORD_PTR arg, size_t bufferSize, WCHAR* buffer, void*) + { + return S_FALSE; + } +}; + +extern SOS* g_sos; + +#define TO_CDADDR(a) a +#define UL64_TO_CDA(a) ((void*)a) +#define SOS_PTR(a) a +#define TO_TADDR(a) ((char *)a) + +struct SYMBOLS +{ + HRESULT GetNameByOffset(DWORD_PTR arg, char *buffer, size_t bufferSize, void*, ULONG64 *displacement) + { + return S_FALSE; + } +}; + +extern SYMBOLS* g_ExtSymbols; + +typedef void* CLRDATA_ADDRESS; + +struct DacpMethodDescData +{ + int whatever; + void Request(void*, CLRDATA_ADDRESS a) + { + } +}; + +struct IDebugDataSpaces +{ + virtual HRESULT ReadVirtual(void* src, void* dest, size_t size, int) = 0; +}; + +HRESULT OutputVaList(ULONG mask, PCSTR format, va_list args); +void ExtOut(PCSTR format, ...); +#define ___in +void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, uint64_t threadId, double timeStamp, DWORD_PTR facility, ___in void** args, bool fPrintFormatString = false); diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/util.h b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/util.h new file mode 100644 index 0000000..b890aef --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin/util.h @@ -0,0 +1,159 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +template +struct Volatile +{ + T t; + T Load() { return t; } +}; + +typedef void* CRITSEC_COOKIE; + +#define STRESS_LOG_ANALYZER + +#include +#include "staticcontract.h" + +// This macro is used to standardize the wide character string literals between UNIX and Windows. +// Unix L"" is UTF32, and on windows it's UTF16. Because of built-in assumptions on the size +// of string literals, it's important to match behaviour between Unix and Windows. Unix will be defined +// as u"" (char16_t) +#ifdef PLATFORM_UNIX +#define W(str) u##str +#else // PLATFORM_UNIX +#define W(str) L##str +#endif // PLATFORM_UNIX + +//***************************************************************************** +// +// **** CQuickBytes +// This helper class is useful for cases where 90% of the time you allocate 512 +// or less bytes for a data structure. This class contains a 512 byte buffer. +// Alloc() will return a pointer to this buffer if your allocation is small +// enough, otherwise it asks the heap for a larger buffer which is freed for +// you. No mutex locking is required for the small allocation case, making the +// code run faster, less heap fragmentation, etc... Each instance will allocate +// 520 bytes, so use accordinly. +// +//***************************************************************************** +template +class CQuickBytesBase +{ +public: + CQuickBytesBase() : + pbBuff(0), + iSize(0), + cbTotal(SIZE) + { } + + void Destroy() + { + if (pbBuff) + { + delete[](BYTE*)pbBuff; + pbBuff = 0; + } + } + + void* Alloc(SIZE_T iItems) + { + iSize = iItems; + if (iItems <= SIZE) + { + cbTotal = SIZE; + return (&rgData[0]); + } + else + { + if (pbBuff) + delete[](BYTE*)pbBuff; + pbBuff = new BYTE[iItems]; + cbTotal = pbBuff ? iItems : 0; + return (pbBuff); + } + } + + // This is for conformity to the CQuickBytesBase that is defined by the runtime so + // that we can use it inside of some GC code that SOS seems to include as well. + // + // The plain vanilla "Alloc" version on this CQuickBytesBase doesn't throw either, + // so we'll just forward the call. + void* AllocNoThrow(SIZE_T iItems) + { + return Alloc(iItems); + } + + HRESULT ReSize(SIZE_T iItems) + { + void* pbBuffNew; + if (iItems <= cbTotal) + { + iSize = iItems; + return NOERROR; + } + + pbBuffNew = new BYTE[iItems + INCREMENT]; + if (!pbBuffNew) + return E_OUTOFMEMORY; + if (pbBuff) + { + memcpy(pbBuffNew, pbBuff, cbTotal); + delete[](BYTE*)pbBuff; + } + else + { + _ASSERTE(cbTotal == SIZE); + memcpy(pbBuffNew, rgData, SIZE); + } + cbTotal = iItems + INCREMENT; + iSize = iItems; + pbBuff = pbBuffNew; + return NOERROR; + + } + + operator PVOID() + { + return ((pbBuff) ? pbBuff : &rgData[0]); + } + + void* Ptr() + { + return ((pbBuff) ? pbBuff : &rgData[0]); + } + + SIZE_T Size() + { + return (iSize); + } + + SIZE_T MaxSize() + { + return (cbTotal); + } + + void* pbBuff; + SIZE_T iSize; // number of bytes used + SIZE_T cbTotal; // total bytes allocated in the buffer + // use UINT64 to enforce the alignment of the memory + UINT64 rgData[(SIZE + sizeof(UINT64) - 1) / sizeof(UINT64)]; +}; + +#define CQUICKBYTES_BASE_SIZE 512 +#define CQUICKBYTES_INCREMENTAL_SIZE 128 + +class CQuickBytesNoDtor : public CQuickBytesBase +{ +}; + +class CQuickBytes : public CQuickBytesNoDtor +{ +public: + CQuickBytes() { } + + ~CQuickBytes() + { + Destroy(); + } +}; diff --git a/src/coreclr/utilcode/stresslog.cpp b/src/coreclr/utilcode/stresslog.cpp index 1080804..2b81551 100644 --- a/src/coreclr/utilcode/stresslog.cpp +++ b/src/coreclr/utilcode/stresslog.cpp @@ -21,6 +21,7 @@ HANDLE StressLogChunk::s_LogChunkHeap = NULL; #endif thread_local ThreadStressLog* StressLog::t_pCurrentThreadLog; +thread_local bool t_triedToCreateThreadStressLog; #endif // !STRESS_LOG_READONLY /*********************************************************************************/ @@ -140,8 +141,8 @@ void StressLog::Leave(CRITSEC_COOKIE) { } /*********************************************************************************/ -void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxBytesPerThread, - unsigned maxBytesTotal, void* moduleBase) +void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxBytesPerThread, + ULONGLONG maxBytesTotal, void* moduleBase, LPWSTR logFilename) { STATIC_CONTRACT_LEAF; @@ -151,7 +152,7 @@ void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxByt return; } - theLog.lock = ClrCreateCriticalSection(CrstStressLog,(CrstFlags)(CRST_UNSAFE_ANYMODE|CRST_DEBUGGER_THREAD|CRST_TAKEN_DURING_SHUTDOWN)); + theLog.lock = ClrCreateCriticalSection(CrstStressLog, (CrstFlags)(CRST_UNSAFE_ANYMODE | CRST_DEBUGGER_THREAD | CRST_TAKEN_DURING_SHUTDOWN)); // StressLog::Terminate is going to free memory. if (maxBytesPerThread < STRESSLOG_CHUNK_SIZE) { @@ -163,7 +164,7 @@ void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxByt { maxBytesTotal = STRESSLOG_CHUNK_SIZE * 256; } - theLog.MaxSizeTotal = maxBytesTotal; + theLog.MaxSizeTotal = (unsigned)min(maxBytesTotal, 0xffffffff);; theLog.totalChunk = 0; theLog.facilitiesToLog = facilities | LF_ALWAYS; theLog.levelToLog = level; @@ -171,7 +172,7 @@ void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxByt theLog.tickFrequency = getTickFrequency(); - GetSystemTimeAsFileTime (&theLog.startTime); + GetSystemTimeAsFileTime(&theLog.startTime); theLog.startTimeStamp = getTimeStamp(); theLog.moduleOffset = (SIZE_T)moduleBase; @@ -179,18 +180,113 @@ void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxByt #ifdef _DEBUG HMODULE hModNtdll = GetModuleHandleA("ntdll.dll"); theLog.RtlCaptureStackBackTrace = reinterpret_cast( - GetProcAddress(hModNtdll, "RtlCaptureStackBackTrace")); + GetProcAddress(hModNtdll, "RtlCaptureStackBackTrace")); #endif // _DEBUG #endif // !HOST_UNIX #if !defined (STRESS_LOG_READONLY) && defined(HOST_WINDOWS) - StressLogChunk::s_LogChunkHeap = HeapCreate (0, STRESSLOG_CHUNK_SIZE * 128, 0); - if (StressLogChunk::s_LogChunkHeap == NULL) + if (logFilename == nullptr) { - StressLogChunk::s_LogChunkHeap = GetProcessHeap (); + StressLogChunk::s_LogChunkHeap = HeapCreate(0, STRESSLOG_CHUNK_SIZE * 128, 0); + if (StressLogChunk::s_LogChunkHeap == NULL) + { + StressLogChunk::s_LogChunkHeap = GetProcessHeap(); + } + _ASSERTE(StressLogChunk::s_LogChunkHeap); } - _ASSERTE (StressLogChunk::s_LogChunkHeap); #endif //!STRESS_LOG_READONLY + +#ifdef MEMORY_MAPPED_STRESSLOG + if (logFilename != nullptr) + { + if (maxBytesTotal < sizeof(StressLogHeader)) + { + return; + } + HandleHolder hFile = WszCreateFile(logFilename, + GENERIC_READ | GENERIC_WRITE, + FILE_SHARE_READ, + NULL, // default security descriptor + CREATE_ALWAYS, + FILE_ATTRIBUTE_NORMAL, + NULL); + + if (hFile == INVALID_HANDLE_VALUE) + { + return; + } + + size_t fileSize = maxBytesTotal; + HandleHolder hMap = WszCreateFileMapping(hFile, NULL, PAGE_READWRITE, (DWORD)(fileSize >> 32), (DWORD)fileSize, NULL); + if (hMap == NULL) + { + return; + } + + theLog.hMapView = MapViewOfFileEx(hMap, FILE_MAP_ALL_ACCESS, 0, 0, fileSize, (void*)0x400000000000); + if (theLog.hMapView == NULL) + { + return; + } + + StressLogHeader* hdr = (StressLogHeader*)(uint8_t*)(void*)theLog.hMapView; + hdr->headerSize = sizeof(StressLogHeader); + hdr->magic = 'STRL'; + hdr->version = 0x00010001; + hdr->memoryBase = (uint8_t*)hdr; + hdr->memoryCur = hdr->memoryBase + sizeof(StressLogHeader); + hdr->memoryLimit = hdr->memoryBase + fileSize; + hdr->logs = nullptr; + hdr->tickFrequency = theLog.tickFrequency; + hdr->startTimeStamp = theLog.startTimeStamp; + theLog.stressLogHeader = hdr; + + // copy coreclr image - just for the string literals + AddModule((uint8_t*)moduleBase); + } +#endif +} + +void StressLog::AddModule(uint8_t* moduleBase) +{ +#ifdef MEMORY_MAPPED_STRESSLOG + int moduleIndex = 0; + StressLogHeader* hdr = theLog.stressLogHeader; + if (hdr == nullptr) + { + // nothing to do for the non-memory mapped stress log + return; + } + size_t cumSize = 0; + while (moduleIndex < MAX_MODULES && hdr->modules[moduleIndex].baseAddress != nullptr) + { + if (hdr->modules[moduleIndex].baseAddress == moduleBase) + return; + cumSize += hdr->modules[moduleIndex].size; + moduleIndex++; + } + if (moduleIndex >= MAX_MODULES) + { + DebugBreak(); + return; + } + hdr->modules[moduleIndex].baseAddress = moduleBase; + uint8_t* addr = moduleBase; + while (true) + { + MEMORY_BASIC_INFORMATION mbi; + size_t size = VirtualQuery(addr, &mbi, sizeof(mbi)); + if (size == 0) + break; + // copy the region containing string literals to the memory mapped file + if (mbi.AllocationBase != moduleBase) + break; + ptrdiff_t offs = (uint8_t*)mbi.BaseAddress - (uint8_t*)mbi.AllocationBase + cumSize; + memcpy(&hdr->moduleImage[offs], mbi.BaseAddress, mbi.RegionSize); + addr += mbi.RegionSize; + hdr->modules[moduleIndex].size = (size_t)(addr - (uint8_t*)moduleBase); + } +#endif //MEMORY_MAPPED_STRESSLOG } /*********************************************************************************/ @@ -259,7 +355,7 @@ ThreadStressLog* StressLog::CreateThreadStressLog() { return NULL; } -#ifdef HOST_WINDOWS +#if defined(HOST_WINDOWS) && !defined(MEMORY_MAPPED_STRESSLOG) if (!StressLogChunk::s_LogChunkHeap) { return NULL; @@ -397,9 +493,28 @@ ThreadStressLog* StressLog::CreateThreadStressLogHelper() { { delete msgs; msgs = 0; +#ifdef MEMORY_MAPPED_STRESSLOG + if (!t_triedToCreateThreadStressLog && theLog.stressLogHeader != nullptr) + { + theLog.stressLogHeader->threadsWithNoLog++; + t_triedToCreateThreadStressLog = true; + } +#endif //MEMORY_MAPPED_STRESSLOG goto LEAVE; } } + else + { + // recycle old thread msg + msgs->threadId = GetCurrentThreadId(); + StressLogChunk* slc = msgs->chunkListHead; + while (true) + { + if (slc == msgs->chunkListTail) + break; + slc = slc->next; + } + } msgs->Activate (); @@ -417,6 +532,10 @@ ThreadStressLog* StressLog::CreateThreadStressLogHelper() { // Put it into the stress log msgs->next = theLog.logs; theLog.logs = msgs; +#ifdef MEMORY_MAPPED_STRESSLOG + if (theLog.stressLogHeader != nullptr) + theLog.stressLogHeader->logs = msgs; +#endif // MEMORY_MAPPED_STRESSLOG } LEAVE: @@ -470,7 +589,7 @@ BOOL StressLog::AllowNewChunk (LONG numChunksInCurThread) return FALSE; } - return (DWORD)theLog.totalChunk * STRESSLOG_CHUNK_SIZE < theLog.MaxSizeTotal; + return theLog.MaxSizeTotal == 0xffffffff || (DWORD)theLog.totalChunk * STRESSLOG_CHUNK_SIZE < theLog.MaxSizeTotal; } BOOL StressLog::ReserveStressLogChunks (unsigned chunksToReserve) @@ -521,45 +640,75 @@ void TrackSO(BOOL tolerance) /*********************************************************************************/ /* fetch a buffer that can be used to write a stress message, it is thread safe */ -void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, va_list Args) +FORCEINLINE void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, va_list Args) { STATIC_CONTRACT_NOTHROW; STATIC_CONTRACT_FORBID_FAULT; - // Asserts in this function cause infinite loops in the asserting mechanism. - // Just use debug breaks instead. + // Asserts in this function cause infinite loops in the asserting mechanism. + // Just use debug breaks instead. #ifndef DACCESS_COMPILE #ifdef _DEBUG - // _ASSERTE ( cArgs >= 0 && cArgs <= 7 ); - if (cArgs < 0 || cArgs > 7) DebugBreak(); + // _ASSERTE ( cArgs >= 0 && cArgs <= 63 ); + if (cArgs < 0 || cArgs > 63) DebugBreak(); #endif // - size_t offs = ((size_t)format - StressLog::theLog.moduleOffset); + size_t offs = 0; +#ifdef MEMORY_MAPPED_STRESSLOG + StressLog::StressLogHeader* hdr = StressLog::theLog.stressLogHeader; + if (hdr != nullptr) + { + int moduleIndex = 0; + size_t cumSize = 0; + offs = 0; + while (moduleIndex < StressLog::MAX_MODULES) + { + offs = (uint8_t*)format - hdr->modules[moduleIndex].baseAddress; + if (offs < hdr->modules[moduleIndex].size) + { + offs += cumSize; + break; + } + cumSize += hdr->modules[moduleIndex].size; + moduleIndex++; + } + } + else +#endif // MEMORY_MAPPED_STRESSLOG + { +#ifdef _DEBUG + // currently SOS stress log only supports a maximum of 7 arguments + if (cArgs > 7) + DebugBreak(); +#endif //_DEBUG + offs = ((size_t)format - StressLog::theLog.moduleOffset); + } // _ASSERTE ( offs < StressMsg::maxOffset ); - if (offs >= StressMsg::maxOffset) - { + if (offs >= StressMsg::maxOffset) + { #ifdef _DEBUG - DebugBreak(); // in lieu of the above _ASSERTE + DebugBreak(); // in lieu of the above _ASSERTE #endif // _DEBUG - // Set it to this string instead. - offs = + // Set it to this string instead. + offs = #ifdef _DEBUG - (size_t)""; + (size_t)""; #else // _DEBUG - 0; // a 0 offset is ignored by StressLog::Dump + 0; // a 0 offset is ignored by StressLog::Dump #endif // _DEBUG else - } + } // Get next available slot StressMsg* msg = AdvanceWrite(cArgs); msg->timeStamp = getTimeStamp(); msg->facility = facility; - msg->formatOffset = offs; - msg->numberOfArgs = cArgs; + msg->formatOffset = offs; + msg->numberOfArgs = cArgs & 0x7; + msg->numberOfArgsX = cArgs >> 3; for ( int i = 0; i < cArgs; ++i ) { @@ -567,6 +716,9 @@ void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, v msg->args[i] = data; } + // only store curPtr once the msg is complete + curPtr = msg; + #ifdef _DEBUG if (!IsValid () || threadId != GetCurrentThreadId ()) DebugBreak(); @@ -574,6 +726,14 @@ void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, v #endif //DACCESS_COMPILE } +void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, ...) +{ + va_list Args; + va_start(Args, format); + LogMsg(facility, cArgs, format, Args); + va_end(Args); +} + FORCEINLINE BOOL StressLog::InlinedStressLogOn(unsigned facility, unsigned level) { STATIC_CONTRACT_LEAF; @@ -621,7 +781,7 @@ BOOL StressLog::LogOn(unsigned facility, unsigned level) #endif /* static */ -void StressLog::LogMsg (unsigned level, unsigned facility, int cArgs, const char* format, ... ) +void StressLog::LogMsg(unsigned level, unsigned facility, int cArgs, const char* format, ...) { STATIC_CONTRACT_SUPPORTS_DAC; #ifndef DACCESS_COMPILE @@ -636,26 +796,65 @@ void StressLog::LogMsg (unsigned level, unsigned facility, int cArgs, const char // set the stress log config parameter. CONTRACT_VIOLATION(TakesLockViolation); - _ASSERTE ( cArgs >= 0 && cArgs <= 7 ); + _ASSERTE(cArgs >= 0 && cArgs <= 63); va_list Args; - if(InlinedStressLogOn(facility, level)) + if (InlinedStressLogOn(facility, level)) { ThreadStressLog* msgs = t_pCurrentThreadLog; - if (msgs == 0) { + if (msgs == 0) + { msgs = CreateThreadStressLog(); if (msgs == 0) return; } va_start(Args, format); - msgs->LogMsg (facility, cArgs, format, Args); + msgs->LogMsg(facility, cArgs, format, Args); va_end(Args); } -// Stress Log ETW feature available only on the desktop versions of the runtime + // Stress Log ETW feature available only on the desktop versions of the runtime +#endif //!DACCESS_COMPILE +} + +/* static */ +void StressLog::LogMsg(unsigned level, unsigned facility, const StressLogMsg &msg) +{ + STATIC_CONTRACT_SUPPORTS_DAC; +#ifndef DACCESS_COMPILE + STATIC_CONTRACT_NOTHROW; + STATIC_CONTRACT_GC_NOTRIGGER; + STATIC_CONTRACT_FORBID_FAULT; + STATIC_CONTRACT_SUPPORTS_DAC; + + // Any stresslog LogMsg could theoretically create a new stress log and thus + // enter a critical section. But we don't want these to cause violations in + // CANNOT_TAKE_LOCK callers, since the callers would otherwise be fine in runs that don't + // set the stress log config parameter. + CONTRACT_VIOLATION(TakesLockViolation); + + _ASSERTE(msg.m_cArgs >= 0 && msg.m_cArgs <= 63); + + if (InlinedStressLogOn(facility, level)) + { +#ifdef HOST_WINDOWS // On Linux, this cast: (va_list)msg.m_args gives a compile error + ThreadStressLog* msgs = t_pCurrentThreadLog; + + if (msgs == 0) + { + msgs = CreateThreadStressLog(); + + if (msgs == 0) + return; + } + msgs->LogMsg(facility, msg.m_cArgs, msg.m_format, (va_list)msg.m_args); +#endif //HOST_WINDOWS + } + + // Stress Log ETW feature available only on the desktop versions of the runtime #endif //!DACCESS_COMPILE } @@ -680,5 +879,37 @@ void StressLog::LogCallStack(const char *const callTag){ } #endif //_DEBUG +#ifdef MEMORY_MAPPED_STRESSLOG +void* StressLog::AllocMemoryMapped(size_t n) +{ + if ((ptrdiff_t)n > 0) + { + StressLogHeader* hdr = theLog.stressLogHeader; + assert(hdr != nullptr); + uint8_t* newMemValue = (uint8_t*)InterlockedAdd64((LONG64*)&hdr->memoryCur, n); + if (newMemValue < hdr->memoryLimit) + { + return newMemValue - n; + } + // when we run out, we just can't allocate anymore + hdr->memoryCur = hdr->memoryLimit; + } + return nullptr; +} + +void* __cdecl ThreadStressLog::operator new(size_t n, const NoThrow&) NOEXCEPT +{ + if (StressLogChunk::s_LogChunkHeap != NULL) + { + //no need to zero memory because we could handle garbage contents + return HeapAlloc(StressLogChunk::s_LogChunkHeap, 0, n); + } + else + { + return StressLog::AllocMemoryMapped(n); + } +} +#endif //MEMORY_MAPPED_STRESSLOG + #endif // STRESS_LOG diff --git a/src/coreclr/vm/ceemain.cpp b/src/coreclr/vm/ceemain.cpp index fb7f2e9..3561f0e 100644 --- a/src/coreclr/vm/ceemain.cpp +++ b/src/coreclr/vm/ceemain.cpp @@ -709,8 +709,9 @@ void EEStartupHelper() unsigned facilities = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::INTERNAL_LogFacility, LF_ALL); unsigned level = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::EXTERNAL_LogLevel, LL_INFO1000); unsigned bytesPerThread = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::UNSUPPORTED_StressLogSize, STRESSLOG_CHUNK_SIZE * 4); - unsigned totalBytes = REGUTIL::GetConfigDWORD_DontUse_(CLRConfig::UNSUPPORTED_TotalStressLogSize, STRESSLOG_CHUNK_SIZE * 1024); - StressLog::Initialize(facilities, level, bytesPerThread, totalBytes, GetClrModuleBase()); + ULONGLONG totalBytes = REGUTIL::GetConfigULONGLONG_DontUse_(CLRConfig::UNSUPPORTED_TotalStressLogSize, STRESSLOG_CHUNK_SIZE * 1024); + LPWSTR logFilename = REGUTIL::GetConfigString_DontUse_(CLRConfig::UNSUPPORTED_StressLogFilename); + StressLog::Initialize(facilities, level, bytesPerThread, totalBytes, GetClrModuleBase(), logFilename); g_pStressLog = &StressLog::theLog; } #endif diff --git a/src/coreclr/vm/gcenv.ee.cpp b/src/coreclr/vm/gcenv.ee.cpp index ffad431..9c6509d 100644 --- a/src/coreclr/vm/gcenv.ee.cpp +++ b/src/coreclr/vm/gcenv.ee.cpp @@ -1684,3 +1684,9 @@ void GCToEEInterface::UpdateGCEventStatus(int currentPublicLevel, int currentPub } #endif // __linux__ && FEATURE_EVENT_TRACE } + +void GCToEEInterface::LogStressMsg(unsigned level, unsigned facility, const StressLogMsg &msg) +{ + StressLog::LogMsg(level, facility, msg); +} + diff --git a/src/coreclr/vm/gcenv.ee.h b/src/coreclr/vm/gcenv.ee.h index c9a1cc2..7a3b596 100644 --- a/src/coreclr/vm/gcenv.ee.h +++ b/src/coreclr/vm/gcenv.ee.h @@ -82,6 +82,8 @@ public: void VerifySyncTableEntry(); void UpdateGCEventStatus(int publicLevel, int publicKeywords, int privateLevel, int privateKeywords); + + void LogStressMsg(unsigned level, unsigned facility, const StressLogMsg& msg); }; } // namespace standalone diff --git a/src/coreclr/vm/gcheaputilities.cpp b/src/coreclr/vm/gcheaputilities.cpp index 3432a00..08f864b 100644 --- a/src/coreclr/vm/gcheaputilities.cpp +++ b/src/coreclr/vm/gcheaputilities.cpp @@ -120,6 +120,8 @@ void FinalizeLoad(IGCHeap* gcHeap, IGCHandleManager* handleMgr, PTR_VOID pGcModu g_gc_load_status = GC_LOAD_STATUS_LOAD_COMPLETE; g_gc_module_base = pGcModuleBase; LOG((LF_GC, LL_INFO100, "GC load successful\n")); + + StressLog::AddModule((uint8_t*)pGcModuleBase); } void StashKeywordAndLevel(bool isPublicProvider, GCEventKeyword keywords, GCEventLevel level) -- 2.7.4