diff --git a/.github/workflows/Linux-network-clients.yml b/.github/workflows/Linux-network-clients.yml index 6abe136402..2795726498 100644 --- a/.github/workflows/Linux-network-clients.yml +++ b/.github/workflows/Linux-network-clients.yml @@ -132,6 +132,17 @@ jobs: make -C samples/network/mcp_server check make -C samples/network/mcp_server clean + - name: GET_LOG's ring, written from four threads while read + shell: bash + working-directory: ${{ github.workspace }} + run: | + set -eu + make -C samples/runloop/log_ring clean + make -C samples/runloop/log_ring SANITIZER=address,undefined + ASAN_OPTIONS=detect_leaks=1 UBSAN_OPTIONS=halt_on_error=1 \ + make -C samples/runloop/log_ring check + make -C samples/runloop/log_ring clean + - name: Command options and speed setters shell: bash working-directory: ${{ github.workspace }} diff --git a/command.c b/command.c index 94259702cc..423543fd7b 100644 --- a/command.c +++ b/command.c @@ -2109,6 +2109,51 @@ bool command_set_option(command_t *cmd, const char *arg) return true; } +#ifdef HAVE_MCP +/* GET_LOG [since] + * + * The lines logged since line @since (0 when left out), as many as one + * reply holds, then NEXT and the number to ask from next time. Lines + * logged before the first GET_LOG, or the MCP server started, are not + * kept; SKIPPED and a count says lines were overwritten before they + * were read. */ +bool command_get_log(command_t *cmd, const char *arg) +{ + size_t first, next, _len; + unsigned since = 0; + char *reply; + + while (arg && *arg == ' ') + arg++; + if (arg && *arg && !command_arg_uint(arg, &since)) + { + command_reply_error(cmd, "GET_LOG", "a line number, not %s", arg); + return false; + } + verbosity_ring_arm(); + if (!(reply = (char*)malloc(COMMAND_LIST_REPLY_MAX + 1))) + { + command_reply_error(cmd, "GET_LOG", "out of memory"); + return false; + } + /* room kept for the SKIPPED and NEXT lines */ + _len = verbosity_ring_read(since, reply + 32, COMMAND_LIST_REPLY_MAX - 64, + &first, &next); + if (first > since) + { + int n = snprintf(reply, 32, "SKIPPED %u\n", (unsigned)(first - since)); + memmove(reply + n, reply + 32, _len); + _len += (size_t)n; + } + else + memmove(reply, reply + 32, _len); + _len += (size_t)snprintf(reply + _len, 32, "NEXT %u\n", (unsigned)next); + cmd->replier(cmd, reply, _len); + free(reply); + return true; +} +#endif + /* RUN_FRAMES in progress: frames still to run, and the reply owed */ static struct { diff --git a/command.h b/command.h index 9472e295f8..c07a8cc0c2 100644 --- a/command.h +++ b/command.h @@ -541,6 +541,11 @@ struct cmd_action_map bool command_get_option(command_t *cmd, const char *arg); bool command_set_option(command_t *cmd, const char *arg); +#ifdef HAVE_MCP +/* GET_LOG [since] */ +bool command_get_log(command_t *cmd, const char *arg); +#endif + /* RUN_FRAMES ; the run loop calls tick after each frame it runs * and cancel when the content goes */ #define COMMAND_RUN_FRAMES_MAX 36000 @@ -632,6 +637,13 @@ static const struct cmd_param cmd_params_option_set[] = { CMD_PARAM_STRING, true, NULL, "on|off", NULL }, { NULL } }; +#ifdef HAVE_MCP +static const struct cmd_param cmd_params_log[] = { + { "since", "The first line wanted, as NEXT gave it; 0 when left out.", + CMD_PARAM_INT, false, NULL, NULL, "0" }, + { NULL } +}; +#endif static const struct cmd_param cmd_params_run_frames[] = { { "count", "How many frames to run.", CMD_PARAM_INT, true, NULL, NULL, NULL }, @@ -730,6 +742,9 @@ static const struct cmd_action_map action_map[] = { /* GET_OPTION reports these and more; this stays for the clients that * have always asked it. */ { "GET_CONFIG_PARAM", command_get_config_param, "", "Report the value of a configuration setting.", CMD_INFO_READ_ONLY | CMD_INFO_NO_TOOL, cmd_params_config }, +#ifdef HAVE_MCP + { "GET_LOG", command_get_log, "[since]", "Report the lines RetroArch has logged since the given line, then NEXT and the line to ask from next time.", CMD_INFO_READ_ONLY, cmd_params_log }, +#endif { "RUN_FRAMES", command_run_frames, "", "Pause and run the content the given number of frames, answered once the last has run; it stays paused.", 0, cmd_params_run_frames }, { "SET_INPUT", command_set_input, " ", "Hold a RetroPad button or stick axis for the core, over the player's own input, until set again or released. Answers with what the player holds: buttons and axes, tab separated.", 0, cmd_params_input }, { "RELEASE_INPUT", command_release_input, "[player]", "Let go of everything SET_INPUT holds, for one player or all.", 0, cmd_params_input_release }, diff --git a/docs/mcp-server.md b/docs/mcp-server.md index 1ca4d136c1..973f405072 100644 --- a/docs/mcp-server.md +++ b/docs/mcp-server.md @@ -118,6 +118,13 @@ A hotkey tool that is still a tool answers ` pressed` for the same reason: the press goes out on the next poll, and what it changed is read back with `GET_OPTION`. +`GET_LOG [since]` gives the lines RetroArch has logged since line +`since` (0 when left out), as far as the logging verbosity lets them be +logged, then `NEXT` and the line number to ask from next time; when +lines were overwritten before they were read it says `SKIPPED` and how +many first. The last 256 lines are kept, from when the MCP server +starts or the first `GET_LOG`. + `RUN_FRAMES ` pauses the content, if it is running, and runs it that many frames, one per frame advance, answering once the last has run; it is left paused. With `SET_INPUT` before it, an assistant plays diff --git a/network/mcp_server.c b/network/mcp_server.c index 3bf92b70e2..f3688ebe3e 100644 --- a/network/mcp_server.c +++ b/network/mcp_server.c @@ -1388,6 +1388,7 @@ command_t *command_mcp_new(uint16_t port, const char *bind_address, cmd->reply_image_to = mcp_reply_image_to; cmd->destroy = mcp_destroy; cmd->structured = true; + verbosity_ring_arm(); RARCH_LOG("[MCP] Listening on http://%s:%hu/mcp.\n", bind_address, (unsigned short)port); return cmd; diff --git a/samples/network/mcp_server/stubs.c b/samples/network/mcp_server/stubs.c index cf522a19a8..27fa32a7c2 100644 --- a/samples/network/mcp_server/stubs.c +++ b/samples/network/mcp_server/stubs.c @@ -20,3 +20,4 @@ void RARCH_ERR(const char *fmt, ...) vfprintf(stderr, fmt, ap); va_end(ap); } +void verbosity_ring_arm(void) { } diff --git a/samples/runloop/log_ring/Makefile b/samples/runloop/log_ring/Makefile new file mode 100644 index 0000000000..48025d8c5a --- /dev/null +++ b/samples/runloop/log_ring/Makefile @@ -0,0 +1,30 @@ +compiler ?= gcc +ROOT := ../../.. +LC := $(ROOT)/libretro-common +TARGET := log_ring_test +SOURCES := log_ring_test.c $(ROOT)/verbosity.c \ + $(LC)/rthreads/rthreads.c $(LC)/compat/compat_strl.c \ + $(LC)/file/file_path.c $(LC)/file/file_path_io.c \ + $(LC)/streams/file_stream.c $(LC)/vfs/vfs_implementation.c \ + $(LC)/string/stdstring.c $(LC)/encodings/encoding_utf.c \ + $(LC)/compat/fopen_utf8.c $(LC)/time/rtime.c $(LC)/string/rstrtod.c +CFLAGS += -std=gnu89 -Wall -g -O1 -I$(ROOT) -I$(LC)/include -DHAVE_MCP \ + -DHAVE_THREADS +LDFLAGS += -lpthread +ifneq ($(SANITIZER),) + CFLAGS += -fsanitize=$(SANITIZER) -fno-omit-frame-pointer + LDFLAGS += -fsanitize=$(SANITIZER) +endif +ifneq ($(findstring mingw,$(compiler)),) + TARGET := $(TARGET).exe + LDFLAGS := $(filter-out -lpthread,$(LDFLAGS)) +endif + +all: $(TARGET) +$(TARGET): $(SOURCES) $(ROOT)/verbosity.h + $(compiler) $(CFLAGS) $(SOURCES) -o $@ $(LDFLAGS) +check: $(TARGET) + ./$(TARGET) 2>/dev/null +clean: + rm -f log_ring_test log_ring_test.exe +.PHONY: all check clean diff --git a/samples/runloop/log_ring/log_ring_test.c b/samples/runloop/log_ring/log_ring_test.c new file mode 100644 index 0000000000..d9d2cf682b --- /dev/null +++ b/samples/runloop/log_ring/log_ring_test.c @@ -0,0 +1,107 @@ +/* GET_LOG's ring in verbosity.c: lines logged from several threads at + * once, read while they are written, arrive whole and in order, and + * an overrun is reported as lines skipped rather than torn lines. */ +#include +#include +#include + +#include +#include + +#include "../../../verbosity.h" + +#define THREADS 4 +#define LINES 20000 + +static unsigned failures; +static retro_atomic_int_t done; + +#define CHECK(test) do { if (!(test)) { \ + fprintf(stderr, "FAIL line %u: %s\n", (unsigned)__LINE__, #test); \ + failures++; } } while (0) + +static void writer(void *data) +{ + unsigned t = (unsigned)(size_t)data; + unsigned i; + for (i = 0; i < LINES; i++) + RARCH_LOG("w%u %06u ........................................\n", t, i); + retro_atomic_fetch_add_int(&done, 1); +} + +/* A line as the writers write it, after the tag RARCH_LOG adds */ +static bool line_whole(const char *s, const char *e) +{ + const char *w = strstr(s, "] w"); + unsigned t, i; + if (!w || w > e) + return false; + if (sscanf(w + 3, "%u %6u", &t, &i) != 2 || t >= THREADS || i >= LINES) + return false; + return (size_t)(e - w) == strlen("] w0 000000 ") + 40; +} + +static unsigned drain(size_t *since, char *buf, size_t len, unsigned *skipped) +{ + size_t first, next; + size_t n = verbosity_ring_read(*since, buf, len, &first, &next); + unsigned got = 0; + char *s = buf; + CHECK(next >= first && first >= *since); + *skipped += (unsigned)(first - *since); + while (s < buf + n) + { + char *e = strchr(s, '\n'); + CHECK(e != NULL); + if (!e) + break; + CHECK(line_whole(s, e)); + got++; + s = e + 1; + } + *since = next; + return got; +} + +int main(void) +{ + sthread_t *th[THREADS]; + char *buf = (char*)malloc(1 << 16); + size_t since = 0, first, next; + unsigned got = 0, skipped = 0, i; + + verbosity_enable(); + CHECK(verbosity_ring_read(0, buf, 1 << 16, &first, &next) == 0); + RARCH_LOG("before the ring is armed\n"); + CHECK(verbosity_ring_read(0, buf, 1 << 16, &first, &next) == 0); + verbosity_ring_arm(); + + for (i = 0; i < THREADS; i++) + th[i] = sthread_create(writer, (void*)(size_t)i); + while (retro_atomic_load_acquire_int(&done) < THREADS) + got += drain(&since, buf, 1 << 16, &skipped); + for (i = 0; i < THREADS; i++) + sthread_join(th[i]); + got += drain(&since, buf, 1 << 16, &skipped); + + /* every line was read once or counted as skipped; a slot being + * written when read is skipped too, so allow none lost beyond that */ + CHECK(since == (size_t)THREADS * LINES); + CHECK(got + skipped <= (unsigned)(THREADS * LINES)); + CHECK(got > 0); + + /* a short buffer stops at a whole line, and NEXT resumes there */ + RARCH_LOG("w0 000001 ........................................\n"); + RARCH_LOG("w0 000002 ........................................\n"); + { + size_t n = verbosity_ring_read(since, buf, 80, &first, &next); + CHECK(n > 0 && n < 80 && next == since + 1); + n = verbosity_ring_read(next, buf, 1 << 16, &first, &next); + CHECK(n > 0 && next == since + 2); + } + + free(buf); + printf("log_ring: %s (%u read, %u skipped)\n", + failures ? "FAIL" : "PASS", got, skipped); + return failures ? 1 : 0; +} diff --git a/tools/tsan-samples.list b/tools/tsan-samples.list index 83ac1a4590..eadb6991d6 100644 --- a/tools/tsan-samples.list +++ b/tools/tsan-samples.list @@ -83,3 +83,4 @@ samples/ui/companion_thumbs_handoff companion_thumbs_test samples/midi/fmsynth_queue fmsynth_queue_test samples/input/joypad_slots joypad_slots_test samples/audio/rsound_thread rsound_thread_test +samples/runloop/log_ring log_ring_test diff --git a/verbosity.c b/verbosity.c index ef2bc33d53..927215053f 100644 --- a/verbosity.c +++ b/verbosity.c @@ -354,6 +354,100 @@ static void rarch_log_line_write(FILE *fp, const char *tag_v, #endif #endif +#ifdef HAVE_MCP +#include +#include + +/* The last lines logged, for GET_LOG, filled by whatever thread logs + * and read on the main thread without a lock: a writer claims a line + * number, marks the slot busy, writes the text as atomic words and + * stamps the slot with its number; a reader takes a slot's text only + * when the stamp is the line it wants before and after the copy. */ +#define LOG_RING_SLOTS 256 +#define LOG_RING_WORDS (256 / sizeof(size_t)) + +struct log_ring_slot +{ + retro_atomic_size_t stamp; /* line number + 1, 0 while written */ + retro_atomic_size_t text[LOG_RING_WORDS]; +}; + +static struct +{ + struct log_ring_slot slots[LOG_RING_SLOTS]; + retro_atomic_size_t head; + retro_atomic_int_t armed; +} log_ring; + +void verbosity_ring_arm(void) +{ + retro_atomic_store_release_int(&log_ring.armed, 1); +} + +static void verbosity_ring_put(const char *line) +{ + size_t i; + size_t seq; + size_t words[LOG_RING_WORDS]; + struct log_ring_slot *slot; + + if (!retro_atomic_load_relaxed_int(&log_ring.armed)) + return; + memset(words, 0, sizeof(words)); + strlcpy((char*)words, line, sizeof(words)); + seq = retro_atomic_fetch_add_size(&log_ring.head, 1); + slot = &log_ring.slots[seq % LOG_RING_SLOTS]; + retro_atomic_store_relaxed_size(&slot->stamp, 0); + retro_atomic_thread_fence_release(); + for (i = 0; i < LOG_RING_WORDS; i++) + retro_atomic_store_relaxed_size(&slot->text[i], words[i]); + retro_atomic_store_release_size(&slot->stamp, seq + 1); +} + +size_t verbosity_ring_read(size_t since, char *s, size_t len, + size_t *first, size_t *next) +{ + size_t _len = 0; + size_t head = retro_atomic_load_acquire_size(&log_ring.head); + size_t seq = since; + + if (head > LOG_RING_SLOTS && seq < head - LOG_RING_SLOTS) + seq = head - LOG_RING_SLOTS; + if (seq > head) + seq = head; + *first = seq; + for (; seq < head; seq++) + { + size_t i, n; + size_t words[LOG_RING_WORDS]; + struct log_ring_slot *slot = &log_ring.slots[seq % LOG_RING_SLOTS]; + size_t stamp = retro_atomic_load_acquire_size(&slot->stamp); + /* still being written, or already a later line: skipped */ + if (stamp != seq + 1) + continue; + for (i = 0; i < LOG_RING_WORDS; i++) + words[i] = retro_atomic_load_relaxed_size(&slot->text[i]); + retro_atomic_thread_fence_acquire(); + if (retro_atomic_load_relaxed_size(&slot->stamp) != stamp) + continue; + ((char*)words)[sizeof(words) - 1] = '\0'; + n = strlen((const char*)words); + if (_len + n + 2 > len) + break; + memcpy(s + _len, words, n); + _len += n; + if (!n || s[_len - 1] != '\n') + s[_len++] = '\n'; + } + if (len) + s[_len < len ? _len : len - 1] = '\0'; + *next = seq; + return _len; +} +#else +#define verbosity_ring_put(line) ((void)0) +#endif + void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap) { #if defined(_XBOX1) || defined(__WINRT__) @@ -421,6 +515,8 @@ void RARCH_LOG_V(const char *tag, const char *fmt, va_list ap) const char *out = rarch_log_line_format(line, sizeof(line), &heap, tag_v, fmt, ap); + verbosity_ring_put(out); + #ifdef HAVE_COMPANION_WIMP /* Mirror the line into the desktop companion's log view, when * one is open. The companion now shows the tag too, and wide diff --git a/verbosity.h b/verbosity.h index ea6dbdc70f..50ee9d7a7c 100644 --- a/verbosity.h +++ b/verbosity.h @@ -57,6 +57,18 @@ void retro_main_log_file_init(const char *path, bool append); bool is_logging_to_file(void); +#ifdef HAVE_MCP +/* The last lines logged, kept for GET_LOG once armed: lines are + * numbered from 0 as they are logged, and @since is the first wanted. + * Writes what fits of them to @s, one per line, and returns its + * length; *@next is the number of the line after the last written, + * and *@first that of the first, later than @since when older lines + * were overwritten. */ +void verbosity_ring_arm(void); +size_t verbosity_ring_read(size_t since, char *s, size_t len, + size_t *first, size_t *next); +#endif + #if defined(HAVE_LOGGER) void logger_init (void);