From c0e7ac3762e5f2f07216f228ec1927a4915c578a Mon Sep 17 00:00:00 2001 From: luisjoseromero Date: Wed, 10 Feb 2021 20:22:51 +0000 Subject: [PATCH] Integrated Chrome tracing Added support for chrome tracing by integrating the minitrace library (github.com/hrydgard/minitrace), and modified it with a background flushing thread that allows tracing to continue automatically after the predefined 1 million event limit. Menu items and an accelerator (Ctr+T) have also been added. Starting and stopping the trace simply replaces trace.json with the new trace data. The feature is disabled by default. Pass MINITRACE=y to the build command to enable it. Some traces are already added as an example, however they won't have any effect if the feature is disabled. --- CMakeLists.txt | 2 + src/CMakeLists.txt | 6 + src/include/86box/plat.h | 10 + src/include/86box/resource.h | 5 + src/include/minitrace/minitrace.h | 270 +++++++++++++++ src/minitrace/minitrace.c | 541 ++++++++++++++++++++++++++++++ src/pc.c | 3 + src/video/video.c | 5 + src/win/86Box.rc | 8 + src/win/Makefile.mingw | 10 +- src/win/win.c | 19 +- src/win/win_ui.c | 28 ++ 12 files changed, 904 insertions(+), 3 deletions(-) create mode 100644 src/include/minitrace/minitrace.h create mode 100644 src/minitrace/minitrace.c diff --git a/CMakeLists.txt b/CMakeLists.txt index fde8c8514..5d420a5e2 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -45,6 +45,8 @@ option(DISCORD "Discord integration" ON) option(NEW_DYNAREC "Use the PCem v15 (\"new\") dynamic recompiler" OFF) +option(MINITRACE "Enable Chrome tracing using the modified minitrace library" OFF) + option(DEV_BRANCH "Development branch" OFF) CMAKE_DEPENDENT_OPTION(AMD_K5 "AMD K5" ON "DEV_BRANCH" OFF) CMAKE_DEPENDENT_OPTION(CL5422 "Cirrus Logic CL-GD 5402/5420/5422" ON "DEV_BRANCH" OFF) diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index f33ab0958..3e0b0515d 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -90,6 +90,12 @@ else() add_subdirectory(codegen) endif() +if(MINITRACE) + add_compile_definitions(MTR_ENABLED) + add_library(minitrace OBJECT minitrace/minitrace.c) + target_link_libraries(86Box minitrace) +endif() + install(TARGETS 86Box) if(VCPKG_TOOLCHAIN) x_vcpkg_install_local_dependencies(TARGETS 86Box DESTINATION "bin") diff --git a/src/include/86box/plat.h b/src/include/86box/plat.h index aac21111f..af7434d09 100644 --- a/src/include/86box/plat.h +++ b/src/include/86box/plat.h @@ -66,6 +66,11 @@ extern int dopause, /* system is paused */ doresize, /* screen resize requested */ quited, /* system exit requested */ mouse_capture; /* mouse is captured in app */ + +#ifdef MTR_ENABLED +extern int tracing_on; +#endif + extern uint64_t timer_freq; extern int infocus; extern char emu_version[200]; /* version ID string */ @@ -165,6 +170,11 @@ extern void startblit(void); extern void endblit(void); extern void take_screenshot(void); +#ifdef MTR_ENABLED +extern void init_trace(void); +extern void shutdown_trace(void); +#endif + #ifdef __cplusplus } #endif diff --git a/src/include/86box/resource.h b/src/include/86box/resource.h index 24ede722a..28abd983b 100644 --- a/src/include/86box/resource.h +++ b/src/include/86box/resource.h @@ -287,6 +287,11 @@ #define IDM_ACTION_EXIT 40014 #define IDM_ACTION_CTRL_ALT_ESC 40015 #define IDM_ACTION_PAUSE 40016 +#ifdef MTR_ENABLED +#define IDM_ACTION_BEGIN_TRACE 40017 +#define IDM_ACTION_END_TRACE 40018 +#define IDM_ACTION_TRACE 40019 +#endif #define IDM_CONFIG 40020 #define IDM_CONFIG_LOAD 40021 #define IDM_CONFIG_SAVE 40022 diff --git a/src/include/minitrace/minitrace.h b/src/include/minitrace/minitrace.h new file mode 100644 index 000000000..2047eedb7 --- /dev/null +++ b/src/include/minitrace/minitrace.h @@ -0,0 +1,270 @@ +// Minitrace +// +// Copyright 2014 by Henrik Rydgård +// http://www.github.com/hrydgard/minitrace +// Released under the MIT license. +// +// Ultra-light dependency free library for performance tracing C/C++ applications. +// Produces traces compatible with Google Chrome's trace viewer. +// Simply open "about:tracing" in Chrome and load the produced JSON. +// +// This contains far less template magic than the original libraries from Chrome +// because this is meant to be usable from C. +// +// See README.md for a tutorial. +// +// The trace format is documented here: +// https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/edit +// More: +// http://www.altdevblogaday.com/2012/08/21/using-chrometracing-to-view-your-inline-profiling-data/ + +#ifndef MINITRACE_H +#define MINITRACE_H + +#include + +// If MTR_ENABLED is not defined, Minitrace does nothing and has near zero overhead. +// Preferably, set this flag in your build system. If you can't just uncomment this line. +// #define MTR_ENABLED + +// By default, will collect up to 1000000 events, then you must flush. +// It's recommended that you simply call mtr_flush on a background thread +// occasionally. It's safe...ish. +#define INTERNAL_MINITRACE_BUFFER_SIZE 1000000 + +#ifdef __cplusplus +extern "C" { +#endif + +// Initializes Minitrace. Must be called very early during startup of your executable, +// before any MTR_ statements. +void mtr_init(const char *json_file); +// Same as above, but allows passing in a custom stream (FILE *), as returned by +// fopen(). It should be opened for writing, preferably in binary mode to avoid +// processing of line endings (i.e. the "wb" mode). +void mtr_init_from_stream(void *stream); + +// Shuts down minitrace cleanly, flushing the trace buffer. +void mtr_shutdown(void); + +// Lets you enable and disable Minitrace at runtime. +// May cause strange discontinuities in the output. +// Minitrace is enabled on startup by default. +void mtr_start(void); +void mtr_stop(void); + +// Flushes the collected data to disk, clearing the buffer for new data. +void mtr_flush(void); + +// Returns the current time in seconds. Used internally by Minitrace. No caching. +double mtr_time_s(void); + +// Registers a handler that will flush the trace on Ctrl+C. +// Works on Linux and MacOSX, and in Win32 console applications. +void mtr_register_sigint_handler(void); + +// Utility function that should rarely be used. +// If str is semi dynamic, store it permanently in a small pool so we don't need to malloc it. +// The pool fills up fast though and performance isn't great. +// Returns a fixed string if the pool is full. +const char *mtr_pool_string(const char *str); + +// Commented-out types will be supported in the future. +typedef enum { + MTR_ARG_TYPE_NONE = 0, + MTR_ARG_TYPE_INT = 1, // I + // MTR_ARG_TYPE_FLOAT = 2, // TODO + // MTR_ARG_TYPE_DOUBLE = 3, // TODO + MTR_ARG_TYPE_STRING_CONST = 8, // C + MTR_ARG_TYPE_STRING_COPY = 9, + // MTR_ARG_TYPE_JSON_COPY = 10, +} mtr_arg_type; + +// TODO: Add support for more than one argument (metadata) per event +// Having more costs speed and memory. +#define MTR_MAX_ARGS 1 + +// Only use the macros to call these. +void internal_mtr_raw_event(const char *category, const char *name, char ph, void *id); +void internal_mtr_raw_event_arg(const char *category, const char *name, char ph, void *id, mtr_arg_type arg_type, const char *arg_name, void *arg_value); + +#ifdef MTR_ENABLED + +// c - category. Can be filtered by in trace viewer (or at least that's the intention). +// A good use is to pass __FILE__, there are macros further below that will do it for you. +// n - name. Pass __FUNCTION__ in most cases, unless you are marking up parts of one. + +// Scopes. In C++, use MTR_SCOPE. In C, always match them within the same scope. +#define MTR_BEGIN(c, n) internal_mtr_raw_event(c, n, 'B', 0) +#define MTR_END(c, n) internal_mtr_raw_event(c, n, 'E', 0) +#define MTR_SCOPE(c, n) MTRScopedTrace ____mtr_scope(c, n) +#define MTR_SCOPE_LIMIT(c, n, l) MTRScopedTraceLimit ____mtr_scope(c, n, l) + +// Async events. Can span threads. ID identifies which events to connect in the view. +#define MTR_START(c, n, id) internal_mtr_raw_event(c, n, 'S', (void *)(id)) +#define MTR_STEP(c, n, id, step) internal_mtr_raw_event_arg(c, n, 'T', (void *)(id), MTR_ARG_TYPE_STRING_CONST, "step", (void *)(step)) +#define MTR_FINISH(c, n, id) internal_mtr_raw_event(c, n, 'F', (void *)(id)) + +// Flow events. Like async events, but displayed in a more fancy way in the viewer. +#define MTR_FLOW_START(c, n, id) internal_mtr_raw_event(c, n, 's', (void *)(id)) +#define MTR_FLOW_STEP(c, n, id, step) internal_mtr_raw_event_arg(c, n, 't', (void *)(id), MTR_ARG_TYPE_STRING_CONST, "step", (void *)(step)) +#define MTR_FLOW_FINISH(c, n, id) internal_mtr_raw_event(c, n, 'f', (void *)(id)) + +// The same macros, but with a single named argument which shows up as metadata in the viewer. +// _I for int. +// _C is for a const string arg. +// _S will copy the string, freeing on flush (expensive but sometimes necessary). +// but required if the string was generated dynamically. + +// Note that it's fine to match BEGIN_S with END and BEGIN with END_S, etc. +#define MTR_BEGIN_C(c, n, aname, astrval) internal_mtr_raw_event_arg(c, n, 'B', 0, MTR_ARG_TYPE_STRING_CONST, aname, (void *)(astrval)) +#define MTR_END_C(c, n, aname, astrval) internal_mtr_raw_event_arg(c, n, 'E', 0, MTR_ARG_TYPE_STRING_CONST, aname, (void *)(astrval)) +#define MTR_SCOPE_C(c, n, aname, astrval) MTRScopedTraceArg ____mtr_scope(c, n, MTR_ARG_TYPE_STRING_CONST, aname, (void *)(astrval)) + +#define MTR_BEGIN_S(c, n, aname, astrval) internal_mtr_raw_event_arg(c, n, 'B', 0, MTR_ARG_TYPE_STRING_COPY, aname, (void *)(astrval)) +#define MTR_END_S(c, n, aname, astrval) internal_mtr_raw_event_arg(c, n, 'E', 0, MTR_ARG_TYPE_STRING_COPY, aname, (void *)(astrval)) +#define MTR_SCOPE_S(c, n, aname, astrval) MTRScopedTraceArg ____mtr_scope(c, n, MTR_ARG_TYPE_STRING_COPY, aname, (void *)(astrval)) + +#define MTR_BEGIN_I(c, n, aname, aintval) internal_mtr_raw_event_arg(c, n, 'B', 0, MTR_ARG_TYPE_INT, aname, (void*)(intptr_t)(aintval)) +#define MTR_END_I(c, n, aname, aintval) internal_mtr_raw_event_arg(c, n, 'E', 0, MTR_ARG_TYPE_INT, aname, (void*)(intptr_t)(aintval)) +#define MTR_SCOPE_I(c, n, aname, aintval) MTRScopedTraceArg ____mtr_scope(c, n, MTR_ARG_TYPE_INT, aname, (void*)(intptr_t)(aintval)) + +// Instant events. For things with no duration. +#define MTR_INSTANT(c, n) internal_mtr_raw_event(c, n, 'I', 0) +#define MTR_INSTANT_C(c, n, aname, astrval) internal_mtr_raw_event_arg(c, n, 'I', 0, MTR_ARG_TYPE_STRING_CONST, aname, (void *)(astrval)) +#define MTR_INSTANT_I(c, n, aname, aintval) internal_mtr_raw_event_arg(c, n, 'I', 0, MTR_ARG_TYPE_INT, aname, (void *)(aintval)) + +// Counters (can't do multi-value counters yet) +#define MTR_COUNTER(c, n, val) internal_mtr_raw_event_arg(c, n, 'C', 0, MTR_ARG_TYPE_INT, n, (void *)(intptr_t)(val)) + +// Metadata. Call at the start preferably. Must be const strings. + +#define MTR_META_PROCESS_NAME(n) internal_mtr_raw_event_arg("", "process_name", 'M', 0, MTR_ARG_TYPE_STRING_COPY, "name", (void *)(n)) +#define MTR_META_THREAD_NAME(n) internal_mtr_raw_event_arg("", "thread_name", 'M', 0, MTR_ARG_TYPE_STRING_COPY, "name", (void *)(n)) +#define MTR_META_THREAD_SORT_INDEX(i) internal_mtr_raw_event_arg("", "thread_sort_index", 'M', 0, MTR_ARG_TYPE_INT, "sort_index", (void *)(i)) + +#else + +#define MTR_BEGIN(c, n) +#define MTR_END(c, n) +#define MTR_SCOPE(c, n) +#define MTR_START(c, n, id) +#define MTR_STEP(c, n, id, step) +#define MTR_FINISH(c, n, id) +#define MTR_FLOW_START(c, n, id) +#define MTR_FLOW_STEP(c, n, id, step) +#define MTR_FLOW_FINISH(c, n, id) +#define MTR_INSTANT(c, n) + +#define MTR_BEGIN_C(c, n, aname, astrval) +#define MTR_END_C(c, n, aname, astrval) +#define MTR_SCOPE_C(c, n, aname, astrval) + +#define MTR_BEGIN_S(c, n, aname, astrval) +#define MTR_END_S(c, n, aname, astrval) +#define MTR_SCOPE_S(c, n, aname, astrval) + +#define MTR_BEGIN_I(c, n, aname, aintval) +#define MTR_END_I(c, n, aname, aintval) +#define MTR_SCOPE_I(c, n, aname, aintval) + +#define MTR_INSTANT(c, n) +#define MTR_INSTANT_C(c, n, aname, astrval) +#define MTR_INSTANT_I(c, n, aname, aintval) + +// Counters (can't do multi-value counters yet) +#define MTR_COUNTER(c, n, val) + +// Metadata. Call at the start preferably. Must be const strings. + +#define MTR_META_PROCESS_NAME(n) + +#define MTR_META_THREAD_NAME(n) +#define MTR_META_THREAD_SORT_INDEX(i) + +#endif + +// Shortcuts for simple function timing with automatic categories and names. + +#define MTR_BEGIN_FUNC() MTR_BEGIN(__FILE__, __FUNCTION__) +#define MTR_END_FUNC() MTR_END(__FILE__, __FUNCTION__) +#define MTR_SCOPE_FUNC() MTR_SCOPE(__FILE__, __FUNCTION__) +#define MTR_INSTANT_FUNC() MTR_INSTANT(__FILE__, __FUNCTION__) +#define MTR_SCOPE_FUNC_LIMIT_S(l) MTRScopedTraceLimit ____mtr_scope(__FILE__, __FUNCTION__, l) +#define MTR_SCOPE_FUNC_LIMIT_MS(l) MTRScopedTraceLimit ____mtr_scope(__FILE__, __FUNCTION__, (double)l * 0.000001) + +// Same, but with a single argument of the usual types. +#define MTR_BEGIN_FUNC_S(aname, arg) MTR_BEGIN_S(__FILE__, __FUNCTION__, aname, arg) +#define MTR_END_FUNC_S(aname, arg) MTR_END_S(__FILE__, __FUNCTION__, aname, arg) +#define MTR_SCOPE_FUNC_S(aname, arg) MTR_SCOPE_S(__FILE__, __FUNCTION__, aname, arg) + +#define MTR_BEGIN_FUNC_C(aname, arg) MTR_BEGIN_C(__FILE__, __FUNCTION__, aname, arg) +#define MTR_END_FUNC_C(aname, arg) MTR_END_C(__FILE__, __FUNCTION__, aname, arg) +#define MTR_SCOPE_FUNC_C(aname, arg) MTR_SCOPE_C(__FILE__, __FUNCTION__, aname, arg) + +#define MTR_BEGIN_FUNC_I(aname, arg) MTR_BEGIN_I(__FILE__, __FUNCTION__, aname, arg) +#define MTR_END_FUNC_I(aname, arg) MTR_END_I(__FILE__, __FUNCTION__, aname, arg) +#define MTR_SCOPE_FUNC_I(aname, arg) MTR_SCOPE_I(__FILE__, __FUNCTION__, aname, arg) + +#ifdef __cplusplus +} + +#ifdef MTR_ENABLED +// These are optimized to use X events (combined B and E). Much easier to do in C++ than in C. +class MTRScopedTrace { +public: + MTRScopedTrace(const char *category, const char *name) + : category_(category), name_(name) { + start_time_ = mtr_time_s(); + } + ~MTRScopedTrace() { + internal_mtr_raw_event(category_, name_, 'X', &start_time_); + } + +private: + const char *category_; + const char *name_; + double start_time_; +}; + +// Only outputs a block if execution time exceeded the limit. +// TODO: This will effectively call mtr_time_s twice at the end, which is bad. +class MTRScopedTraceLimit { +public: + MTRScopedTraceLimit(const char *category, const char *name, double limit_s) + : category_(category), name_(name), limit_(limit_s) { + start_time_ = mtr_time_s(); + } + ~MTRScopedTraceLimit() { + double end_time = mtr_time_s(); + if (end_time - start_time_ >= limit_) { + internal_mtr_raw_event(category_, name_, 'X', &start_time_); + } + } + +private: + const char *category_; + const char *name_; + double start_time_; + double limit_; +}; + +class MTRScopedTraceArg { +public: + MTRScopedTraceArg(const char *category, const char *name, mtr_arg_type arg_type, const char *arg_name, void *arg_value) + : category_(category), name_(name) { + internal_mtr_raw_event_arg(category, name, 'B', 0, arg_type, arg_name, arg_value); + } + ~MTRScopedTraceArg() { + internal_mtr_raw_event(category_, name_, 'E', 0); + } + +private: + const char *category_; + const char *name_; +}; +#endif + +#endif + +#endif diff --git a/src/minitrace/minitrace.c b/src/minitrace/minitrace.c new file mode 100644 index 000000000..11cae6b9a --- /dev/null +++ b/src/minitrace/minitrace.c @@ -0,0 +1,541 @@ +// minitrace +// Copyright 2014 by Henrik Rydgård +// http://www.github.com/hrydgard/minitrace +// Released under the MIT license. + +// See minitrace.h for basic documentation. + +#include +#include +#include + +#ifdef _WIN32 +#pragma warning (disable:4996) +#define WIN32_LEAN_AND_MEAN +#include +#ifndef __MINGW32__ +#define __thread __declspec(thread) +#endif +#define pthread_cond_t CONDITION_VARIABLE +#define pthread_cond_init(a) InitializeConditionVariable(a) +#define pthread_cond_wait(a, b) SleepConditionVariableCS(a, b, INFINITE) +#define pthread_cond_signal(a) WakeConditionVariable(a) +#define pthread_mutex_t CRITICAL_SECTION +#define pthread_mutex_init(a, b) InitializeCriticalSection(a) +#define pthread_mutex_lock(a) EnterCriticalSection(a) +#define pthread_mutex_unlock(a) LeaveCriticalSection(a) +#define pthread_mutex_destroy(a) DeleteCriticalSection(a) +#else +#include +#include +#include +#include +#endif + +#include + +#ifdef __GNUC__ +#define ATTR_NORETURN __attribute__((noreturn)) +#else +#define ATTR_NORETURN +#endif + +#define ARRAY_SIZE(x) sizeof(x)/sizeof(x[0]) +#define TRUE 1 +#define FALSE 0 + +// Ugh, this struct is already pretty heavy. +// Will probably need to move arguments to a second buffer to support more than one. +typedef struct raw_event { + const char *name; + const char *cat; + void *id; + int64_t ts; + uint32_t pid; + uint32_t tid; + char ph; + mtr_arg_type arg_type; + const char *arg_name; + union { + const char *a_str; + int a_int; + double a_double; + }; +} raw_event_t; + +static raw_event_t *event_buffer; +static raw_event_t *flush_buffer; +static volatile int event_count; +static __attribute__ ((aligned (32))) volatile long is_tracing = FALSE; +static __attribute__ ((aligned (32))) volatile long stop_flushing_requested = FALSE; +static int is_flushing = FALSE; +static int events_in_progress = 0; +static int64_t time_offset; +static int first_line = 1; +static FILE *f; +static __thread int cur_thread_id; // Thread local storage +static int cur_process_id; +static pthread_mutex_t mutex; +static pthread_mutex_t event_mutex; +static pthread_cond_t buffer_not_full_cond; +static pthread_cond_t buffer_full_cond; + +#define STRING_POOL_SIZE 100 +static char *str_pool[100]; + +// forward declaration +void mtr_flush_with_state(int); + +// Tiny portability layer. +// Exposes: +// get_cur_thread_id() +// get_cur_process_id() +// mtr_time_s() +// pthread basics +#ifdef _WIN32 +#define atomic_load(a) InterlockedOr((a), 0) +#define atomic_store(a, b) InterlockedExchange((a), b) + +static int get_cur_thread_id() { + return (int)GetCurrentThreadId(); +} +static int get_cur_process_id() { + return (int)GetCurrentProcessId(); +} + +static uint64_t _frequency = 0; +static uint64_t _starttime = 0; +double mtr_time_s() { + if (_frequency == 0) { + QueryPerformanceFrequency((LARGE_INTEGER*)&_frequency); + QueryPerformanceCounter((LARGE_INTEGER*)&_starttime); + } + __int64 time; + QueryPerformanceCounter((LARGE_INTEGER*)&time); + return ((double) (time - _starttime) / (double) _frequency); +} + +// Ctrl+C handling for Windows console apps +static BOOL WINAPI CtrlHandler(DWORD fdwCtrlType) { + if (atomic_load(&is_tracing) && fdwCtrlType == CTRL_C_EVENT) { + printf("Ctrl-C detected! Flushing trace and shutting down.\n\n"); + mtr_flush(); + mtr_shutdown(); + } + ExitProcess(1); +} + +void mtr_register_sigint_handler() { + // For console apps: + SetConsoleCtrlHandler(&CtrlHandler, TRUE); +} + +HANDLE thread_handle; + +static DWORD WINAPI thread_flush_proc(void* param) { + while(TRUE) { + mtr_flush_with_state(FALSE); + if(atomic_load(&stop_flushing_requested)) { + break; + } + } + return 0; +} + +static void init_flushing_thread(void) { + pthread_mutex_lock(&mutex); + is_flushing = FALSE; + pthread_mutex_unlock(&mutex); + thread_handle = CreateThread(NULL, 0, thread_flush_proc, (void*)0, 0, NULL); +} + +static void join_flushing_thread(void) { + WaitForSingleObject(thread_handle, INFINITE); +} + +#else + +static inline int get_cur_thread_id() { + return (int)(intptr_t)pthread_self(); +} +static inline int get_cur_process_id() { + return (int)getpid(); +} + +#if defined(BLACKBERRY) +double mtr_time_s() { + struct timespec time; + clock_gettime(CLOCK_MONOTONIC, &time); // Linux must use CLOCK_MONOTONIC_RAW due to time warps + return time.tv_sec + time.tv_nsec / 1.0e9; +} +#else +double mtr_time_s() { + static time_t start; + struct timeval tv; + gettimeofday(&tv, NULL); + if (start == 0) { + start = tv.tv_sec; + } + tv.tv_sec -= start; + return (double)tv.tv_sec + (double)tv.tv_usec / 1000000.0; +} +#endif // !BLACKBERRY + +static void termination_handler(int signum) ATTR_NORETURN; +static void termination_handler(int signum) { + (void) signum; + if (is_tracing) { + printf("Ctrl-C detected! Flushing trace and shutting down.\n\n"); + mtr_flush(); + fwrite("\n]}\n", 1, 4, f); + fclose(f); + } + exit(1); +} + +void mtr_register_sigint_handler() { +#ifndef MTR_ENABLED + return; +#endif + // Avoid altering set-to-be-ignored handlers while registering. + if (signal(SIGINT, &termination_handler) == SIG_IGN) + signal(SIGINT, SIG_IGN); +} + +#endif + +void mtr_init_from_stream(void *stream) { +#ifndef MTR_ENABLED + return; +#endif + event_buffer = (raw_event_t *)malloc(INTERNAL_MINITRACE_BUFFER_SIZE * sizeof(raw_event_t)); + flush_buffer = (raw_event_t *)malloc(INTERNAL_MINITRACE_BUFFER_SIZE * sizeof(raw_event_t)); + event_count = 0; + f = (FILE *)stream; + const char *header = "{\"traceEvents\":[\n"; + fwrite(header, 1, strlen(header), f); + time_offset = (uint64_t)(mtr_time_s() * 1000000); + first_line = 1; + pthread_mutex_init(&mutex, 0); + pthread_mutex_init(&event_mutex, 0); +} + +void mtr_init(const char *json_file) { +#ifndef MTR_ENABLED + return; +#endif + mtr_init_from_stream(fopen(json_file, "wb")); +} + +void mtr_shutdown() { + int i; +#ifndef MTR_ENABLED + return; +#endif + + mtr_flush_with_state(TRUE); + + fwrite("\n]}\n", 1, 4, f); + fclose(f); + pthread_mutex_destroy(&mutex); + pthread_mutex_destroy(&event_mutex); + f = 0; + free(event_buffer); + event_buffer = 0; + for (i = 0; i < STRING_POOL_SIZE; i++) { + if (str_pool[i]) { + free(str_pool[i]); + str_pool[i] = 0; + } + } +} + +const char *mtr_pool_string(const char *str) { + int i; + for (i = 0; i < STRING_POOL_SIZE; i++) { + if (!str_pool[i]) { + str_pool[i] = (char*)malloc(strlen(str) + 1); + strcpy(str_pool[i], str); + return str_pool[i]; + } else { + if (!strcmp(str, str_pool[i])) + return str_pool[i]; + } + } + return "string pool full"; +} + +void mtr_start() { +#ifndef MTR_ENABLED + return; +#endif + pthread_cond_init(&buffer_not_full_cond); + pthread_cond_init(&buffer_full_cond); + atomic_store(&is_tracing, TRUE); + init_flushing_thread(); +} + +void mtr_stop() { +#ifndef MTR_ENABLED + return; +#endif + atomic_store(&is_tracing, FALSE); + atomic_store(&stop_flushing_requested, TRUE); + pthread_cond_signal(&buffer_not_full_cond); + pthread_cond_signal(&buffer_full_cond); + join_flushing_thread(); + atomic_store(&stop_flushing_requested, FALSE); +} + +// TODO: fwrite more than one line at a time. +// Flushing is thread safe and process async +// using double-buffering mechanism. +// Aware: only one flushing process may be +// running at any point of time +void mtr_flush_with_state(int is_last) { +#ifndef MTR_ENABLED + return; +#endif + int i = 0; + char linebuf[1024]; + char arg_buf[1024]; + char id_buf[256]; + int event_count_copy = 0; + int events_in_progress_copy = 1; + raw_event_t *event_buffer_tmp = NULL; + + // small critical section to swap buffers + // - no any new events can be spawn while + // swapping since they tied to the same mutex + // - checks for any flushing in process + pthread_mutex_lock(&mutex); + // if not flushing already + if (is_flushing) { + pthread_mutex_unlock(&mutex); + return; + } + is_flushing = TRUE; + if(!is_last) { + while(event_count < INTERNAL_MINITRACE_BUFFER_SIZE && atomic_load(&is_tracing)) { + pthread_cond_wait(&buffer_full_cond, &mutex); + } + } + event_count_copy = event_count; + event_buffer_tmp = flush_buffer; + flush_buffer = event_buffer; + event_buffer = event_buffer_tmp; + event_count = 0; + // waiting for any unfinished events before swap + while (events_in_progress_copy != 0) { + pthread_mutex_lock(&event_mutex); + events_in_progress_copy = events_in_progress; + pthread_mutex_unlock(&event_mutex); + } + pthread_mutex_unlock(&mutex); + pthread_cond_signal(&buffer_not_full_cond); + + for (i = 0; i < event_count_copy; i++) { + raw_event_t *raw = &flush_buffer[i]; + int len; + switch (raw->arg_type) { + case MTR_ARG_TYPE_INT: + snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":%i", raw->arg_name, raw->a_int); + break; + case MTR_ARG_TYPE_STRING_CONST: + snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":\"%s\"", raw->arg_name, raw->a_str); + break; + case MTR_ARG_TYPE_STRING_COPY: + if (strlen(raw->a_str) > 700) { + snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":\"%.*s\"", raw->arg_name, 700, raw->a_str); + } else { + snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":\"%s\"", raw->arg_name, raw->a_str); + } + break; + case MTR_ARG_TYPE_NONE: + arg_buf[0] = '\0'; + break; + } + if (raw->id) { + switch (raw->ph) { + case 'S': + case 'T': + case 'F': + // TODO: Support full 64-bit pointers + snprintf(id_buf, ARRAY_SIZE(id_buf), ",\"id\":\"0x%08x\"", (uint32_t)(uintptr_t)raw->id); + break; + case 'X': + snprintf(id_buf, ARRAY_SIZE(id_buf), ",\"dur\":%i", (int)raw->a_double); + break; + } + } else { + id_buf[0] = 0; + } + const char *cat = raw->cat; +#ifdef _WIN32 + // On Windows, we often end up with backslashes in category. + char temp[256]; + { + int len = (int)strlen(cat); + int i; + if (len > 255) len = 255; + for (i = 0; i < len; i++) { + temp[i] = cat[i] == '\\' ? '/' : cat[i]; + } + temp[len] = 0; + cat = temp; + } +#endif + + len = snprintf(linebuf, ARRAY_SIZE(linebuf), "%s{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 ",\"ph\":\"%c\",\"name\":\"%s\",\"args\":{%s}%s}", + first_line ? "" : ",\n", + cat, raw->pid, raw->tid, raw->ts - time_offset, raw->ph, raw->name, arg_buf, id_buf); + fwrite(linebuf, 1, len, f); + first_line = 0; + + if (raw->arg_type == MTR_ARG_TYPE_STRING_COPY) { + free((void*)raw->a_str); + } + #ifdef MTR_COPY_EVENT_CATEGORY_AND_NAME + free(raw->name); + free(raw->cat); + #endif + } + + pthread_mutex_lock(&mutex); + is_flushing = is_last; + pthread_mutex_unlock(&mutex); +} + +void mtr_flush() { + mtr_flush_with_state(FALSE); +} + +void internal_mtr_raw_event(const char *category, const char *name, char ph, void *id) { +#ifndef MTR_ENABLED + return; +#endif + + if (!atomic_load(&is_tracing)) { + return; + } + pthread_mutex_lock(&mutex); + while(event_count >= INTERNAL_MINITRACE_BUFFER_SIZE && atomic_load(&is_tracing)) { + pthread_cond_wait(&buffer_not_full_cond, &mutex); + } + raw_event_t *ev = &event_buffer[event_count]; + ++event_count; + pthread_mutex_lock(&event_mutex); + ++events_in_progress; + pthread_mutex_unlock(&event_mutex); + int local_event_count = event_count; + pthread_mutex_unlock(&mutex); + if(local_event_count >= INTERNAL_MINITRACE_BUFFER_SIZE) { + pthread_cond_signal(&buffer_full_cond); + } + + double ts = mtr_time_s(); + + if (!cur_thread_id) { + cur_thread_id = get_cur_thread_id(); + } + if (!cur_process_id) { + cur_process_id = get_cur_process_id(); + } + +#ifdef MTR_COPY_EVENT_CATEGORY_AND_NAME + const size_t category_len = strlen(category); + ev->cat = malloc(category_len + 1); + strcpy(ev->cat, category); + + const size_t name_len = strlen(name); + ev->name = malloc(name_len + 1); + strcpy(ev->name, name); + +#else + ev->cat = category; + ev->name = name; +#endif + + ev->id = id; + ev->ph = ph; + if (ev->ph == 'X') { + double x; + memcpy(&x, id, sizeof(double)); + ev->ts = (int64_t)(x * 1000000); + ev->a_double = (ts - x) * 1000000; + } else { + ev->ts = (int64_t)(ts * 1000000); + } + ev->tid = cur_thread_id; + ev->pid = cur_process_id; + ev->arg_type = MTR_ARG_TYPE_NONE; + + pthread_mutex_lock(&event_mutex); + --events_in_progress; + pthread_mutex_unlock(&event_mutex); +} + +void internal_mtr_raw_event_arg(const char *category, const char *name, char ph, void *id, mtr_arg_type arg_type, const char *arg_name, void *arg_value) { +#ifndef MTR_ENABLED + return; +#endif + if (!atomic_load(&is_tracing)) { + return; + } + pthread_mutex_lock(&mutex); + while(event_count >= INTERNAL_MINITRACE_BUFFER_SIZE && atomic_load(&is_tracing)) { + pthread_cond_wait(&buffer_not_full_cond, &mutex); + } + raw_event_t *ev = &event_buffer[event_count]; + ++event_count; + pthread_mutex_lock(&event_mutex); + ++events_in_progress; + pthread_mutex_unlock(&event_mutex); + int local_event_count = event_count; + pthread_mutex_unlock(&mutex); + if(local_event_count >= INTERNAL_MINITRACE_BUFFER_SIZE) { + pthread_cond_signal(&buffer_full_cond); + } + + + if (!cur_thread_id) { + cur_thread_id = get_cur_thread_id(); + } + if (!cur_process_id) { + cur_process_id = get_cur_process_id(); + } + double ts = mtr_time_s(); + +#ifdef MTR_COPY_EVENT_CATEGORY_AND_NAME + const size_t category_len = strlen(category); + ev->cat = malloc(category_len + 1); + strcpy(ev->cat, category); + + const size_t name_len = strlen(name); + ev->name = malloc(name_len + 1); + strcpy(ev->name, name); + +#else + ev->cat = category; + ev->name = name; +#endif + + ev->id = id; + ev->ts = (int64_t)(ts * 1000000); + ev->ph = ph; + ev->tid = cur_thread_id; + ev->pid = cur_process_id; + ev->arg_type = arg_type; + ev->arg_name = arg_name; + switch (arg_type) { + case MTR_ARG_TYPE_INT: ev->a_int = (int)(uintptr_t)arg_value; break; + case MTR_ARG_TYPE_STRING_CONST: ev->a_str = (const char*)arg_value; break; + case MTR_ARG_TYPE_STRING_COPY: ev->a_str = strdup((const char*)arg_value); break; + case MTR_ARG_TYPE_NONE: break; + } + + pthread_mutex_lock(&event_mutex); + --events_in_progress; + pthread_mutex_unlock(&event_mutex); +} + diff --git a/src/pc.c b/src/pc.c index ef1005091..efe6f0967 100644 --- a/src/pc.c +++ b/src/pc.c @@ -89,6 +89,9 @@ int dopause, /* system is paused */ uint64_t timer_freq; char emu_version[200]; /* version ID string */ +#ifdef MTR_ENABLED +int tracing_on = 0; +#endif /* Commandline options. */ int dump_on_exit = 0; /* (O) dump regs on exit */ diff --git a/src/video/video.c b/src/video/video.c index 678e7771b..7d9c85def 100644 --- a/src/video/video.c +++ b/src/video/video.c @@ -70,6 +70,7 @@ #include <86box/video.h> #include <86box/vid_svga.h> +#include volatile int screenshots = 0; bitmap_t *buffer32 = NULL; @@ -285,6 +286,7 @@ void blit_thread(void *param) while (1) { thread_wait_event(blit_data.wake_blit_thread, -1); thread_reset_event(blit_data.wake_blit_thread); + MTR_BEGIN("video", "blit_thread"); if (blit_func) blit_func(blit_data.x, blit_data.y, @@ -292,6 +294,7 @@ void blit_thread(void *param) blit_data.w, blit_data.h); blit_data.busy = 0; + MTR_END("video", "blit_thread"); thread_set_event(blit_data.blit_complete); } } @@ -448,6 +451,7 @@ void video_blit_memtoscreen(int x, int y, int y1, int y2, int w, int h) { int yy; + MTR_BEGIN("video", "video_blit_memtoscreen"); if (y2 > 0) { for (yy = y1; yy < y2; yy++) { @@ -482,6 +486,7 @@ video_blit_memtoscreen(int x, int y, int y1, int y2, int w, int h) blit_data.h = h; thread_set_event(blit_data.wake_blit_thread); + MTR_END("video", "video_blit_memtoscreen"); } diff --git a/src/win/86Box.rc b/src/win/86Box.rc index 8dfa152db..7bc70a1ef 100644 --- a/src/win/86Box.rc +++ b/src/win/86Box.rc @@ -122,6 +122,11 @@ BEGIN # endif MENUITEM SEPARATOR MENUITEM "Take s&creenshot\tCtrl+F11", IDM_ACTION_SCREENSHOT +#ifdef MTR_ENABLED + MENUITEM SEPARATOR + MENUITEM "Begin trace\tCtrl+T", IDM_ACTION_BEGIN_TRACE + MENUITEM "End trace\tCtrl+T", IDM_ACTION_END_TRACE +#endif END #if defined(ENABLE_LOG_TOGGLES) || defined(ENABLE_LOG_COMMANDS) POPUP "&Logging" @@ -262,6 +267,9 @@ BEGIN #endif #ifdef ENABLE_LOG_BREAKPOINT VK_F10, IDM_LOG_BREAKPOINT, CONTROL, VIRTKEY +#endif +#ifdef MTR_ENABLED + "T", IDM_ACTION_TRACE, CONTROL, VIRTKEY #endif VK_PRIOR,IDM_VID_FULLSCREEN, VIRTKEY, CONTROL , ALT VK_F11, IDM_ACTION_SCREENSHOT, VIRTKEY, CONTROL diff --git a/src/win/Makefile.mingw b/src/win/Makefile.mingw index 5aaad9a86..a5eedf84f 100644 --- a/src/win/Makefile.mingw +++ b/src/win/Makefile.mingw @@ -284,7 +284,7 @@ endif ######################################################################### # Nothing should need changing from here on.. # ######################################################################### -VPATH := $(EXPATH) . $(CODEGEN) cpu \ +VPATH := $(EXPATH) . $(CODEGEN) minitrace cpu \ cdrom chipset device disk disk/minivhd floppy \ game machine mem printer \ sio sound \ @@ -482,6 +482,12 @@ RFLAGS += -DUSE_DISCORD DISCORDOBJ := win_discord.o endif +ifeq ($(MINITRACE), y) +OPTS += -DMTR_ENABLED +RFLAGS += -DMTR_ENABLED +MINITRACEOBJ := minitrace.o +endif + # Options for the DEV branch. ifeq ($(DEV_BRANCH), y) OPTS += -DDEV_BRANCH @@ -781,7 +787,7 @@ OBJ := $(MAINOBJ) $(CPUOBJ) $(CHIPSETOBJ) $(MCHOBJ) $(DEVOBJ) $(MEMOBJ) \ $(FDDOBJ) $(GAMEOBJ) $(CDROMOBJ) $(ZIPOBJ) $(MOOBJ) $(HDDOBJ) $(MINIVHDOBJ) \ $(NETOBJ) $(PRINTOBJ) $(SCSIOBJ) $(SIOOBJ) $(SNDOBJ) $(VIDOBJ) \ $(PLATOBJ) $(UIOBJ) $(FSYNTHOBJ) $(MUNTOBJ) $(DEVBROBJ) \ - $(DISCORDOBJ) + $(DISCORDOBJ) $(MINITRACEOBJ) ifdef EXOBJ OBJ += $(EXOBJ) endif diff --git a/src/win/win.c b/src/win/win.c index 3e29062eb..da9e4028b 100644 --- a/src/win/win.c +++ b/src/win/win.c @@ -49,7 +49,9 @@ #include <86box/win_sdl.h> #include <86box/win.h> #include <86box/version.h> - +#ifdef MTR_ENABLED +#include +#endif typedef struct { WCHAR str[512]; @@ -217,6 +219,21 @@ plat_get_string(int i) return((wchar_t *)str); } +#ifdef MTR_ENABLED +void +init_trace(void) +{ + mtr_init("trace.json"); + mtr_start(); +} + +void +shutdown_trace(void) +{ + mtr_stop(); + mtr_shutdown(); +} +#endif /* Create a console if we don't already have one. */ static void diff --git a/src/win/win_ui.c b/src/win/win_ui.c index e72307d9b..9e156f67c 100644 --- a/src/win/win_ui.c +++ b/src/win/win_ui.c @@ -48,6 +48,9 @@ # include <86box/win_discord.h> #endif +#ifdef MTR_ENABLED +#include +#endif #define TIMER_1SEC 1 /* ID of the one-second timer */ @@ -294,6 +297,9 @@ ResetAllMenus(void) else EnableMenuItem(menuMain, IDM_DISCORD, MF_DISABLED); #endif +#ifdef MTR_ENABLED + EnableMenuItem(menuMain, IDM_ACTION_END_TRACE, MF_DISABLED); +#endif } @@ -378,6 +384,19 @@ plat_power_off(void) exit(-1); } +#ifdef MTR_ENABLED +static void +handle_trace(HMENU hmenu, int trace) +{ + EnableMenuItem(hmenu, IDM_ACTION_BEGIN_TRACE, trace? MF_GRAYED : MF_ENABLED); + EnableMenuItem(hmenu, IDM_ACTION_END_TRACE, trace? MF_ENABLED : MF_GRAYED); + if (trace) { + init_trace(); + } else { + shutdown_trace(); + } +} +#endif /* Catch WM_INPUT messages for 'current focus' window. */ #if defined(__amd64__) || defined(__aarch64__) @@ -489,6 +508,15 @@ MainWindowProcedure(HWND hwnd, UINT message, WPARAM wParam, LPARAM lParam) take_screenshot(); break; +#ifdef MTR_ENABLED + case IDM_ACTION_BEGIN_TRACE: + case IDM_ACTION_END_TRACE: + case IDM_ACTION_TRACE: + tracing_on = !tracing_on; + handle_trace(hmenu, tracing_on); + break; +#endif + case IDM_ACTION_HRESET: win_notify_dlg_open(); if (confirm_reset)