gbdb,video: improve logging

Add more runtime toggles and add the ability to log to a file for
faster runs and better searchability.

src/apps/gbdb.c

@@ -11,6 +11,9 @@
 #include <stdbool.h>
 #include <signal.h>
 #include <stdarg.h>
+#include <sys/stat.h>
+#include <fcntl.h>
+#include <unistd.h>
 
 #include "common/common.h"
 #include "gb_disas.h"
@@ -49,20 +52,37 @@ static volatile sig_atomic_t paused = 0;
 
 static struct {
 	bool quiet;
+	int log_fd;
 } config;
 
-static void gb_log(const char *fmt, ...)
+void gb_log(const char *fmt, ...)
 {
-	va_list args;
+	va_list args, args_copy;
+
 	va_start(args, fmt);
-
+	va_copy(args_copy, args);
-	if (config.quiet) {
+	if (!config.quiet) {
-		return;
+		vprintf(fmt, args);
 	}
-
-	vprintf(fmt, args);
-
 	va_end(args);
+
+	if (config.log_fd != -1) {
+		vdprintf(config.log_fd, fmt, args_copy);
+	}
+}
+
+void gb_error(const char *fmt, ...)
+{
+	va_list args, args_copy;
+
+	va_start(args, fmt);
+	va_copy(args_copy, args);
+	vprintf(fmt, args);
+	va_end(args);
+
+	if (config.log_fd != -1) {
+		vdprintf(config.log_fd, fmt, args_copy);
+	}
 }
 
 
@@ -90,6 +110,8 @@ static void init(void)
 	lr35902_init(&cpu, memory, &cpu_ops);
 	gb_video_init(&video, memory);
 	gb_mem_init(memory, &video);
+
+	config.log_fd = -1;
 }
 
 static void cycle()
@@ -106,18 +128,120 @@ static void show_prompt()
 	fflush(stdout);
 }
 
+static void call_next_cmd(char *arg_list,
+						   struct tri *commands,
+						   const char *cmdname)
+{
+	char * remainder;
+	gbdb_cmd *cmd;
+	bool ambiguous = false;
+	remainder = strchr(arg_list, ' ');
+	if (remainder != NULL) {
+		remainder[0] = '\0';
+		remainder++;
+	}
+
+	cmd = tri_get_string_autocomplete(commands, arg_list, &ambiguous);
+
+	if (ambiguous) {
+		gb_error("ambiguous %s command: '%s'\n", cmdname, arg_list);
+		return;
+	}
+
+	if (cmd == NULL) {
+		gb_error("unrecognized %s command: '%s'\n", cmdname, arg_list);
+		return;
+	}
+
+	cmd(remainder);
+}
+
+static void set_logfile(char *arglist)
+{
+	char *token = token = strtok(arglist, " ");
+	int fd;
+
+	if (token != NULL) {
+		strip_newline(token);
+	}
+
+	if (token == NULL || strcmp(token, "") == 0) {
+		if (config.log_fd != -1) {
+			close(config.log_fd);
+		}
+		config.log_fd = -1;
+		return;
+	}
+
+	fd = open(token,
+			  O_WRONLY | O_TRUNC | O_CREAT,
+			  S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
+	if (fd < 0) {
+		gb_error("Failed to open logfile %s, %s\n", token, strerror(errno));
+		return;
+	}
+
+	if (config.log_fd != -1) {
+		close(config.log_fd);
+	}
+
+	config.log_fd = fd;
+}
+
+static void set_quiet_on(char *arg_list)
+{
+	config.quiet = true;
+}
+
+static void set_quiet_off(char *arg_list)
+{
+	config.quiet = false;
+}
+
+static void set_quiet(char *arg_list)
+{
+	static bool init = false;
+	static struct tri commands;
+
+	if (!init) {
+		tri_init(&commands);
+		tri_add_string(&commands, "on", set_quiet_on);
+		tri_add_string(&commands, "true", set_quiet_on);
+		tri_add_string(&commands, "off",  set_quiet_off);
+		tri_add_string(&commands, "false",  set_quiet_off);
+		init = true;
+	}
+
+	call_next_cmd(arg_list, &commands, "set quiet");
+}
+
+static void set_video_debug(char *arg_list)
+{
+	video.debug_logging = true;
+}
+
 static void set(char *arg_list)
 {
-	/* TODO make this support other options */
+	static bool init = false;
-	config.quiet = true;
+	static struct tri commands;
+
+	if (!init) {
+		tri_init(&commands);
+		tri_add_string(&commands, "quiet", set_quiet);
+		tri_add_string(&commands, "logfile",  set_logfile);
+		tri_add_string(&commands, "video_debug",  set_video_debug);
+		init = true;
+	}
+
+	call_next_cmd(arg_list, &commands, "set");
 }
 
 static void echo(char *arg_list)
 {
 	if (arg_list != NULL) {
-		printf("%s\n", arg_list);
+		gb_log("%s\n", arg_list);
 	} else {
-		printf("\n");
+		gb_log("\n");
 	}
 }
 
@@ -174,32 +298,39 @@ static void regs(char *arg_list)
 	uint8_t f = (cpu.nf << CPU_F_BIT_POS_N) | (cpu.zf << CPU_F_BIT_POS_Z) |
 		(cpu.cf << CPU_F_BIT_POS_C) | (cpu.hf << CPU_F_BIT_POS_H);
 
-	printf("AF: 0x%04x A: 0x%02x F: 0x%02x\n", (uint16_t) (cpu.a << 8) | f, cpu.a, f);
+	gb_log("AF: 0x%04x A: 0x%02x F: 0x%02x\n", (uint16_t) (cpu.a << 8) | f, cpu.a, f);
-	printf("BC: 0x%04x B: 0x%02x C: 0x%02x\n", cpu.bc, cpu.b, cpu.c);
+	gb_log("BC: 0x%04x B: 0x%02x C: 0x%02x\n", cpu.bc, cpu.b, cpu.c);
-	printf("DE: 0x%04x D: 0x%02x E: 0x%02x\n", cpu.de, cpu.d, cpu.e);
+	gb_log("DE: 0x%04x D: 0x%02x E: 0x%02x\n", cpu.de, cpu.d, cpu.e);
-	printf("HL: 0x%04x H: 0x%02x L: 0x%02x\n", cpu.hl, cpu.h, cpu.l);
+	gb_log("HL: 0x%04x H: 0x%02x L: 0x%02x\n", cpu.hl, cpu.h, cpu.l);
-	printf("PC: 0x%04x\n", cpu.pc);
+	gb_log("PC: 0x%04x\n", cpu.pc);
-	printf("SP: 0x%04x\n", cpu.sp);
+	gb_log("SP: 0x%04x\n", cpu.sp);
 }
 
 static void peek(char *arg_list)
 {
 	uint16_t pc = lr35902_get_reg_16(&cpu, LR35902_REG_PC);
 	uint8_t byte = gb_mem_read(memory, pc);
-	printf("0x%04x:%s\n", pc, gb_byte_to_opcode(byte));
+	gb_log("0x%04x:%s\n", pc, gb_byte_to_opcode(byte));
+}
+
+static void vstep(char *arg_list)
+{
+	peek(NULL);
+	step(arg_list);
+	regs(NULL);
 }
 
 static void stats(char *arg_list)
 {
-	printf("Cycles: %llu\n", cpu.metrics.cycles);
+	gb_log("Cycles: %" PRId64 "\n", cpu.metrics.cycles);
-	printf("Retired Insructions %llu\n", cpu.metrics.retired_instrs);
+	gb_log("Retired Insructions %" PRId64 "\n", cpu.metrics.retired_instrs);
-	printf("Memory Reads: %llu\n", cpu.metrics.mem_reads);
+	gb_log("Memory Reads: %" PRId64 " \n", cpu.metrics.mem_reads);
-	printf("Memory Writes:	%llu\n", cpu.metrics.mem_writes);
+	gb_log("Memory Writes: %" PRId64 "\n", cpu.metrics.mem_writes);
 }
 
 static void help(char *arg_list)
 {
-	printf(usage);
+	gb_log(usage);
 }
 
 static int64_t parse_reg_str(const char *str)
@@ -253,20 +384,20 @@ static void assert(char *arg_list)
 
 	val0_str = strtok(arg_list, " ");
 	if (val0_str == NULL) {
-		printf("%s", usage);
+		gb_error("%s", usage);
 		return;
 	}
 	val0 = parse_val(val0_str);
 
 	operator_str = strtok(NULL, " ");
 	if (operator_str == NULL) {
-		printf("%s", usage);
+		gb_error("%s", usage);
 		return;
 	}
 
 	val1_str = strtok(NULL, " ");
 	if (val1_str == NULL) {
-		printf("%s", usage);
+		gb_error("%s", usage);
 		return;
 	}
 	val1 = parse_val(val1_str);
@@ -296,13 +427,13 @@ static void assert(char *arg_list)
 			goto fail;
 		}
 	} else {
-		printf("%s", usage);
+		gb_error("%s", usage);
 	}
 
 	return;
 fail:
-	printf("ASSERT: %s %s %s\n", val0_str, operator_str, val1_str);
+	gb_error("ASSERT: %s %s %s\n", val0_str, operator_str, val1_str);
-	printf("%s=%lld, %s=%lld\n", val0_str, val0, val1_str, val1);
+	gb_error("%s=%" PRId64 ", %s=%" PRId64 "\n", val0_str, val0, val1_str, val1);
 	regs(NULL);
 	stats(NULL);
 	exit(1);
@@ -314,7 +445,7 @@ static void mem(char *arg_list)
 	char *token = strtok(arg_list, " ");
 
 	if (token == NULL) {
-		printf("usage: mem <addr> (num bytes) (format)\n");
+		gb_error("usage: mem <addr> (num bytes) (format)\n");
 		return;
 	}
 
@@ -333,11 +464,11 @@ static void mem(char *arg_list)
 		uint8_t val = gb_mem_read(memory, addr + i);
 
 		if (token != NULL && token[0] == 'i') {
-			printf("0x%04x:%s\n", addr + i, gb_byte_to_opcode(val));
+			gb_log("0x%04x:%s\n", addr + i, gb_byte_to_opcode(val));
 		} else if (token != NULL && token[0] == 'b') {
-			printf("0x%04x:0x%02x %s\n", addr + i, val, gb_byte_to_opcode(val));
+			gb_log("0x%04x:0x%02x %s\n", addr + i, val, gb_byte_to_opcode(val));
 		} else {
-			printf("0x%04x:0x%02x\n", addr + i, val);
+			gb_log("0x%04x:0x%02x\n", addr + i, val);
 		}
 	}
 
@@ -347,7 +478,7 @@ static void load(char *arg_list)
 {
 	char *token = strtok(arg_list, " ");
 	if (token == NULL) {
-		printf("usage: load <file>\n");
+		gb_error("usage: load <file>\n");
 		return;
 	}
 
@@ -360,7 +491,7 @@ static void load_bootrom(char *arg_list)
 {
 	char *token = strtok(arg_list, " ");
 	if (token == NULL) {
-		printf("usage: bootrom <file>\n");
+		gb_error("usage: bootrom <file>\n");
 		return;
 	}
 
@@ -446,7 +577,7 @@ static int do_set_breakpoint(uint16_t addr, bool temp)
 		gb_mem_force_write(memory, addr, 0xd3);
 		num_breakpoints++;
 	} else {
-		printf("maximum number of breakpoints reached\n");
+		gb_error("maximum number of breakpoints reached\n");
 	}
 }
 
@@ -456,7 +587,7 @@ static void set_breakpoint(char *arg_string)
 	char *token = strtok(arg_string, " ");
 
 	if (token == NULL) {
-		printf("usage: breakpoint add <addr>\n");
+		gb_error("usage: breakpoint add <addr>\n");
 		return;
 	}
 
@@ -470,14 +601,14 @@ static void runto(char *arg_string)
 	char *token = strtok(arg_string, " ");
 
 	if (token == NULL) {
-		printf("usage: runto <addr>\n");
+		gb_error("usage: runto <addr>\n");
 		return;
 	}
 
 	addr = parse_val(token);
 	rc = do_set_breakpoint(addr, true);
 	if (rc < 0) {
-		printf("failed to set breakpoint\n");
+		gb_error("failed to set breakpoint\n");
 		return;
 	}
 
@@ -517,7 +648,7 @@ static void breakpoint_addr_hit(uint16_t addr)
 
 
 	if (bkpt == NULL) {
-		printf("No breakpoint found at addr=%d\n", addr);
+		gb_error("No breakpoint found at addr=%d\n", addr);
 		return;
 	}
 
@@ -532,7 +663,7 @@ static void delete_breakpoint(char *arg_string)
 	int rc, bkpt;
 
 	if (token == NULL) {
-		printf("usage: breakpoint rm <bkpt num>\n");
+		gb_error("usage: breakpoint rm <bkpt num>\n");
 		return;
 	}
 
@@ -540,7 +671,7 @@ static void delete_breakpoint(char *arg_string)
 
 	rc = do_delete_breakpoint(bkpt);
 	if (rc < 0) {
-		printf("%d is not a valid breakpoint number\n", bkpt);
+		gb_error("%d is not a valid breakpoint number\n", bkpt);
 	}
 }
 
@@ -550,10 +681,10 @@ static void display_breakpoints(char *arg_string)
 
 	if (num_breakpoints) {
 		for (i = 0; i < num_breakpoints; i++) {
-			printf("#%d: 0x%04x\n", breakpoints[i].id, breakpoints[i].addr);
+			gb_log("#%d: 0x%04x\n", breakpoints[i].id, breakpoints[i].addr);
 		}
 	} else {
-		printf("No breakpoints set\n");
+		gb_log("No breakpoints set\n");
 	}
 }
 
@@ -575,28 +706,7 @@ static void breakpoint(char *arg_list)
 		init = true;
 	}
 
-	char * remainder;
+	call_next_cmd(arg_list, &commands, "breakpoint");
-	gbdb_cmd *cmd;
-	bool ambiguous = false;
-	remainder = strchr(arg_list, ' ');
-	if (remainder != NULL) {
-		remainder[0] = '\0';
-		remainder++;
-	}
-
-	cmd = tri_get_string_autocomplete(&commands, arg_list, &ambiguous);
-
-	if (ambiguous) {
-		printf("ambiguous breakpoint command: '%s'\n", arg_list);
-		return;
-	}
-
-	if (cmd == NULL) {
-		printf("unrecognized breakpoint command: '%s'\n", arg_list);
-		return;
-	}
-
-	cmd(remainder);
 }
 
 static bool breakpoint_is_at_addr(uint16_t addr) {
@@ -657,13 +767,14 @@ static void process_cmd(const char *cmd_str, struct tri *commands)
 			return;
 		}
 
+
 		cmd = tri_get_string_autocomplete(commands, cmd_buffer, &ambiguous);
 
 		if (ambiguous) {
-			printf("ambiguous command: '%s'\n", cmd_buffer);
+			gb_error("ambiguous command: '%s'\n", cmd_buffer);
 			break;
 		} else if (cmd == NULL) {
-			printf("unrecognized command: '%s'\n", cmd_buffer);
+			gb_error("unrecognized command: '%s'\n", cmd_buffer);
 			break;
 		} else {
 			cmd(arg_str);
@@ -708,6 +819,7 @@ int main(int argc, char **argv)
 
 	tri_init(&commands);
 	tri_add_string(&commands, "step", step);
+	tri_add_string(&commands, "vstep", vstep);
 	tri_add_string(&commands, "run", run);
 	tri_add_string(&commands, "regs", regs);
 	tri_add_string(&commands, "stats", stats);
@@ -732,7 +844,7 @@ int main(int argc, char **argv)
 
 	if (argc > 1) {
 		if (load_initfile(argv[1], &commands)) {
-			printf("Failed to load initfile\n");
+			gb_error("Failed to load initfile\n");
 		}
 	}
 
@@ -758,5 +870,9 @@ int main(int argc, char **argv)
 		process_cmd(cmd_str, &commands);
 	}
 
+	if (config.log_fd != -1) {
+		close(config.log_fd);
+	}
+
 	return 0;
 }

src/common/common.h

@@ -3,6 +3,7 @@
 
 #include <stdlib.h>
 #include <stdio.h>
+#include <stdarg.h>
 
 #define MIN(a,b) ((a) > (b) ? (b) : (a))
 #define MAX(a,b) ((a) < (b) ? (b) : (a))
@@ -43,12 +44,12 @@ void downcase(char *str);
 #define DEBUG_LOG(...)	  \
 	do { \
 		if (DEBUG_ON) { \
-			printf("DEBUG: %s:%d <%s> : ", \
+			gb_log("DEBUG: %s:%d <%s> : ",		\
-			       __FILE__, __LINE__, \
+				   __FILE__, __LINE__,			\
-			       __func__); \
+				   __func__);					\
-			printf(__VA_ARGS__); \
+			printf(__VA_ARGS__);				\
-			printf("\n"); \
+			printf("\n");						\
-		} \
+		}										\
 	} while (0)
 
 #endif

src/gbemu/memory.c

@@ -54,7 +54,6 @@ void gb_mem_write(struct gb_memory *cpu, uint16_t addr, uint8_t val)
 		break;
 	case 0x8000 ... 0x87FF:
 	case 0x9800 ... 0x9BFF:
-		printf("Wrote [0x%x]=%x\n", addr, val);
 		ram[addr] = val;
 		break;
 	case 0 ... 0x100:

src/gbemu/video.c

@@ -1,5 +1,6 @@
 #include "gbemu/video.h"
 #include "gbemu/memory.h"
+#include "common/common.h"
 #include "common/bmp.h"
 
 #include <string.h>
@@ -30,6 +31,8 @@ static uint8_t color_tbl[4] = {
 void gb_video_init(struct gb_video *video, struct gb_memory *memory)
 {
 	memset(video, 0, sizeof(*video));
+
+	video->debug_logging = 0;
 	video->memory = memory;
 
 	bmp = bmp_new(BMP_GRAYSCALE, BUFFER_WIDTH, BUFFER_HEIGHT);
@@ -47,14 +50,9 @@ static void gb_video_fetch_tile_data(struct gb_video *video, uint8_t *databuf,
 		uint16_t addr = tile_addr + (index * TILE_BYTES) + i;
 		databuf[i] = gb_mem_read(video->memory, addr);
 		if (log && databuf[i] != 0) {
-			printf("addr=%x, databuf[%d]=%x\n", addr, i, databuf[i]);
 			logged = 1;
 		}
 	}
-
-	if (log && logged) {
-		printf("\n");
-	}
 }
 
 static void gb_video_screenshot(struct gb_video *video)
@@ -69,7 +67,6 @@ static void gb_video_screenshot(struct gb_video *video)
 	int log = id == 30;
 
 	snprintf(filename, sizeof(filename), "screenshot-%d.bmp", id++);
-	printf("Rendering screenshot %s\n", filename);
 
 	if (!(video->lcdcont & 1)) {
 		goto out;
@@ -84,11 +81,6 @@ static void gb_video_screenshot(struct gb_video *video)
 			tile = gb_mem_read(video->memory, addr);
 			gb_video_fetch_tile_data(video, tile_data, tile, log);
 
-			if (log) {
-				printf("Tile_x=%d, tile_y=%d, addr=%x, tile=%d\n",
-					   tile_x, tile_y, addr, tile);
-			}
-
 			for (i = 0 ; i < TILE_WIDTH * TILE_HEIGHT; i++) {
 				int offset_x = i % TILE_WIDTH;
 				int offset_y = i / TILE_WIDTH;
@@ -103,11 +95,6 @@ static void gb_video_screenshot(struct gb_video *video)
 				total_x = tile_x * TILE_WIDTH + (7 - offset_x);
 				total_y = tile_y * TILE_HEIGHT + offset_y;
 
-				if (log && color != 0) {
-					printf("offset=%d, total_x=%d, total_y=%d, td_index=%d, color=%d\n",
-						   total_y * BUFFER_WIDTH + total_x, total_x, total_y, td_index, color);
-				}
-
 				buffer[(BUFFER_HEIGHT - total_y) * BUFFER_WIDTH + total_x] = color_tbl[color];
 			}
 		}
@@ -134,31 +121,52 @@ void gb_video_cycle(struct gb_video *video, int cycles)
 
 uint8_t gb_video_mem_read(struct gb_video *video, uint16_t addr)
 {
+	uint8_t val;
+
 	switch (addr) {
 	case 0xFF40:
-		return video->lcdcont;
+		val = video->lcdcont;
+		break;
 	case 0xFF41:
-		return video->lcdstat;
+		val = video->lcdstat;
+		break;
 	case 0xFF42:
-		return video->scrolly;
+		val = video->scrolly;
+		break;
 	case 0xFF43:
-		return video->scrollx;
+		val = video->scrollx;
+		break;
 	case 0xFF44:
-		return video->curline;
+		val = video->curline;
+		break;
 	case 0xFF45:
-		return video->cmpline;
+		val = video->cmpline;
+		break;
 	case 0xFF4A:
-		return video->wndposy;
+		val = video->wndposy;
+		break;
 	case 0xFF4B:
-		return video->wndposx;
+		val = video->wndposx;
+		break;
 	default:
-		return 0;
+		val = 0;
 	}
+
+	if (video->debug_logging) {
+		gb_log("Read Video[%x]=0x%x\n", addr, val);
+	}
+
+	return val;
 }
 
 void gb_video_mem_write(struct gb_video *video, uint16_t addr, uint8_t val)
 {
 	uint8_t *write_addr;
+
+	if (video->debug_logging) {
+		gb_log("Video[%x]=%x\n", addr, val);
+	}
+
 	switch (addr) {
 	case 0xFF40:
 		write_addr = &video->lcdcont;

src/gbemu/video.h

@@ -92,6 +92,7 @@ struct gb_video {
 	/******************************/
 
 	int line_counter;
+	int debug_logging;
 
 	struct gb_memory *memory;
 };