#ifndef TOS_LOG_DEBUG_MEMORY_C #define TOS_LOG_DEBUG_MEMORY_C #include "../stdlib/Types.h" #include "Debug.h" #include "DebugMemory.h" #include "Log.h" #include "TimingStat.h" #include "../utils/StringUtils.h" #include "../utils/TestUtils.h" #include "../thread/Atomic.h" #include "../architecture/Intrinsics.h" #include "../compiler/CompilerUtils.h" global_persist DebugContainer* debug_container = NULL; // WARNING: Spinlock uses TimeUtils which uses performance counter, which is part of DebugContainer // @todo The explanation above is insane. We did this so we only have to set the performance counter once but it is biting us now #include "../thread/Spinlock.cpp" #if _WIN32 #include void setup_performance_count() { if (!debug_container) { return; } LARGE_INTEGER perf_counter; QueryPerformanceFrequency(&perf_counter); debug_container->performance_count_frequency = perf_counter.QuadPart; } #elif __linux__ void setup_performance_count() { if (!debug_container) { return; } FILE* fp = fopen("/proc/cpuinfo", "r"); if (!fp) { return; } char line[256]; uint64 cpu_freq = 0; while (fgets(line, sizeof(line), fp)) { if (sscanf(line, "cpu MHz%*[^0-9]%ld", &cpu_freq) == 1) { break; } } fclose(fp); debug_container->performance_count_frequency = cpu_freq == 0 ? 1 : cpu_freq * 1000000; } #endif void log_to_file() { // we don't log an empty log pool if (!debug_container || debug_container->log_memory.pos == 0 || !debug_container->log_fp) { return; } #if _WIN32 DWORD written; WriteFile( debug_container->log_fp, (char *) debug_container->log_memory.memory, (uint32) debug_container->log_memory.pos, &written, NULL ); #else if (debug_container->log_fp < 0) { return; } write( debug_container->log_fp, (char *) debug_container->log_memory.memory, (uint32) debug_container->log_memory.pos ); #endif } // IMPORTANT: This function should only be called when you actually use this data // e.g. log to display or file inline void update_timing_stat(uint32 stat, const char* function) { uint64 new_tick_count = intrin_timestamp_counter(); TimingStat* timing_stat = &debug_container->perf_stats[stat]; spinlock_start(&debug_container->perf_stats_spinlock); timing_stat->function = function; timing_stat->delta_tick = (uint32) (new_tick_count - timing_stat->old_tick_count); timing_stat->delta_time = (f64) timing_stat->delta_tick / (f64) debug_container->performance_count_frequency; timing_stat->old_tick_count = new_tick_count; spinlock_end(&debug_container->perf_stats_spinlock); } inline void update_timing_stat_start(uint32 stat, const char*) { spinlock_start(&debug_container->perf_stats_spinlock); debug_container->perf_stats[stat].old_tick_count = intrin_timestamp_counter(); spinlock_end(&debug_container->perf_stats_spinlock); } inline void update_timing_stat_end(uint32 stat, const char* function) { uint64 new_tick_count = intrin_timestamp_counter(); TimingStat* timing_stat = &debug_container->perf_stats[stat]; spinlock_start(&debug_container->perf_stats_spinlock); timing_stat->function = function; timing_stat->delta_tick = (uint32) (new_tick_count - timing_stat->old_tick_count); timing_stat->delta_time = (f64) timing_stat->delta_tick / (f64) debug_container->performance_count_frequency; timing_stat->old_tick_count = new_tick_count; spinlock_end(&debug_container->perf_stats_spinlock); } inline void update_timing_stat_end_continued(uint32 stat, const char* function) { uint64 new_tick_count = intrin_timestamp_counter(); TimingStat* timing_stat = &debug_container->perf_stats[stat]; spinlock_start(&debug_container->perf_stats_spinlock); timing_stat->function = function; timing_stat->delta_tick = (uint32) ((uint32) (new_tick_count - timing_stat->old_tick_count) + timing_stat->delta_tick); timing_stat->delta_time = timing_stat->delta_time + (f64) timing_stat->delta_tick / (f64) debug_container->performance_count_frequency; timing_stat->old_tick_count = new_tick_count; spinlock_end(&debug_container->perf_stats_spinlock); } inline void update_timing_stat_reset(uint32 stat) { TimingStat* timing_stat = &debug_container->perf_stats[stat]; spinlock_start(&debug_container->perf_stats_spinlock); timing_stat->function = NULL; timing_stat->delta_tick = 0; timing_stat->delta_time = 0; spinlock_end(&debug_container->perf_stats_spinlock); } inline void reset_counter(int32 id) { if (!debug_container || !debug_container->counter) { return; } atomic_set_acquire(&debug_container->counter[id], 0); } inline void log_increment(int32 id, int64 by = 1) { if (!debug_container || !debug_container->counter) { return; } atomic_add_acquire(&debug_container->counter[id], by); } inline void log_counter(int32 id, int64 value) { if (!debug_container || !debug_container->counter) { return; } atomic_set_acquire(&debug_container->counter[id], value); } inline DebugMemory* debug_memory_find(uintptr_t start) { for (uint64 i = 0; i < debug_container->dmc.memory_size; ++i) { if (debug_container->dmc.memory_stats[i].start <= start && debug_container->dmc.memory_stats[i].start + debug_container->dmc.memory_stats[i].size >= start ) { return &debug_container->dmc.memory_stats[i]; } } return NULL; } void debug_memory_init(uintptr_t start, uint64 size) { if (!start || !debug_container) { return; } const DebugMemory* mem = debug_memory_find(start); if (mem) { return; } DebugMemoryContainer* dmc = &debug_container->dmc; if (dmc->memory_size <= dmc->memory_element_idx) { DebugMemory* old = dmc->memory_stats; dmc->memory_size += 3; dmc->memory_stats = (DebugMemory *) calloc(dmc->memory_size, sizeof(DebugMemory)); if (old) { memcpy(dmc->memory_stats, old, (dmc->memory_size - 3) * sizeof(DebugMemory)); free(old); } } DebugMemory* debug_mem = &dmc->memory_stats[dmc->memory_element_idx]; debug_mem->start = start; debug_mem->size = size; debug_mem->usage = 0; ++dmc->memory_element_idx; } void debug_memory_log(uintptr_t start, uint64 size, int32 type, const char* function) { if (!start || !debug_container) { return; } DebugMemory* mem = debug_memory_find(start); if (!mem) { return; } uint64 idx = atomic_fetch_add_relaxed(&mem->action_idx, 1); if (idx >= ARRAY_COUNT(mem->last_action)) { atomic_set_acquire(&mem->action_idx, 1); idx %= ARRAY_COUNT(mem->last_action); } DebugMemoryRange* dmr = &mem->last_action[idx]; dmr->type = type; dmr->start = start - mem->start; dmr->size = size; dmr->time = intrin_timestamp_counter(); dmr->function_name = function; if (type < 0 && mem->usage < size * -type) { mem->usage = 0; } else { mem->usage += size * type; } } void debug_memory_reserve(uintptr_t start, uint64 size, int32 type, const char* function) { if (!start || !debug_container) { return; } DebugMemory* mem = debug_memory_find(start); if (!mem) { return; } uint64 idx = atomic_fetch_add_relaxed(&mem->reserve_action_idx, 1); if (idx >= ARRAY_COUNT(mem->reserve_action)) { atomic_set_acquire(&mem->reserve_action_idx, 1); idx %= ARRAY_COUNT(mem->reserve_action); } DebugMemoryRange* dmr = &mem->reserve_action[idx]; dmr->type = type; dmr->start = start - mem->start; dmr->size = size; dmr->time = intrin_timestamp_counter(); dmr->function_name = function; } // undo reserve void debug_memory_free(uintptr_t start) { if (!start || !debug_container) { return; } DebugMemory* mem = debug_memory_find(start); if (!mem) { return; } for (int32 i = 0; i < ARRAY_COUNT(mem->reserve_action); ++i) { DebugMemoryRange* dmr = &mem->reserve_action[i]; if (dmr->start == start - mem->start) { dmr->size = 0; return; } } } // @bug This probably requires thread safety inline void debug_memory_reset() { if (!debug_container) { return; } // We remove debug information that are "older" than 1GHz uint64 time = intrin_timestamp_counter() - 1 * GHZ; for (uint64 i = 0; i < debug_container->dmc.memory_element_idx; ++i) { for (int32 j = 0; j < DEBUG_MEMORY_RANGE_MAX; ++j) { if (debug_container->dmc.memory_stats[i].last_action[j].time < time) { memset(&debug_container->dmc.memory_stats[i].last_action[j], 0, sizeof(DebugMemoryRange)); } } } } // @bug This probably requires thread safety byte* log_get_memory() { LogMemory* log_mem = &debug_container->log_memory; if (log_mem->pos + MAX_LOG_LENGTH > log_mem->size) { log_mem->pos = 0; } byte* offset = (byte *) (log_mem->memory + log_mem->pos); memset((void *) offset, 0, MAX_LOG_LENGTH); log_mem->pos += MAX_LOG_LENGTH; return offset; } void log(const char* str, bool should_log, const char* file, const char* function, int32 line) { if (!should_log || !debug_container) { return; } int64 len = str_length(str); while (len > 0) { LogMessage* msg = (LogMessage *) log_get_memory(); // Fill file msg->file = file; msg->function = function; msg->line = line; msg->message = (char *) (msg + 1); msg->time = system_time(); int32 message_length = (int32) OMS_MIN(MAX_LOG_LENGTH - sizeof(LogMessage) - 1, len); memcpy(msg->message, str, message_length); msg->message[message_length] = '\0'; str += message_length; len -= MAX_LOG_LENGTH - sizeof(LogMessage); if (debug_container->log_memory.size - debug_container->log_memory.pos < MAX_LOG_LENGTH) { log_to_file(); debug_container->log_memory.pos = 0; } } } void log(const char* format, LogDataArray data, bool should_log, const char* file, const char* function, int32 line) { ASSERT_SIMPLE(str_length(format) + str_length(file) + str_length(function) + 50 < MAX_LOG_LENGTH); if (!should_log || !debug_container) { return; } if (data.data[0].type == LOG_DATA_VOID) { log(format, should_log, file, function, line); return; } LogMessage* msg = (LogMessage *) log_get_memory(); msg->file = file; msg->function = function; msg->line = line; msg->message = (char *) (msg + 1); msg->time = system_time(); char temp_format[MAX_LOG_LENGTH]; str_copy_short(msg->message, format); for (int32 i = 0; i < LOG_DATA_ARRAY; ++i) { if (data.data[i].type == LOG_DATA_VOID) { break; } str_copy_short(temp_format, msg->message); switch (data.data[i].type) { case LOG_DATA_NONE: { } break; case LOG_DATA_BYTE: { sprintf_fast_iter(msg->message, temp_format, (int32) *((byte *) data.data[i].value)); } break; case LOG_DATA_INT32: { sprintf_fast_iter(msg->message, temp_format, *((int32 *) data.data[i].value)); } break; case LOG_DATA_UINT32: { sprintf_fast_iter(msg->message, temp_format, *((uint32 *) data.data[i].value)); } break; case LOG_DATA_INT64: { sprintf_fast_iter(msg->message, temp_format, *((int64 *) data.data[i].value)); } break; case LOG_DATA_UINT64: { sprintf_fast_iter(msg->message, temp_format, *((uint64 *) data.data[i].value)); } break; case LOG_DATA_CHAR: { sprintf_fast_iter(msg->message, temp_format, *((char *) data.data[i].value)); } break; case LOG_DATA_CHAR_STR: { sprintf_fast_iter(msg->message, temp_format, (const char *) data.data[i].value); } break; case LOG_DATA_FLOAT32: { sprintf_fast_iter(msg->message, temp_format, *((f32 *) data.data[i].value)); } break; case LOG_DATA_FLOAT64: { sprintf_fast_iter(msg->message, temp_format, *((f64 *) data.data[i].value)); } break; default: { UNREACHABLE(); } } } if (debug_container->log_memory.size - debug_container->log_memory.pos < MAX_LOG_LENGTH) { log_to_file(); debug_container->log_memory.pos = 0; } } #endif