SCP: Add option to write debug output to an in memory circular buffer

This commit is contained in:
Mark Pizzolato 2018-10-08 17:50:00 -07:00
parent 948d8cc6e8
commit 6a3424df86
3 changed files with 119 additions and 33 deletions

56
scp.c
View file

@ -576,6 +576,10 @@ FILEREF *sim_log_ref = NULL; /* log file file referen
FILE *sim_deb = NULL; /* debug file */ FILE *sim_deb = NULL; /* debug file */
FILEREF *sim_deb_ref = NULL; /* debug file file reference */ FILEREF *sim_deb_ref = NULL; /* debug file file reference */
int32 sim_deb_switches = 0; /* debug switches */ int32 sim_deb_switches = 0; /* debug switches */
size_t sim_deb_buffer_size = 0; /* debug memory buffer size */
char *sim_deb_buffer = NULL; /* debug memory buffer */
size_t sim_debug_buffer_offset = 0; /* debug memory buffer insertion offset */
size_t sim_debug_buffer_inuse = 0; /* debug memory buffer inuse count */
struct timespec sim_deb_basetime; /* debug timestamp relative base time */ struct timespec sim_deb_basetime; /* debug timestamp relative base time */
char *sim_prompt = NULL; /* prompt string */ char *sim_prompt = NULL; /* prompt string */
static FILE *sim_gotofile; /* the currently open do file */ static FILE *sim_gotofile; /* the currently open do file */
@ -1224,6 +1228,13 @@ static const char simh_help[] =
"5-E\n" "5-E\n"
" The -E switch causes data blob output to also display the data as\n" " The -E switch causes data blob output to also display the data as\n"
" EBCDIC characters.\n" " EBCDIC characters.\n"
"5-B\n"
" The -B switch causes debug data output to be written to a circular\n"
" buffer in memory. This avoids the potential delays for disk I/O to\n"
" and the disk storage that a long running debug might consume.\n"
" The size of the circular memory buffer that is used is specified on\n"
" the SET DEBUG command line, for example:\n\n"
"++SET DEBUG -B <sizeinMB> <debug-destination>\n\n"
#define HLP_SET_BREAK "*Commands SET Breakpoints" #define HLP_SET_BREAK "*Commands SET Breakpoints"
"3Breakpoints\n" "3Breakpoints\n"
"+SET BREAK <list> set breakpoints\n" "+SET BREAK <list> set breakpoints\n"
@ -12181,6 +12192,33 @@ size_t debug_line_bufsize = 0;
size_t debug_line_offset = 0; size_t debug_line_offset = 0;
size_t debug_line_count = 0; size_t debug_line_count = 0;
static void _debug_fwrite (const char *buf, size_t len)
{
size_t move_size;
if (sim_deb_buffer == NULL) {
fwrite (buf, 1, len, sim_deb); /* output now. */
return;
}
if ((sim_deb == stdout) && (!sim_is_running))
fwrite (buf, 1, len, stdout); /* output now. */
while (len > 0) {
if (sim_debug_buffer_offset + len <= sim_deb_buffer_size)
move_size = len;
else
move_size = sim_deb_buffer_size - sim_debug_buffer_offset;
memcpy (sim_deb_buffer + sim_debug_buffer_offset, buf, move_size);
sim_debug_buffer_offset += move_size;
if (sim_debug_buffer_offset == sim_deb_buffer_size) {
sim_debug_buffer_offset = 0;
sim_debug_buffer_inuse = sim_deb_buffer_size;
}
if (sim_debug_buffer_inuse < sim_deb_buffer_size)
sim_debug_buffer_inuse += move_size;
len -= move_size;
}
}
/* /*
* Optionally filter debug output to summarize duplicate debug lines * Optionally filter debug output to summarize duplicate debug lines
*/ */
@ -12190,7 +12228,7 @@ char *eol;
if (sim_deb_switches & SWMASK ('F')) { /* filtering disabled? */ if (sim_deb_switches & SWMASK ('F')) { /* filtering disabled? */
if (len > 0) if (len > 0)
fwrite (buf, 1, len, sim_deb); /* output now. */ _debug_fwrite (buf, len); /* output now. */
return; /* done */ return; /* done */
} }
if (debug_line_offset + len + 1 > debug_line_bufsize) { if (debug_line_offset + len + 1 > debug_line_bufsize) {
@ -12207,20 +12245,20 @@ while ((eol = strchr (debug_line_buf, '\n')) || flush) {
if ((0 != memcmp ("DBG(", debug_line_buf, 4)) || (endprefix == NULL)) { if ((0 != memcmp ("DBG(", debug_line_buf, 4)) || (endprefix == NULL)) {
if (debug_line_count > 0) if (debug_line_count > 0)
fwrite (debug_line_buf_last, 1, strlen (debug_line_buf_last), sim_deb); _debug_fwrite (debug_line_buf_last, strlen (debug_line_buf_last));
if (debug_line_count > 1) { if (debug_line_count > 1) {
char countstr[32]; char countstr[32];
sprintf (countstr, "same as above (%d time%s)\r\n", (int)(debug_line_count - 1), ((debug_line_count - 1) != 1) ? "s" : ""); sprintf (countstr, "same as above (%d time%s)\r\n", (int)(debug_line_count - 1), ((debug_line_count - 1) != 1) ? "s" : "");
fwrite (debug_line_last_prefix, 1, strlen (debug_line_last_prefix), sim_deb); _debug_fwrite (debug_line_last_prefix, strlen (debug_line_last_prefix));
fwrite (countstr, 1, strlen (countstr), sim_deb); _debug_fwrite (countstr, strlen (countstr));
} }
if (flush) { if (flush) {
linesize = debug_line_offset; linesize = debug_line_offset;
flush = FALSE; /* already flushed */ flush = FALSE; /* already flushed */
} }
if (linesize) if (linesize)
fwrite (debug_line_buf, 1, linesize, sim_deb); _debug_fwrite (debug_line_buf, linesize);
debug_line_count = 0; debug_line_count = 0;
} }
else { else {
@ -12239,13 +12277,13 @@ while ((eol = strchr (debug_line_buf, '\n')) || flush) {
debug_line_last_prefix[(endprefix - debug_line_buf) + 3] = '\0'; debug_line_last_prefix[(endprefix - debug_line_buf) + 3] = '\0';
} }
else { else {
fwrite (debug_line_buf_last, 1, strlen (debug_line_buf_last), sim_deb); _debug_fwrite (debug_line_buf_last, strlen (debug_line_buf_last));
if (debug_line_count > 1) { if (debug_line_count > 1) {
char countstr[32]; char countstr[32];
sprintf (countstr, "same as above (%d time%s)\r\n", (int)(debug_line_count - 1), ((debug_line_count - 1) != 1) ? "s" : ""); sprintf (countstr, "same as above (%d time%s)\r\n", (int)(debug_line_count - 1), ((debug_line_count - 1) != 1) ? "s" : "");
fwrite (debug_line_last_prefix, 1, strlen (debug_line_last_prefix), sim_deb); _debug_fwrite (debug_line_last_prefix, strlen (debug_line_last_prefix));
fwrite (countstr, 1, strlen (countstr), sim_deb); _debug_fwrite (countstr, strlen (countstr));
} }
debug_line_buf_last_endprefix_offset = endprefix - debug_line_buf; debug_line_buf_last_endprefix_offset = endprefix - debug_line_buf;
memcpy (debug_line_buf_last, debug_line_buf, linesize); memcpy (debug_line_buf_last, debug_line_buf, linesize);
@ -12284,6 +12322,7 @@ if (sim_deb == sim_log) { /* debug is log */
return SCPE_OK; return SCPE_OK;
} }
if (!(saved_deb_switches & SWMASK ('B'))) {
strcpy (saved_debug_filename, sim_logfile_name (sim_deb, sim_deb_ref)); strcpy (saved_debug_filename, sim_logfile_name (sim_deb, sim_deb_ref));
sim_quiet = 1; sim_quiet = 1;
@ -12293,6 +12332,7 @@ sim_set_debon (0, saved_debug_filename);
sim_deb_basetime = saved_deb_basetime; sim_deb_basetime = saved_deb_basetime;
sim_switches = saved_sim_switches; sim_switches = saved_sim_switches;
sim_quiet = saved_quiet; sim_quiet = saved_quiet;
}
return SCPE_OK; return SCPE_OK;
} }

4
scp.h
View file

@ -355,6 +355,10 @@ extern FILEREF *sim_log_ref; /* log file file referen
extern FILE *sim_deb; /* debug file */ extern FILE *sim_deb; /* debug file */
extern FILEREF *sim_deb_ref; /* debug file file reference */ extern FILEREF *sim_deb_ref; /* debug file file reference */
extern int32 sim_deb_switches; /* debug display flags */ extern int32 sim_deb_switches; /* debug display flags */
extern size_t sim_deb_buffer_size; /* debug memory buffer size */
extern char *sim_deb_buffer; /* debug memory buffer */
extern size_t sim_debug_buffer_offset; /* debug memory buffer insertion offset */
extern size_t sim_debug_buffer_inuse; /* debug memory buffer inuse count */
extern struct timespec sim_deb_basetime; /* debug base time for relative time output */ extern struct timespec sim_deb_basetime; /* debug base time for relative time output */
extern DEVICE **sim_internal_devices; extern DEVICE **sim_internal_devices;
extern uint32 sim_internal_device_count; extern uint32 sim_internal_device_count;

View file

@ -138,6 +138,10 @@
#define nice(n) ({}) #define nice(n) ({})
#endif #endif
#ifndef MIN
#define MIN(a,b) (((a) <= (b)) ? (a) : (b))
#endif
/* Forward Declaraations of Platform specific routines */ /* Forward Declaraations of Platform specific routines */
static t_stat sim_os_poll_kbd (void); static t_stat sim_os_poll_kbd (void);
@ -2222,9 +2226,16 @@ t_stat sim_set_debon (int32 flag, CONST char *cptr)
char gbuf[CBUFSIZE]; char gbuf[CBUFSIZE];
t_stat r; t_stat r;
time_t now; time_t now;
size_t buffer_size;
if ((cptr == NULL) || (*cptr == 0)) /* need arg */ if ((cptr == NULL) || (*cptr == 0)) /* need arg */
return SCPE_2FARG; return SCPE_2FARG;
if (sim_switches & SWMASK ('B')) {
cptr = get_glyph_nc (cptr, gbuf, 0); /* buffer size */
buffer_size = (size_t)strtoul (gbuf, NULL, 10);
if ((buffer_size == 0) || (buffer_size > 1024))
return sim_messagef (SCPE_ARG, "Invalid debug memory buffersize %u MB\n", (unsigned int)buffer_size);
}
cptr = get_glyph_nc (cptr, gbuf, 0); /* get file name */ cptr = get_glyph_nc (cptr, gbuf, 0); /* get file name */
if (*cptr != 0) /* now eol? */ if (*cptr != 0) /* now eol? */
return SCPE_2MARG; return SCPE_2MARG;
@ -2233,7 +2244,11 @@ r = sim_open_logfile (gbuf, FALSE, &sim_deb, &sim_deb_ref);
if (r != SCPE_OK) if (r != SCPE_OK)
return r; return r;
sim_deb_switches = sim_switches; /* save debug switches */ sim_deb_switches = sim_switches &
(SWMASK ('R') | SWMASK ('P') |
SWMASK ('T') | SWMASK ('A') |
SWMASK ('F') | SWMASK ('N') |
SWMASK ('B')); /* save debug switches */
if (sim_deb_switches & SWMASK ('R')) { if (sim_deb_switches & SWMASK ('R')) {
struct tm loc_tm, gmt_tm; struct tm loc_tm, gmt_tm;
time_t time_t_now; time_t time_t_now;
@ -2247,25 +2262,33 @@ if (sim_deb_switches & SWMASK ('R')) {
if (!(sim_deb_switches & (SWMASK ('A') | SWMASK ('T')))) if (!(sim_deb_switches & (SWMASK ('A') | SWMASK ('T'))))
sim_deb_switches |= SWMASK ('T'); sim_deb_switches |= SWMASK ('T');
} }
if (!sim_quiet) { sim_messagef (SCPE_OK, "Debug output to \"%s\"\n", sim_logfile_name (sim_deb, sim_deb_ref));
sim_printf ("Debug output to \"%s\"\n", sim_logfile_name (sim_deb, sim_deb_ref));
if (sim_deb_switches & SWMASK ('P')) if (sim_deb_switches & SWMASK ('P'))
sim_printf (" Debug messages contain current PC value\n"); sim_messagef (SCPE_OK, " Debug messages contain current PC value\n");
if (sim_deb_switches & SWMASK ('T')) if (sim_deb_switches & SWMASK ('T'))
sim_printf (" Debug messages display time of day as hh:mm:ss.msec%s\n", sim_deb_switches & SWMASK ('R') ? " relative to the start of debugging" : ""); sim_messagef (SCPE_OK, " Debug messages display time of day as hh:mm:ss.msec%s\n", sim_deb_switches & SWMASK ('R') ? " relative to the start of debugging" : "");
if (sim_deb_switches & SWMASK ('A')) if (sim_deb_switches & SWMASK ('A'))
sim_printf (" Debug messages display time of day as seconds.msec%s\n", sim_deb_switches & SWMASK ('R') ? " relative to the start of debugging" : ""); sim_messagef (SCPE_OK, " Debug messages display time of day as seconds.msec%s\n", sim_deb_switches & SWMASK ('R') ? " relative to the start of debugging" : "");
if (sim_deb_switches & SWMASK ('F')) if (sim_deb_switches & SWMASK ('F'))
sim_printf (" Debug messages will not be filtered to summarize duplicate lines\n"); sim_messagef (SCPE_OK, " Debug messages will not be filtered to summarize duplicate lines\n");
if (sim_deb_switches & SWMASK ('E')) if (sim_deb_switches & SWMASK ('E'))
sim_printf (" Debug messages containing blob data in EBCDIC will display in readable form\n"); sim_messagef (SCPE_OK, " Debug messages containing blob data in EBCDIC will display in readable form\n");
if (sim_deb_switches & SWMASK ('B'))
sim_messagef (SCPE_OK, " Debug messages will be written to a %u MB circular memory buffer\n",
(unsigned int)buffer_size);
time(&now); time(&now);
fprintf (sim_deb, "Debug output to \"%s\" at %s", sim_logfile_name (sim_deb, sim_deb_ref), ctime(&now)); fprintf (sim_deb, "Debug output to \"%s\" at %s", sim_logfile_name (sim_deb, sim_deb_ref), ctime(&now));
show_version (sim_deb, NULL, NULL, 0, NULL); show_version (sim_deb, NULL, NULL, 0, NULL);
}
if (sim_deb_switches & SWMASK ('N')) if (sim_deb_switches & SWMASK ('N'))
sim_deb_switches &= ~SWMASK ('N'); /* Only process the -N flag initially */ sim_deb_switches &= ~SWMASK ('N'); /* Only process the -N flag initially */
if (sim_deb_switches & SWMASK ('B')) {
sim_deb_buffer_size = (size_t)(1024 * 1024 * buffer_size);
sim_deb_buffer = realloc (sim_deb_buffer, sim_deb_buffer_size);
sim_debug_buffer_offset = sim_debug_buffer_inuse = 0;
memset (sim_deb_buffer, 0, sim_deb_buffer_size);
}
return SCPE_OK; return SCPE_OK;
} }
@ -2277,6 +2300,25 @@ if (cptr && (*cptr != 0)) /* now eol? */
return SCPE_2MARG; return SCPE_2MARG;
if (sim_deb == NULL) /* no debug? */ if (sim_deb == NULL) /* no debug? */
return SCPE_OK; return SCPE_OK;
if (sim_deb_switches & SWMASK ('B')) {
size_t offset = (sim_debug_buffer_inuse == sim_deb_buffer_size) ? sim_debug_buffer_offset : 0;
const char *bufmsg = "Circular Buffer Contents follow here:\n\n";
fwrite (bufmsg, 1, strlen (bufmsg), sim_deb);
while (sim_debug_buffer_inuse > 0) {
size_t write_size = MIN (sim_deb_buffer_size - offset, sim_debug_buffer_inuse);
fwrite (sim_deb_buffer + offset, 1, write_size, sim_deb);
sim_debug_buffer_inuse -= write_size;
offset += write_size;
if (offset == sim_deb_buffer_size)
offset = 0;
}
free (sim_deb_buffer);
sim_deb_buffer = NULL;
sim_deb_buffer_size = sim_debug_buffer_offset = sim_debug_buffer_inuse = 0;
}
sim_close_logfile (&sim_deb_ref); sim_close_logfile (&sim_deb_ref);
sim_deb = NULL; sim_deb = NULL;
sim_deb_switches = 0; sim_deb_switches = 0;