SCP: Add debug duplicate line output summary support

This commit is contained in:
Mark Pizzolato 2018-07-27 13:56:18 -07:00
parent 9cc726790e
commit 7a08f2368e
3 changed files with 163 additions and 50 deletions

162
scp.c
View file

@ -519,7 +519,8 @@ t_stat do_cmd_label (int32 flag, CONST char *cptr, CONST char *label);
void int_handler (int signal);
t_stat set_prompt (int32 flag, CONST char *cptr);
t_stat sim_set_asynch (int32 flag, CONST char *cptr);
static const char *get_dbg_verb (uint32 dbits, DEVICE* dptr, UNIT *uptr);
static const char *_get_dbg_verb (uint32 dbits, DEVICE* dptr, UNIT *uptr);
static t_stat _sim_debug_flush (void);
/* Global data */
@ -1210,6 +1211,9 @@ static const char simh_help[] =
"5-D\n"
" The -D switch causes data blob output to also display the data as\n"
" RADIX-50 characters.\n"
"5-F\n"
" The -F switch causes duplicate successive lines of debug to be\n"
" summarized to reduce noise from the debug data stream.\n"
"5-E\n"
" The -E switch causes data blob output to also display the data as\n"
" EBCDIC characters.\n"
@ -7884,7 +7888,7 @@ signal (SIGTERM, SIG_DFL); /* cancel WRU */
if (sim_log) /* flush console log */
fflush (sim_log);
if (sim_deb) /* flush debug log */
sim_debug_flush ();
_sim_debug_flush ();
for (i = 1; (dptr = sim_devices[i]) != NULL; i++) { /* flush attached files */
for (j = 0; j < dptr->numunits; j++) { /* if not buffered in mem */
uptr = dptr->units + j;
@ -11826,7 +11830,7 @@ if (exp->buf_size) {
free (bstr);
}
if (exp->dptr && (exp->dbit & exp->dptr->dctrl))
fprintf (st, " Expect Debugging via: SET %s DEBUG%s%s\n", sim_dname(exp->dptr), exp->dptr->debflags ? "=" : "", exp->dptr->debflags ? get_dbg_verb (exp->dbit, exp->dptr, NULL) : "");
fprintf (st, " Expect Debugging via: SET %s DEBUG%s%s\n", sim_dname(exp->dptr), exp->dptr->debflags ? "=" : "", exp->dptr->debflags ? _get_dbg_verb (exp->dbit, exp->dptr, NULL) : "");
fprintf (st, " Match Rules:\n");
if (!*match)
return sim_exp_showall (st, exp);
@ -12091,7 +12095,7 @@ if (after)
if (delay)
fprintf (st, " Default delay between character input is %u instructions\n", after);
if (snd->dptr && (snd->dbit & snd->dptr->dctrl))
fprintf (st, " Send Debugging via: SET %s DEBUG%s%s\n", sim_dname(snd->dptr), snd->dptr->debflags ? "=" : "", snd->dptr->debflags ? get_dbg_verb (snd->dbit, snd->dptr, NULL) : "");
fprintf (st, " Send Debugging via: SET %s DEBUG%s%s\n", sim_dname(snd->dptr), snd->dptr->debflags ? "=" : "", snd->dptr->debflags ? _get_dbg_verb (snd->dbit, snd->dptr, NULL) : "");
return SCPE_OK;
}
@ -12165,10 +12169,133 @@ return SCPE_OK;
const char *debug_bstates = "01_^";
AIO_TLS char debug_line_prefix[256];
int32 debug_unterm = 0;
char *debug_line_buf_last = NULL;
size_t debug_line_buf_last_endprefix_offset = 0;
AIO_TLS char debug_line_last_prefix[256];
char *debug_line_buf = NULL;
size_t debug_line_bufsize = 0;
size_t debug_line_offset = 0;
size_t debug_line_count = 0;
/*
* Optionally filter debug output to summarize duplicate debug lines
*/
static void _sim_debug_write_flush (const char *buf, size_t len, t_bool flush)
{
char *eol;
if (!(sim_deb_switches & SWMASK ('F'))) { /* filtering disabled? */
if (len > 0)
fwrite (buf, 1, len, sim_deb); /* output now. */
return; /* done */
}
if (debug_line_offset + len + 1 > debug_line_bufsize) {
debug_line_bufsize += MAX(1024, debug_line_offset + len + 1);
debug_line_buf = (char *)realloc (debug_line_buf, debug_line_bufsize);
debug_line_buf_last = (char *)realloc (debug_line_buf_last, debug_line_bufsize);
}
memcpy (&debug_line_buf[debug_line_offset], buf, len);
debug_line_buf[debug_line_offset + len] = '\0';
debug_line_offset += len;
while ((eol = strchr (debug_line_buf, '\n')) || flush) {
char *endprefix = strstr (debug_line_buf, ")> ");
size_t linesize = (eol - debug_line_buf) + 1;
if ((0 != memcmp ("DBG(", debug_line_buf, 4)) || (endprefix == NULL)) {
if (debug_line_count > 0)
fwrite (debug_line_buf_last, 1, strlen (debug_line_buf_last), sim_deb);
if (debug_line_count > 1) {
char countstr[32];
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);
fwrite (countstr, 1, strlen (countstr), sim_deb);
}
if (flush) {
linesize = debug_line_offset;
flush = FALSE; /* already flushed */
}
if (linesize)
fwrite (debug_line_buf, 1, linesize, sim_deb);
debug_line_count = 0;
}
else {
if (debug_line_count == 0) {
debug_line_buf_last_endprefix_offset = endprefix - debug_line_buf;
memcpy (debug_line_buf_last, debug_line_buf, linesize);
debug_line_buf_last[linesize] = '\0';
debug_line_count = 1;
}
else {
if (0 == memcmp (&debug_line_buf[endprefix - debug_line_buf],
&debug_line_buf_last[debug_line_buf_last_endprefix_offset],
(eol - endprefix)+ 1)) {
++debug_line_count;
memcpy (debug_line_last_prefix, debug_line_buf, (endprefix - debug_line_buf) + 3);
debug_line_last_prefix[(endprefix - debug_line_buf) + 3] = '\0';
}
else {
fwrite (debug_line_buf_last, 1, strlen (debug_line_buf_last), sim_deb);
if (debug_line_count > 1) {
char countstr[32];
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);
fwrite (countstr, 1, strlen (countstr), sim_deb);
}
debug_line_buf_last_endprefix_offset = endprefix - debug_line_buf;
memcpy (debug_line_buf_last, debug_line_buf, linesize);
debug_line_buf_last[linesize] = '\0';
debug_line_count = 1;
}
}
}
debug_line_offset -= linesize;
if (debug_line_offset > 0)
memmove (debug_line_buf, eol + 1, debug_line_offset);
debug_line_buf[debug_line_offset] = '\0';
}
}
static void _sim_debug_write (const char *buf, size_t len)
{
_sim_debug_write_flush (buf, len, FALSE);
}
static t_stat _sim_debug_flush (void)
{
int32 saved_quiet = sim_quiet;
int32 saved_sim_switches = sim_switches;
int32 saved_deb_switches = sim_deb_switches;
struct timespec saved_deb_basetime = sim_deb_basetime;
char saved_debug_filename[CBUFSIZE];
if (sim_deb == NULL) /* no debug? */
return SCPE_OK;
_sim_debug_write_flush ("", 0, TRUE);
if (sim_deb == sim_log) { /* debug is log */
fflush (sim_deb); /* fflush is the best we can do */
return SCPE_OK;
}
strcpy (saved_debug_filename, sim_logfile_name (sim_deb, sim_deb_ref));
sim_quiet = 1;
sim_set_deboff (0, NULL);
sim_switches = saved_deb_switches;
sim_set_debon (0, saved_debug_filename);
sim_deb_basetime = saved_deb_basetime;
sim_switches = saved_sim_switches;
sim_quiet = saved_quiet;
return SCPE_OK;
}
/* Finds debug phrase matching bitmask from from device DEBTAB table */
static const char *get_dbg_verb (uint32 dbits, DEVICE* dptr, UNIT *uptr)
static const char *_get_dbg_verb (uint32 dbits, DEVICE* dptr, UNIT *uptr)
{
static const char *debtab_none = "DEBTAB_ISNULL";
static const char *debtab_nomatch = "DEBTAB_NOMATCH";
@ -12196,7 +12323,7 @@ return some_match ? some_match : debtab_nomatch;
static const char *sim_debug_prefix (uint32 dbits, DEVICE* dptr, UNIT* uptr)
{
const char* debug_type = get_dbg_verb (dbits, dptr, uptr);
const char* debug_type = _get_dbg_verb (dbits, dptr, uptr);
char tim_t[32] = "";
char tim_a[32] = "";
char pc_s[64] = "";
@ -12357,7 +12484,7 @@ else
if ((!sim_oline) && (sim_log && (sim_log != stdout)))
fprintf (sim_log, "%s", buf);
if (sim_deb && (sim_deb != stdout) && (sim_deb != sim_log))
fwrite (buf, 1, strlen (buf), sim_deb);
_sim_debug_write (buf, strlen (buf));
if (buf != stackbuf)
free (buf);
@ -12508,9 +12635,9 @@ if (sim_deb && dptr && ((dptr->dctrl | (uptr ? uptr->dctrl : 0)) & dbits)) {
if (i >= j) {
if ((i != j) || (i == 0)) {
if (!debug_unterm) /* print prefix when required */
fwrite (debug_prefix, 1, strlen (debug_prefix), sim_deb);
fwrite (&buf[j], 1, i-j, sim_deb);
fwrite ("\r\n", 1, 2, sim_deb);
_sim_debug_write (debug_prefix, strlen (debug_prefix));
_sim_debug_write (&buf[j], i-j);
_sim_debug_write ("\r\n", 2);
}
debug_unterm = 0;
}
@ -12519,8 +12646,8 @@ if (sim_deb && dptr && ((dptr->dctrl | (uptr ? uptr->dctrl : 0)) & dbits)) {
}
if (i > j) {
if (!debug_unterm) /* print prefix when required */
fwrite (debug_prefix, 1, strlen (debug_prefix), sim_deb);
fwrite (&buf[j], 1, i-j, sim_deb);
_sim_debug_write (debug_prefix, strlen (debug_prefix));
_sim_debug_write (&buf[j], i-j);
}
/* Set unterminated flag for next time */
@ -12662,7 +12789,7 @@ int Fprintf (FILE *f, const char* fmt, ...)
int ret = 0;
va_list args;
if (sim_mfile) {
if (sim_mfile || (f == sim_deb)) {
char stackbuf[STACKBUFSIZE];
int32 bufsize = sizeof(stackbuf);
char *buf = stackbuf;
@ -12680,7 +12807,9 @@ if (sim_mfile) {
#endif /* NO_vsnprintf */
va_end (arglist);
/* If the formatted result didn't fit into the buffer, then grow the buffer and try again */
/* If the formatted result didn't fit into the buffer,
* then grow the buffer and try again
*/
if ((len < 0) || (len >= bufsize-1)) {
if (buf != stackbuf)
@ -12699,12 +12828,17 @@ if (sim_mfile) {
/* Store the formatted data */
if (f == sim_deb) {
_sim_debug_write (buf, len);
}
else {
if (sim_mfile->pos + len > sim_mfile->size) {
sim_mfile->size = sim_mfile->pos + 2 * MAX(bufsize, 512);
sim_mfile->buf = (char *)realloc (sim_mfile->buf, sim_mfile->size);
}
memcpy (sim_mfile->buf + sim_mfile->pos, buf, len);
sim_mfile->pos += len;
}
if (buf != stackbuf)
free (buf);

View file

@ -2259,6 +2259,10 @@ if (!sim_quiet) {
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" : "");
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" : "");
if (sim_deb_switches & SWMASK ('F'))
sim_printf (" Debug messages will be filtered to summarize duplicate lines\n");
if (sim_deb_switches & SWMASK ('E'))
sim_printf (" Debug messages containing blob data in EBCDIC will display in readable form\n");
time(&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);
@ -2269,34 +2273,6 @@ if (sim_deb_switches & SWMASK ('N'))
return SCPE_OK;
}
t_stat sim_debug_flush (void)
{
int32 saved_quiet = sim_quiet;
int32 saved_sim_switches = sim_switches;
int32 saved_deb_switches = sim_deb_switches;
struct timespec saved_deb_basetime = sim_deb_basetime;
char saved_debug_filename[CBUFSIZE];
if (sim_deb == NULL) /* no debug? */
return SCPE_OK;
if (sim_deb == sim_log) { /* debug is log */
fflush (sim_deb); /* fflush is the best we can do */
return SCPE_OK;
}
strcpy (saved_debug_filename, sim_logfile_name (sim_deb, sim_deb_ref));
sim_quiet = 1;
sim_set_deboff (0, NULL);
sim_switches = saved_deb_switches;
sim_set_debon (0, saved_debug_filename);
sim_deb_basetime = saved_deb_basetime;
sim_switches = saved_sim_switches;
sim_quiet = saved_quiet;
return SCPE_OK;
}
/* Set nodebug routine */
t_stat sim_set_deboff (int32 flag, CONST char *cptr)
@ -2330,6 +2306,10 @@ if (sim_deb) {
fprintf (st, " 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'))
fprintf (st, " 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'))
fprintf (st, " Debug messages will be filtered to summarize duplicate lines\n");
if (sim_deb_switches & SWMASK ('E'))
fprintf (st, " Debug messages containing blob data in EBCDIC will display in readable form\n");
for (i = 0; (dptr = sim_devices[i]) != NULL; i++) {
t_bool unit_debug = FALSE;
uint32 unit;

View file

@ -90,7 +90,6 @@ t_stat sim_set_cons_nolog (int32 flg, CONST char *cptr);
t_stat sim_set_deboff (int32 flag, CONST char *cptr);
t_stat sim_set_cons_expect (int32 flg, CONST char *cptr);
t_stat sim_set_cons_noexpect (int32 flg, CONST char *cptr);
t_stat sim_debug_flush (void);
t_stat sim_set_pchar (int32 flag, CONST char *cptr);
t_stat sim_set_cons_speed (int32 flag, CONST char *cptr);
t_stat sim_show_console (FILE *st, DEVICE *dptr, UNIT *uptr, int32 flag, CONST char *cptr);