Skip to content

Commit

Permalink
Enable dprintf logging for the whole GC (#94816)
Browse files Browse the repository at this point in the history
  • Loading branch information
@cshung
cshung authored Nov 17, 2023
1 parent 9f6ac8c commit a1d48d6
Show file tree
Hide file tree
Showing 8 changed files with 320 additions and 195 deletions.
40 changes: 40 additions & 0 deletions src/coreclr/gc/env/gcenv.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -358,6 +358,46 @@ struct StressLogMsg
m_args[10] = (void*)(size_t)data11;
m_args[11] = (void*)(size_t)data12;
}


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, typename T13 >
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, T13 data13) : m_cArgs(13), 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*) && sizeof(T13) <= 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;
m_args[12] = (void*)(size_t)data13;
}

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, typename T13, typename T14 >
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, T13 data13, T14 data14) : m_cArgs(14), 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*) && sizeof(T13) <= sizeof(void*) && sizeof(T14) <= 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;
m_args[12] = (void*)(size_t)data13;
m_args[13] = (void*)(size_t)data14;
}
};

class StressLog
Expand Down
150 changes: 4 additions & 146 deletions src/coreclr/gc/gc.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -455,97 +455,6 @@ void gc_heap::add_to_history()
#endif //GC_HISTORY && BACKGROUND_GC
}

#if defined(TRACE_GC) && defined(SIMPLE_DPRINTF)
BOOL gc_log_on = TRUE;
FILE* gc_log = NULL;
size_t gc_log_file_size = 0;

size_t gc_buffer_index = 0;
size_t max_gc_buffers = 0;

static CLRCriticalSection gc_log_lock;

// we keep this much in a buffer and only flush when the buffer is full
#define gc_log_buffer_size (1024*1024)
uint8_t* gc_log_buffer = 0;
size_t gc_log_buffer_offset = 0;

void flush_gc_log (bool close)
{
if (gc_log_on && (gc_log != NULL))
{
fwrite(gc_log_buffer, gc_log_buffer_offset, 1, gc_log);
fflush(gc_log);
if (close)
{
fclose(gc_log);
gc_log_on = false;
gc_log = NULL;
}
gc_log_buffer_offset = 0;
}
}

void log_va_msg(const char *fmt, va_list args)
{
gc_log_lock.Enter();

const int BUFFERSIZE = 4096;
static char rgchBuffer[BUFFERSIZE];
char * pBuffer = &rgchBuffer[0];

pBuffer[0] = '\n';
int buffer_start = 1;
int pid_len = sprintf_s (&pBuffer[buffer_start], BUFFERSIZE - buffer_start,
"[%5d]", (uint32_t)GCToOSInterface::GetCurrentThreadIdForLogging());
buffer_start += pid_len;
memset(&pBuffer[buffer_start], '-', BUFFERSIZE - buffer_start);
int msg_len = _vsnprintf_s (&pBuffer[buffer_start], BUFFERSIZE - buffer_start, _TRUNCATE, fmt, args);
if (msg_len == -1)
{
msg_len = BUFFERSIZE - buffer_start;
}

msg_len += buffer_start;

if ((gc_log_buffer_offset + msg_len) > (gc_log_buffer_size - 12))
{
char index_str[8];
memset (index_str, '-', 8);
sprintf_s (index_str, ARRAY_SIZE(index_str), "%d", (int)gc_buffer_index);
gc_log_buffer[gc_log_buffer_offset] = '\n';
memcpy (gc_log_buffer + (gc_log_buffer_offset + 1), index_str, 8);

gc_buffer_index++;
if (gc_buffer_index > max_gc_buffers)
{
fseek (gc_log, 0, SEEK_SET);
gc_buffer_index = 0;
}
fwrite(gc_log_buffer, gc_log_buffer_size, 1, gc_log);
fflush(gc_log);
memset (gc_log_buffer, '*', gc_log_buffer_size);
gc_log_buffer_offset = 0;
}

memcpy (gc_log_buffer + gc_log_buffer_offset, pBuffer, msg_len);
gc_log_buffer_offset += msg_len;

gc_log_lock.Leave();
}

void GCLog (const char *fmt, ... )
{
if (gc_log_on && (gc_log != NULL))
{
va_list args;
va_start(args, fmt);
log_va_msg (fmt, args);
va_end(args);
}
}
#endif //TRACE_GC && SIMPLE_DPRINTF

#ifdef GC_CONFIG_DRIVEN

BOOL gc_config_log_on = FALSE;
Expand Down Expand Up @@ -594,6 +503,8 @@ void GCLogConfig (const char *fmt, ... )

void GCHeap::Shutdown()
{
// This does not work for standalone GC on Windows because windows closed the file
// handle in DllMain for the standalone GC before we get here.
#if defined(TRACE_GC) && defined(SIMPLE_DPRINTF) && !defined(BUILD_AS_STANDALONE)
flush_gc_log (true);
#endif //TRACE_GC && SIMPLE_DPRINTF && !BUILD_AS_STANDALONE
Expand Down Expand Up @@ -7080,9 +6991,11 @@ void gc_heap::gc_thread_function ()
}
#endif //DYNAMIC_HEAP_COUNT
uint32_t wait_result = gc_heap::ee_suspend_event.Wait(wait_on_time_out_p ? wait_time : INFINITE, FALSE);
#ifdef DYNAMIC_HEAP_COUNT
dprintf (9999, ("waiting for ee done res %d (timeout %d, %I64d ms since last suspend end)(should_change_heap_count is %d) (gradual_decommit_in_progress_p %d)",
wait_result, wait_time, ((GetHighPrecisionTimeStamp() - last_suspended_end_time) / 1000),
dynamic_heap_count_data.should_change_heap_count, gradual_decommit_in_progress_p));
#endif //DYNAMIC_HEAP_COUNT
if (wait_result == WAIT_TIMEOUT)
{
#ifdef DYNAMIC_HEAP_COUNT
Expand Down Expand Up @@ -13986,26 +13899,6 @@ void gc_heap::adjust_ephemeral_limits ()
#endif //USE_REGIONS
}

#if defined(TRACE_GC) || defined(GC_CONFIG_DRIVEN)
FILE* CreateLogFile(const GCConfigStringHolder& temp_logfile_name, bool is_config)
{
FILE* logFile;

if (!temp_logfile_name.Get())
{
return nullptr;
}

char logfile_name[MAX_LONGPATH+1];
//uint32_t pid = GCToOSInterface::GetCurrentProcessId();
const char* suffix = is_config ? ".config.log" : ".log";
//_snprintf_s(logfile_name, MAX_LONGPATH+1, _TRUNCATE, "%s.%d%s", temp_logfile_name.Get(), pid, suffix);
_snprintf_s(logfile_name, MAX_LONGPATH+1, _TRUNCATE, "%s%s", temp_logfile_name.Get(), suffix);
logFile = fopen(logfile_name, "wb");
return logFile;
}
#endif //TRACE_GC || GC_CONFIG_DRIVEN

uint32_t adjust_heaps_hard_limit_worker (uint32_t nhp, size_t limit)
{
if (!limit)
Expand Down Expand Up @@ -14115,41 +14008,6 @@ HRESULT gc_heap::initialize_gc (size_t soh_segment_size,
#endif //MULTIPLE_HEAPS
)
{
#if defined(TRACE_GC) && defined(SIMPLE_DPRINTF)
if (GCConfig::GetLogEnabled())
{
gc_log = CreateLogFile(GCConfig::GetLogFile(), false);

if (gc_log == NULL)
{
GCToEEInterface::LogErrorToHost("Cannot create log file");
return E_FAIL;
}

// GCLogFileSize in MBs.
gc_log_file_size = static_cast<size_t>(GCConfig::GetLogFileSize());

if (gc_log_file_size <= 0 || gc_log_file_size > 500)
{
GCToEEInterface::LogErrorToHost("Invalid log file size (valid size needs to be larger than 0 and smaller than 500)");
fclose (gc_log);
return E_FAIL;
}

gc_log_lock.Initialize();
gc_log_buffer = new (nothrow) uint8_t [gc_log_buffer_size];
if (!gc_log_buffer)
{
fclose(gc_log);
return E_OUTOFMEMORY;
}

memset (gc_log_buffer, '*', gc_log_buffer_size);

max_gc_buffers = gc_log_file_size * 1024 * 1024 / gc_log_buffer_size;
}
#endif //TRACE_GC && SIMPLE_DPRINTF

#ifdef GC_CONFIG_DRIVEN
if (GCConfig::GetConfigLogEnabled())
{
Expand Down
52 changes: 52 additions & 0 deletions src/coreclr/gc/gc.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -341,4 +341,56 @@ inline bool IsServerHeap()
#endif // FEATURE_SVR_GC
}

#ifndef MAX_LONGPATH
#define MAX_LONGPATH 1024
#endif // MAX_LONGPATH

// #define TRACE_GC
// #define SIMPLE_DPRINTF

#ifdef TRACE_GC
#define MIN_CUSTOM_LOG_LEVEL 7
#define SEG_REUSE_LOG_0 (MIN_CUSTOM_LOG_LEVEL)
#define SEG_REUSE_LOG_1 (MIN_CUSTOM_LOG_LEVEL + 1)
#define DT_LOG_0 (MIN_CUSTOM_LOG_LEVEL + 2)
#define BGC_TUNING_LOG (MIN_CUSTOM_LOG_LEVEL + 3)
#define GTC_LOG (MIN_CUSTOM_LOG_LEVEL + 4)
#define GC_TABLE_LOG (MIN_CUSTOM_LOG_LEVEL + 5)
#define JOIN_LOG (MIN_CUSTOM_LOG_LEVEL + 6)
#define SPINLOCK_LOG (MIN_CUSTOM_LOG_LEVEL + 7)
#define SNOOP_LOG (MIN_CUSTOM_LOG_LEVEL + 8)
#define REGIONS_LOG (MIN_CUSTOM_LOG_LEVEL + 9)

// NOTE! This is for HEAP_BALANCE_INSTRUMENTATION
// This particular one is special and needs to be well formatted because we
// do post processing on it with tools\GCLogParser. If you need to add some
// detail to help with investigation that's not 't processed by tooling
// prefix it with TEMP so that line will be written to the results as is in
// the result. I have some already logged with HEAP_BALANCE_TEMP_LOG.
#define HEAP_BALANCE_LOG (MIN_CUSTOM_LOG_LEVEL + 10)
#define HEAP_BALANCE_TEMP_LOG (MIN_CUSTOM_LOG_LEVEL + 11)

#ifdef SIMPLE_DPRINTF

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;}}
#else //SIMPLE_DPRINTF
#ifdef HOST_64BIT
#define dprintf(l,x) STRESS_LOG_VA(l,x);
//#define dprintf(l,x) {if ((l <= 2) || (l == 6666)) {STRESS_LOG_VA(l,x);}}
#else //HOST_64BIT
#error Logging dprintf to stress log on 32 bits platforms is not supported.
#endif //HOST_64BIT
#endif //SIMPLE_DPRINTF

#else //TRACE_GC
#define dprintf(l,x)
#endif //TRACE_GC

#if defined(TRACE_GC) || defined(GC_CONFIG_DRIVEN)
FILE* CreateLogFile(const GCConfigStringHolder& temp_logfile_name, bool is_config);
#endif //TRACE_GC || GC_CONFIG_DRIVEN

#endif // __GC_H
Loading

0 comments on commit a1d48d6

Please sign in to comment.