diff --git a/src/coreclr/gc/env/gcenv.h b/src/coreclr/gc/env/gcenv.h index 8a796a0ab9a8ec..3b231c6ad03643 100644 --- a/src/coreclr/gc/env/gcenv.h +++ b/src/coreclr/gc/env/gcenv.h @@ -97,7 +97,6 @@ enum LogFacility LF_GC = 0x00000001, LF_GCALLOC = 0x00000100, LF_GCROOTS = 0x00080000, - LF_ALWAYS = 0x80000000, }; enum LogLevel @@ -192,19 +191,25 @@ struct StressLogMsg } }; -template<> -void* StressLogMsg::ConvertArgument(float arg) = delete; - #if TARGET_64BIT template<> inline void* StressLogMsg::ConvertArgument(double arg) { return (void*)(size_t)(*((uint64_t*)&arg)); } +// COMPAT: Convert 32-bit floats to 64-bit doubles. +template<> +inline void* StressLogMsg::ConvertArgument(float arg) +{ + return StressLogMsg::ConvertArgument((double)arg); +} #else template<> void* StressLogMsg::ConvertArgument(double arg) = delete; +template<> +void* StressLogMsg::ConvertArgument(float arg) = delete; + // COMPAT: Truncate 64-bit integer arguments to 32-bit template<> inline void* StressLogMsg::ConvertArgument(uint64_t arg) @@ -234,7 +239,7 @@ class StressLog static void LogMsg(unsigned dprintfLevel, const StressLogMsg& msg) { - GCToEEInterface::LogStressMsg(LL_ALWAYS, LF_ALWAYS|(dprintfLevel<<16)|LF_GC, msg); + GCToEEInterface::LogStressMsg(LL_ALWAYS, (dprintfLevel<<16)|LF_GC, msg); } static void LogMsg(unsigned level, unsigned facility, const StressLogMsg& msg) diff --git a/src/coreclr/gc/gc.cpp b/src/coreclr/gc/gc.cpp index 1e11c4d505d624..24368301f4b835 100644 --- a/src/coreclr/gc/gc.cpp +++ b/src/coreclr/gc/gc.cpp @@ -7442,7 +7442,7 @@ bool gc_heap::virtual_commit (void* address, size_t size, int bucket, int h_numb if ((base + size) > limit) { - dprintf (1, ("%zd + %zd = %zd > limit %zd ", base, size, (base + size), limit)); + dprintf (2, ("%zd + %zd = %zd > limit %zd ", base, size, (base + size), limit)); exceeded_p = true; } } @@ -8259,9 +8259,9 @@ uint8_t* get_plug_start_in_saved (uint8_t* old_loc, mark* pinned_plug_entry) { uint8_t* saved_pre_plug_info = (uint8_t*)(pinned_plug_entry->get_pre_plug_reloc_info()); uint8_t* plug_start_in_saved = saved_pre_plug_info + (old_loc - (pinned_plug (pinned_plug_entry) - sizeof (plug_and_gap))); - //dprintf (1, ("detected a very short plug: %zx before PP %zx, pad %zx", + //dprintf (2, ("detected a very short plug: %zx before PP %zx, pad %zx", // old_loc, pinned_plug (pinned_plug_entry), plug_start_in_saved)); - dprintf (1, ("EP: %p(%p), %p", old_loc, pinned_plug (pinned_plug_entry), plug_start_in_saved)); + dprintf (2, ("EP: %p(%p), %p", old_loc, pinned_plug (pinned_plug_entry), plug_start_in_saved)); return plug_start_in_saved; } @@ -13511,7 +13511,7 @@ void gc_heap::distribute_free_regions() } } - dprintf (1, ("moved %2zd regions (%8zd) to decommit based on time", num_decommit_regions_by_time, size_decommit_regions_by_time)); + dprintf (REGIONS_LOG, ("moved %2zd regions (%8zd) to decommit based on time", num_decommit_regions_by_time, size_decommit_regions_by_time)); global_free_huge_regions.transfer_regions (&global_regions_to_decommit[huge_free_region]); @@ -30793,7 +30793,7 @@ void gc_heap::realloc_plan_generation_start (generation* gen, generation* consin generation_allocation_pointer (consing_gen) += allocation_left; } - dprintf (1, ("plan re-alloc gen%d start at %p (ptr: %p, limit: %p)", gen->gen_num, + dprintf (2, ("plan re-alloc gen%d start at %p (ptr: %p, limit: %p)", gen->gen_num, generation_plan_allocation_start (consing_gen), generation_allocation_pointer (consing_gen), generation_allocation_limit (consing_gen))); @@ -32337,7 +32337,7 @@ void gc_heap::process_remaining_regions (int current_plan_gen_num, generation* c } } - dprintf (1, ("we still need %d regions, %d will be empty", plan_regions_needed, to_be_empty_regions)); + dprintf (REGIONS_LOG, ("we still need %d regions, %d will be empty", plan_regions_needed, to_be_empty_regions)); if (plan_regions_needed > to_be_empty_regions) { dprintf (REGIONS_LOG, ("h%d %d regions will be empty but we still need %d regions!!", heap_number, to_be_empty_regions, plan_regions_needed)); @@ -33693,7 +33693,7 @@ void gc_heap::plan_phase (int condemned_gen_number) #else 0; #endif //SHORT_PLUGS - dprintf (1, ("gen%d: NON PIN alloc: %zd, pin com: %zd, sweep: %zd, surv: %zd, pinsurv: %zd(%d%% added, %d%% art), np surv: %zd, pad: %zd", + dprintf (2, ("gen%d: NON PIN alloc: %zd, pin com: %zd, sweep: %zd, surv: %zd, pinsurv: %zd(%d%% added, %d%% art), np surv: %zd, pad: %zd", gen_idx, generation_allocation_size (temp_gen), generation_pinned_allocation_compact_size (temp_gen), @@ -43414,7 +43414,7 @@ generation* gc_heap::expand_heap (int condemned_generation, BOOL should_promote_ephemeral = FALSE; ptrdiff_t eph_size = total_ephemeral_size; #ifdef BACKGROUND_GC - dprintf(2,("%s: ---- Heap Expansion ----", (gc_heap::background_running_p() ? "FGC" : "NGC"))); + dprintf(2,("%s: ---- Heap Expansion ----", get_str_gc_type())); #endif //BACKGROUND_GC settings.heap_expansion = TRUE; @@ -43916,7 +43916,7 @@ size_t gc_heap::desired_new_allocation (dynamic_data* dd, { size_t allocated = 0; size_t committed = uoh_committed_size (gen_number, &allocated); - dprintf (1, ("GC#%zd h%d, GMI: UOH budget, UOH commit %zd (obj %zd, frag %zd), total commit: %zd (recorded: %zd)", + dprintf (2, ("GC#%zd h%d, GMI: UOH budget, UOH commit %zd (obj %zd, frag %zd), total commit: %zd (recorded: %zd)", (size_t)settings.gc_index, heap_number, committed, allocated, dd_fragmentation (dynamic_data_of (gen_number)), @@ -43993,7 +43993,7 @@ size_t gc_heap::desired_new_allocation (dynamic_data* dd, dd_surv (dd) = cst; - dprintf (1, (ThreadStressLog::gcDesiredNewAllocationMsg(), + dprintf (2, (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)); @@ -47292,18 +47292,18 @@ void gc_heap::descr_generations (const char* msg) #endif //!TRACE_GC #ifdef STRESS_LOG - if (StressLog::StressLogOn(LF_GC, LL_INFO10)) + if (StressLog::StressLogOn(LF_GC, LL_INFO1000)) { gc_heap* hp = 0; #ifdef MULTIPLE_HEAPS hp= this; #endif //MULTIPLE_HEAPS - STRESS_LOG1(LF_GC, LL_INFO10, "GC Heap %p\n", hp); + STRESS_LOG1(LF_GC, LL_INFO1000, "GC Heap %p\n", hp); for (int n = max_generation; n >= 0; --n) { #ifndef USE_REGIONS - STRESS_LOG4(LF_GC, LL_INFO10, " Generation %d [%p, %p] cur = %p\n", + STRESS_LOG4(LF_GC, LL_INFO1000, " Generation %d [%p, %p] cur = %p\n", n, generation_allocation_start(generation_of(n)), generation_allocation_limit(generation_of(n)), @@ -47313,7 +47313,7 @@ void gc_heap::descr_generations (const char* msg) heap_segment* seg = generation_start_segment(generation_of(n)); while (seg) { - STRESS_LOG4(LF_GC, LL_INFO10, " Segment mem %p alloc = %p used %p committed %p\n", + STRESS_LOG4(LF_GC, LL_INFO1000, " Segment mem %p alloc = %p used %p committed %p\n", heap_segment_mem(seg), heap_segment_allocated(seg), heap_segment_used(seg), @@ -48141,7 +48141,7 @@ void gc_heap::verify_heap (BOOL begin_gc_p) dprintf (2,("[%s]GC#%zu(%s): Verifying heap - begin", (begin_gc_p ? "BEG" : "END"), VolatileLoad(&settings.gc_index), - (settings.concurrent ? "BGC" : (gc_heap::background_running_p() ? "FGC" : "NGC")))); + get_str_gc_type())); #else dprintf (2,("[%s]GC#%zu: Verifying heap - begin", (begin_gc_p ? "BEG" : "END"), VolatileLoad(&settings.gc_index))); @@ -48548,7 +48548,7 @@ void gc_heap::verify_heap (BOOL begin_gc_p) #ifdef BACKGROUND_GC dprintf (2, ("(%s)(%s)(%s) total_objects_verified is %zd, total_objects_verified_deep is %zd", - (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC")), + get_str_gc_type(), (begin_gc_p ? "BEG" : "END"), ((current_c_gc_state == c_gc_state_planning) ? "in plan" : "not in plan"), total_objects_verified, total_objects_verified_deep)); @@ -48601,7 +48601,7 @@ void gc_heap::verify_heap (BOOL begin_gc_p) } dprintf (2,("GC%zu(%s): Verifying heap - end", VolatileLoad(&settings.gc_index), - (settings.concurrent ? "BGC" : (gc_heap::background_running_p() ? "FGC" : "NGC")))); + get_str_gc_type())); #else dprintf (2,("GC#d: Verifying heap - end", VolatileLoad(&settings.gc_index))); #endif //BACKGROUND_GC @@ -50362,6 +50362,15 @@ last_recorded_gc_info* gc_heap::get_completed_bgc_info() } #endif //BACKGROUND_GC +const char* gc_heap::get_str_gc_type() +{ +#ifdef BACKGROUND_GC + return (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC")); +#else // BACKGROUND_GC + return "NGC"; +#endif // BACKGROUND_GC +} + void gc_heap::do_pre_gc() { STRESS_LOG_GC_STACK; @@ -50390,14 +50399,21 @@ void gc_heap::do_pre_gc() #ifdef TRACE_GC size_t total_allocated_since_last_gc[total_oh_count]; get_total_allocated_since_last_gc (total_allocated_since_last_gc); - + bool compatibleWithStressLog = true; +#ifdef SIMPLE_DPRINTF + compatibleWithStressLog = false; +#endif //SIMPLE_DPRINTF + bgc_state b_state = bgc_not_in_process; #ifdef BACKGROUND_GC + b_state = settings.b_state; +#endif //BACKGROUND_GC + size_t heap_size_before = get_total_heap_size(); uint64_t start_gc_time = GetHighPrecisionTimeStamp(); uint64_t elapsed_since_last_gc_us = start_gc_time - last_alloc_reset_suspended_end_time; max_peak_heap_size = max (max_peak_heap_size, heap_size_before); - dprintf (6666, (ThreadStressLog::gcDetailedStartMsg(), + dprintf (6666, (ThreadStressLog::gcDetailedStartMsg(compatibleWithStressLog), VolatileLoad(&settings.gc_index), dd_collection_count (hp->dynamic_data_of (0)), settings.condemned_generation, @@ -50410,18 +50426,11 @@ void gc_heap::do_pre_gc() (elapsed_since_last_gc_us ? (total_allocated_since_last_gc[gc_oh_num::loh] / 1000.0 / elapsed_since_last_gc_us) : 0), total_allocated_since_last_gc[gc_oh_num::poh], (elapsed_since_last_gc_us ? (total_allocated_since_last_gc[gc_oh_num::poh] / 1000.0 / elapsed_since_last_gc_us) : 0), - (settings.concurrent ? "BGC" : (gc_heap::background_running_p() ? "FGC" : "NGC")), - settings.b_state, - n_heaps, - (heap_size_before / 1000.0 / 1000.0), - (max_peak_heap_size / 1000.0 / 1000.0))); -#else - dprintf (1, ("*GC* %d(gen0:%d)(%d)(alloc: %zd)", - VolatileLoad(&settings.gc_index), - dd_collection_count(hp->dynamic_data_of(0)), - settings.condemned_generation, - (total_allocated_since_last_gc[0] + total_allocated_since_last_gc[1] + total_allocated_since_last_gc[2]))); -#endif //BACKGROUND_GC + get_str_gc_type(), + b_state, + n_heaps + SIMPLE_DPRINTF_ARG(heap_size_before / 1000.0 / 1000.0) + SIMPLE_DPRINTF_ARG(max_peak_heap_size / 1000.0 / 1000.0))); if (heap_hard_limit) { @@ -50840,18 +50849,12 @@ void gc_heap::do_post_gc() } #endif //BGC_SERVO_TUNING -#ifdef BACKGROUND_GC - const char* str_gc_type = (settings.concurrent ? "BGC" : (gc_heap::background_running_p () ? "FGC" : "NGC")); -#else - const char* str_gc_type = "NGC"; -#endif //BACKGROUND_GC - dprintf (6666, (ThreadStressLog::gcDetailedEndMsg(), VolatileLoad (&settings.gc_index), dd_collection_count (hp->dynamic_data_of (0)), (get_total_heap_size() / 1000.0 / 1000.0), settings.condemned_generation, - str_gc_type, + get_str_gc_type(), (settings.compaction ? "C" : "S"), (settings.promotion ? "P" : "S"), settings.entry_memory_load, diff --git a/src/coreclr/gc/gc.h b/src/coreclr/gc/gc.h index a1586ce8f687f2..3e4f83ab7e38f4 100644 --- a/src/coreclr/gc/gc.h +++ b/src/coreclr/gc/gc.h @@ -344,9 +344,23 @@ inline bool IsServerHeap() #define MAX_LONGPATH 1024 #endif // MAX_LONGPATH -// #define TRACE_GC +// TRACE_GC has two sub-modes: the standard VM stress log mechanism and +// SIMPLE_DPRINTF, which is text output. By default, we enable TRACE_GC (not +// SIMPLE_DPRINTF) for debug/checked builds so that we can catch build breaks. +// HOST_64BIT is required because logging dprintf to the stress log us only +// supported on 64 bit platforms. We could consider enabling it in release +// builds and for more logging sites (see below for details) but are being +// conservative about performance impact. +// +// Normal development time changes are to enable SIMPLE_DPRINTF here (which +// will automatically set TRACE_GC) or to only enable TRACE_GC. + // #define SIMPLE_DPRINTF +#if defined(SIMPLE_DPRINTF) || (defined(_DEBUG) && defined(HOST_64BIT)) +#define TRACE_GC +#endif // _DEBUG + #ifdef TRACE_GC #define MIN_CUSTOM_LOG_LEVEL 7 #define SEG_REUSE_LOG_0 (MIN_CUSTOM_LOG_LEVEL) @@ -375,10 +389,79 @@ HRESULT initialize_log_file(); void flush_gc_log (bool); void GCLog (const char *fmt, ... ); #define dprintf(l,x) {if ((l == 1) || (l == GTC_LOG)) {GCLog x;}} +#define SIMPLE_DPRINTF_ARG(x) , x + #else //SIMPLE_DPRINTF + #ifdef HOST_64BIT -#define dprintf(l,x) STRESS_LOG_VA(l,x); + +// ------------------------------- +// Stress log / dprintf background +// ------------------------------- +// +// This code connects dprintf to the stress log mechanism. These machanisms +// and their usage has evolved a bit separately over time, so there are some +// rough edges here. +// +// The stress log mechanism has a LogFacility and a LogLevel. Facilities can be +// chosen through DOTNET_LogFacility, and the facility is recorded in the +// stress log. LogFacility is a bitmask. The GC only has a few bits reserved +// in the bitmask, and most GC logging uses a single value (LF_GC, which is 0x1). +// +// The stress log logging level can be chosen through DOTNET_LogLevel. This +// causes filtering at runtime, and the level is not recorded in the stress log. +// The first argument to dprintf is similar, though it can record either a level +// (values below 7) or a GC area (values starting with SEG_REUSE_LOG_0 above). +// Developers often use StressLogAnalyzer to filter by this value at _analysis_ +// time, which doesn't match usual stress log usage. +// +// In practice, dprintf(1) and LL_INFO10 (which has the value 4) have been used +// similarly on log messages. A dprintf(1) is generally called about once per +// GC, and LL_INFO10 is "10 logs per small but not trivial run". Other values +// have been audited. We could consider moving the GC values to be in line with +// the rest of the runtime (change 1 to 4 to make room for errors/warnings, etc.) +// or (to avoid churn) convert them by adding 3. +// +// To allow StressLogAnalyzer to use the GC level values, we abuse the stress +// log LogLevel by storing the GC value in the upper 16 bits of LogLevel and +// also settings LF_GC (0x1). This works because we don't enable other logging +// when doing GC investigations. However, we don't want to do this by default +// because setting the upper bits will cause GC logging to masquerade as non-GC +// logging. For example, dprintf(3) would use (3 << 16) | LF_GC == 0x30001, +// which is LF_ASSERT | LF_VERIFIER | LF_GC in other contexts. +// +// Lastly, we have GC logging for some very low level operations, so by default +// we don't want to even have the check that logging is enabled for performance +// reasons. Right now we are very conservative and only allow dprintf(1) to go +// to the stress log in default builds, but we could consider allowing more in +// the future. + +// ----------------------------- +// Stress log / dprintf settings +// ----------------------------- +// +// (See above for details.) +// +// The following line works for normal debug/checked builds (where STRESS_LOG is +// defined and SIMPLE_DPRINTF is not). All dprintf sites are checked for +// compilation errors, yet all but those with level 1 can be statically +// optimized away. In the future after more auditing, this could be expanded to +// more levels. +// +// Note that zero is passed because STRESS_LOG_VA/LogMsg will add LF_GC and in +// normal builds we don't want conflicts in the upper bits of LogFacility. +#define dprintf(l,x) if (l == 1) {STRESS_LOG_VA(0,x);} + +// For private builds where it is ok (and useful) to have conflicts in the upper +// bits of LogFacility, more events can be allowed and the dprintf level can be +// passed through. Usually this is going to be a GC investigation and the other +// logging will be disabled, so the theoretical conflict won't happen in +// practice. Note that in these examples, 'l' ("ell", not "one") is passed +// rather than '0'. +//#define dprintf(l,x) STRESS_LOG_VA(l,x); //#define dprintf(l,x) {if ((l <= 2) || (l == 6666)) {STRESS_LOG_VA(l,x);}} + +#define SIMPLE_DPRINTF_ARG(x) #else //HOST_64BIT #error Logging dprintf to stress log on 32 bits platforms is not supported. #endif //HOST_64BIT diff --git a/src/coreclr/gc/gcpriv.h b/src/coreclr/gc/gcpriv.h index 69c464c0545e6b..f34fedfdc3f140 100644 --- a/src/coreclr/gc/gcpriv.h +++ b/src/coreclr/gc/gcpriv.h @@ -1573,6 +1573,8 @@ class gc_heap private: + PER_HEAP_ISOLATED_METHOD const char* get_str_gc_type(); + #ifdef TRACE_GC PER_HEAP_METHOD void print_free_list (int gen, heap_segment* seg); #endif // TRACE_GC diff --git a/src/coreclr/inc/gcmsg.inl b/src/coreclr/inc/gcmsg.inl index d2461a3cdbf03c..d1da723b0987be 100644 --- a/src/coreclr/inc/gcmsg.inl +++ b/src/coreclr/inc/gcmsg.inl @@ -41,12 +41,33 @@ return "%d gc thread waiting... Done"; } - static const char* gcDetailedStartMsg() +#define GC_DETAILED_START_PREFIX "*GC* %d(gen0:%d)(%d)" +#define GC_DETAILED_START_STRESSLOG "(alloced for %.3fms, g0 %zd (b: %zd, %zd/h) (%.3fmb/ms), g3 %zd (%.3fmb/ms), g4 %zd (%.3fmb/ms))(%s)(%d)(%d)" +#define GC_DETAILED_START_DPRINTF_EXTRA "(heap size: %.3fmb max: %.3fmb)" + + static const char* gcDetailedStartPrefix() + { + STATIC_CONTRACT_LEAF; + return GC_DETAILED_START_PREFIX; + } + + static const char* gcDetailedStartMsg(bool compatibleWithStressLog) { STATIC_CONTRACT_LEAF; - return "*GC* %d(gen0:%d)(%d)(alloced for %.3fms, g0 %zd (b: %zd, %zd/h) (%.3fmb/ms), g3 %zd (%.3fmb/ms), g4 %zd (%.3fmb/ms))(%s)(%d)(%d)(heap size: %.3fmb max: %.3fmb)"; + if (compatibleWithStressLog) + { + return GC_DETAILED_START_PREFIX GC_DETAILED_START_STRESSLOG; + } + else + { + return GC_DETAILED_START_PREFIX GC_DETAILED_START_STRESSLOG GC_DETAILED_START_DPRINTF_EXTRA; + } } +#undef GC_DETAILED_START_PREFIX +#undef GC_DETAILED_START_STRESSLOG +#undef GC_DETAILED_START_DPRINTF_EXTRA + static const char* gcDetailedEndMsg() { STATIC_CONTRACT_LEAF; diff --git a/src/coreclr/inc/stresslog.h b/src/coreclr/inc/stresslog.h index 58fbfdba97e2aa..5a5b9e85e97c01 100644 --- a/src/coreclr/inc/stresslog.h +++ b/src/coreclr/inc/stresslog.h @@ -371,19 +371,24 @@ typedef USHORT static StressLog theLog; // We only have one log, and this is it }; - -template<> -void* StressLog::ConvertArgument(float arg) = delete; - #if TARGET_64BIT template<> inline void* StressLog::ConvertArgument(double arg) { return (void*)(size_t)(*((uint64_t*)&arg)); } + +// COMPAT: Convert 32-bit floats to 64-bit doubles. +template<> +inline void* StressLog::ConvertArgument(float arg) +{ + return StressLog::ConvertArgument((double)arg); +} #else template<> void* StressLog::ConvertArgument(double arg) = delete; +template<> +void* StressLog::ConvertArgument(float arg) = delete; // COMPAT: Truncate 64-bit integer arguments to 32-bit template<> diff --git a/src/coreclr/nativeaot/Runtime/inc/stressLog.h b/src/coreclr/nativeaot/Runtime/inc/stressLog.h index fc031897f492d4..15570c2af9e285 100644 --- a/src/coreclr/nativeaot/Runtime/inc/stressLog.h +++ b/src/coreclr/nativeaot/Runtime/inc/stressLog.h @@ -344,19 +344,26 @@ class StressLog { }; -template<> -void* StressLog::ConvertArgument(float arg) = delete; - #if TARGET_64BIT template<> inline void* StressLog::ConvertArgument(double arg) { return (void*)(size_t)(*((uint64_t*)&arg)); } + +// COMPAT: Convert 32-bit floats to 64-bit doubles. +template<> +inline void* StressLog::ConvertArgument(float arg) +{ + return StressLog::ConvertArgument((double)arg); +} #else template<> void* StressLog::ConvertArgument(double arg) = delete; +template<> +void* StressLog::ConvertArgument(float arg) = delete; + // COMPAT: Truncate 64-bit integer arguments to 32-bit template<> inline void* StressLog::ConvertArgument(uint64_t arg) diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp index 379f6e3ccaf01a..2d4822a4bc58fc 100644 --- a/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp @@ -109,7 +109,7 @@ const char *getFacilityName(DWORD_PTR lf) /* 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) +void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, uint64_t threadId, double timeStamp, DWORD_PTR facility, uint32_t numArgs, ___in void** inArgs, bool fPrintFormatString) { if (threadId & 0x8000000000000000) fprintf(file, "GC%2d %13.9f : ", (unsigned)threadId, timeStamp); @@ -123,6 +123,15 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou { fprintf(file, "***|\"%s\"|*** ", format); } + + // Below we are going to pass substrings of the format with as-big-as-possibly-needed portions + // of the args array. This allocates a larger args array to avoid buffer over-reads. Formats + // will have at most 16 arguments because the EE/GC interface doesn't allow more than that. + const int extraArgSlots = 16; + void** args = (void**)_alloca((numArgs + extraArgSlots) * sizeof(void*)); + memcpy(args, inArgs, numArgs * sizeof(void*)); + memset(&args[numArgs], 0, extraArgSlots * sizeof(void*)); + CQuickBytes fullname; void** argsPtr = args; static char formatCopy[256]; @@ -143,6 +152,16 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou ptr[-1] = '{'; else if (c == '%') { + while (isdigit(*ptr)) + { + // This is enough to handle %5s. It doesn't need to handle %0.3f because the below code will + // work in the sense that it consider the specifier finished at the '.', but that's good enough + // because the entire specifier will end up being passed to fprintf later. + // + // To handle %5p, we would need to parse and use the width specifier in the 'p' code below. + ptr++; + } + argsPtr++; // This format will consume one of the args if (*ptr == '%') { @@ -157,7 +176,7 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou // Print the string up to that point c = *ptr; *ptr = 0; // Terminate the string temporarily - fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10]); + fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12], args[13], args[14], args[15]); *ptr = c; // Put it back // move the argument pointers past the part the was printed @@ -299,7 +318,7 @@ void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inou } // Print anything after the last special format instruction. - fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10]); + fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6], args[7], args[8], args[9], args[10], args[11], args[12], args[13], args[14], args[15]); fprintf(file, "\n"); } @@ -519,8 +538,10 @@ HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugD } else { + uint32_t numberOfArgs = latestMsg.GetNumberOfArgs(); args = latestMsg.GetArgs(); - formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg.GetFacility(), args); + formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg.GetFacility(), + numberOfArgs, args); } } msgCtr++; diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp index 20d0f1b6b22918..8a188fd69e94a5 100644 --- a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp @@ -139,7 +139,7 @@ bool LookupGcThread(uint64_t threadId, GcThread *gcThread) d(IS_UNKNOWN, "") \ d(IS_THREAD_WAIT, ThreadStressLog::gcServerThread0StartMsg()) \ d(IS_THREAD_WAIT_DONE, ThreadStressLog::gcServerThreadNStartMsg()) \ -d(IS_GCSTART, ThreadStressLog::gcDetailedStartMsg()) \ +d(IS_GCSTART, ThreadStressLog::gcDetailedStartPrefix()) \ d(IS_GCEND, ThreadStressLog::gcDetailedEndMsg()) \ d(IS_MARK_START, ThreadStressLog::gcStartMarkMsg()) \ d(IS_PLAN_START, ThreadStressLog::gcStartPlanMsg()) \ @@ -1241,13 +1241,9 @@ static void PrintFriendlyNumber(LONGLONG n) static void PrintMessage(CorClrData& corClrData, FILE *outputFile, uint64_t threadId, StressMsgReader msg) { - void* argBuffer[StressMsg::maxArgCnt]; char* format = (char*)(s_hdr->moduleImage + msg.GetFormatOffset()); - int numberOfArgs = msg.GetNumberOfArgs(); - for (int i = 0; i < numberOfArgs; i++) - { - argBuffer[i] = msg.GetArgs()[i]; - } + void** args = msg.GetArgs(); + uint32_t numberOfArgs = msg.GetNumberOfArgs(); double deltaTime = ((double)(msg.GetTimeStamp() - s_hdr->startTimeStamp)) / s_hdr->tickFrequency; if (!s_printHexTidForGcThreads) { @@ -1261,7 +1257,7 @@ static void PrintMessage(CorClrData& corClrData, FILE *outputFile, uint64_t thre threadId |= 0x4000000000000000; } } - formatOutput(&corClrData, outputFile, format, threadId, deltaTime, msg.GetFacility(), argBuffer, s_fPrintFormatStrings); + formatOutput(&corClrData, outputFile, format, threadId, deltaTime, msg.GetFacility(), numberOfArgs, args, s_fPrintFormatStrings); } int ProcessStressLog(void* baseAddress, int argc, char* argv[]) @@ -1299,6 +1295,7 @@ int ProcessStressLog(void* baseAddress, int argc, char* argv[]) memset(&mapImageToStringId, 0, sizeof(mapImageToStringId)); memset(s_interestingStringFilter, 0, sizeof(s_interestingStringFilter)); memset(s_interestingStringMatchMode, 0, sizeof(s_interestingStringMatchMode)); + s_interestingStringMatchMode[IS_GCSTART] = true; memset(s_printEarliestMessageFromGcThread, 0, sizeof(s_printEarliestMessageFromGcThread)); if (!ParseOptions(argc, argv)) diff --git a/src/coreclr/tools/StressLogAnalyzer/strike.h b/src/coreclr/tools/StressLogAnalyzer/strike.h index 846f780bbc67c5..2ad4d32bf48570 100644 --- a/src/coreclr/tools/StressLogAnalyzer/strike.h +++ b/src/coreclr/tools/StressLogAnalyzer/strike.h @@ -60,4 +60,4 @@ struct IDebugDataSpaces 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); +void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, uint64_t threadId, double timeStamp, DWORD_PTR facility, uint32_t numArgs, ___in void** args, bool fPrintFormatString = false);