From 7a08f2368e1965d34d2fcc1e1d6d7fe42f2130fa Mon Sep 17 00:00:00 2001 From: Mark Pizzolato Date: Fri, 27 Jul 2018 13:56:18 -0700 Subject: [PATCH] SCP: Add debug duplicate line output summary support --- scp.c | 176 ++++++++++++++++++++++++++++++++++++++++++++------ sim_console.c | 36 +++-------- sim_console.h | 1 - 3 files changed, 163 insertions(+), 50 deletions(-) diff --git a/scp.c b/scp.c index ca22fc9c..022756a3 100644 --- a/scp.c +++ b/scp.c @@ -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; } @@ -12162,13 +12166,136 @@ return SCPE_OK; /* Debug printout routines, from Dave Hittner */ -const char* debug_bstates = "01_^"; +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) @@ -12697,14 +12826,19 @@ if (sim_mfile) { break; } -/* Store the formatted data */ + /* Store the formatted data */ - 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); + 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; } - memcpy (sim_mfile->buf + sim_mfile->pos, buf, len); - sim_mfile->pos += len; if (buf != stackbuf) free (buf); diff --git a/sim_console.c b/sim_console.c index aa10ba60..f23f5635 100644 --- a/sim_console.c +++ b/sim_console.c @@ -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; diff --git a/sim_console.h b/sim_console.h index 7f2d4901..361870bd 100644 --- a/sim_console.h +++ b/sim_console.h @@ -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);