| [hatari-devel] Compressing identical successive trace output lines |
[ Thread Index |
Date Index
| More lists.tuxfamily.org/hatari-devel Archives
]
Hi,
I've had a problem with tracing that some programs hit specific trace
point constantly, either as result of bug, or as their normal working,
which can scroll the relevant (other) output from console view and
scroll buffer near-instantly.
Attached are patches to change tracing so that one can specify whether
trace output will compress repeated lines, and how many successive
repeats there needs to be for it to output intermediate info about the
repeats.
I'm mapping also LOG_TRACE_PRINT() macro to this, but there are few
traces where this falls down:
- IDE ATAPI CMD
- NF_SCSIDRV inout
Because they do multiple lines of output.
Then there are few things that access TraceFile directly for multi-line
output (instead of using LOG_TRACE_PRINT macro):
- CPU + DSP disasm tracing
- CPU + DSP register tracing
- AES tracing
I.e. one should not enable trace compression when tracing one of above 7
items is enabled.
Comments / thoughts?
- Eero
From f1b8169829a6275312bdff343f33068531ee1c88 Mon Sep 17 00:00:00 2001
From: Eero Tamminen <oak@xxxxxxxxxxxxxx>
Date: Sun, 28 Aug 2022 22:11:48 +0300
Subject: [PATCH 2/2] Change CPU+DSP symbol tracing to use Log_Trace() function
So that repeated entries will be compressed on output.
---
src/debug/debugcpu.c | 29 ++++++++++-------------------
src/debug/debugdsp.c | 31 +++++++++++--------------------
2 files changed, 21 insertions(+), 39 deletions(-)
diff --git a/src/debug/debugcpu.c b/src/debug/debugcpu.c
index 6114d0d6..83478f6b 100644
--- a/src/debug/debugcpu.c
+++ b/src/debug/debugcpu.c
@@ -143,23 +143,6 @@ static int DebugCpu_SaveBin(int nArgc, char *psArgs[])
}
-/**
- * Check whether given address matches any CPU symbol and whether
- * there's profiling information available for it. If yes, show it.
- *
- * @return true if symbol was shown, false otherwise
- */
-static bool DebugCpu_ShowAddressInfo(Uint32 addr, FILE *fp)
-{
- const char *symbol = Symbols_GetByCpuAddress(addr, SYMTYPE_ALL);
- if (symbol)
- {
- fprintf(fp, "%s:\n", symbol);
- return true;
- }
- return false;
-}
-
/**
* Disassemble - arg = starting address, or PC.
*/
@@ -202,6 +185,7 @@ int DebugCpu_DisAsm(int nArgc, char *psArgs[])
prev_addr = disasm_addr;
for (shown = 0; shown < lines && disasm_addr < disasm_upper; shown++)
{
+ const char *symbol;
if (prev_addr < pc && disasm_addr > pc)
{
fputs("ERROR, disassembly misaligned with PC address, correcting\n", debugOutput);
@@ -214,8 +198,12 @@ int DebugCpu_DisAsm(int nArgc, char *psArgs[])
shown++;
}
prev_addr = disasm_addr;
- if (DebugCpu_ShowAddressInfo(disasm_addr, debugOutput))
+ symbol = Symbols_GetByCpuAddress(disasm_addr, SYMTYPE_ALL);
+ if (symbol)
+ {
+ fprintf(debugOutput, "%s:\n", symbol);
shown++;
+ }
Disasm(debugOutput, (uaecptr)disasm_addr, &nextpc, 1);
disasm_addr = nextpc;
}
@@ -900,7 +888,10 @@ void DebugCpu_Check(void)
}
if (LOG_TRACE_LEVEL((TRACE_CPU_DISASM|TRACE_CPU_SYMBOLS)))
{
- DebugCpu_ShowAddressInfo(M68000_GetPC(), TraceFile);
+ const char *symbol;
+ symbol = Symbols_GetByCpuAddress(M68000_GetPC(), SYMTYPE_ALL);
+ if (symbol)
+ Log_Trace("%s\n", symbol);
}
if (LOG_TRACE_LEVEL(TRACE_CPU_REGS))
{
diff --git a/src/debug/debugdsp.c b/src/debug/debugdsp.c
index e0abcb83..27838a8e 100644
--- a/src/debug/debugdsp.c
+++ b/src/debug/debugdsp.c
@@ -101,24 +101,6 @@ error_msg:
}
-/**
- * Check whether given address matches any DSP symbol and whether
- * there's profiling information available for it. If yes, show it.
- *
- * @return true if symbol was shown, false otherwise
- */
-static bool DebugDsp_ShowAddressInfo(Uint16 addr, FILE *fp)
-{
- const char *symbol = Symbols_GetByDspAddress(addr, SYMTYPE_ALL);
- if (symbol)
- {
- fprintf(fp, "%s:\n", symbol);
- return true;
- }
- return false;
-}
-
-
/**
* DSP disassemble - arg = starting address/range, or PC.
*/
@@ -176,6 +158,8 @@ int DebugDsp_DisAsm(int nArgc, char *psArgs[])
prev_addr = dsp_disasm_addr;
fprintf(debugOutput, "DSP disasm 0x%hx-0x%hx:\n", dsp_disasm_addr, dsp_disasm_upper);
for (shown = 1; shown < lines && dsp_disasm_addr < dsp_disasm_upper; shown++) {
+ const char *symbol;
+
if (prev_addr < pc && dsp_disasm_addr > pc)
{
fputs("ERROR, disassembly misaligned with PC address, correcting\n", debugOutput);
@@ -188,8 +172,12 @@ int DebugDsp_DisAsm(int nArgc, char *psArgs[])
shown++;
}
prev_addr = dsp_disasm_addr;
- if (DebugDsp_ShowAddressInfo(dsp_disasm_addr, debugOutput))
+ symbol = Symbols_GetByDspAddress(dsp_disasm_addr, SYMTYPE_ALL);
+ if (symbol)
+ {
+ fprintf(debugOutput, "%s:\n", symbol);
shown++;
+ }
dsp_disasm_addr = DSP_DisasmAddress(debugOutput, dsp_disasm_addr, dsp_disasm_addr);
}
fflush(debugOutput);
@@ -529,7 +517,10 @@ void DebugDsp_Check(void)
}
if (LOG_TRACE_LEVEL((TRACE_DSP_DISASM|TRACE_DSP_SYMBOLS)))
{
- DebugDsp_ShowAddressInfo(DSP_GetPC(), TraceFile);
+ const char *symbol;
+ symbol = Symbols_GetByDspAddress(DSP_GetPC(), SYMTYPE_ALL);
+ if (symbol)
+ Log_Trace("%s\n", symbol);
}
if (nDspActiveCBs)
{
--
2.30.2
From a0235c341d1d23cc72d795a42077ec343f1c8e10 Mon Sep 17 00:00:00 2001
From: Eero Tamminen <oak@xxxxxxxxxxxxxx>
Date: Sun, 28 Aug 2022 20:54:01 +0300
Subject: [PATCH 1/2] Support for compressing successive identical trace output
There are situations (bugs) where specific tracepoint starts repeating
constantly. After it repeats for a while, rest is useless, fills logs
quickly and often scrolls the useful info (about how that sitation was
entered) out of view faster than one can react.
Repeat checking may slow tracing measurably, so it can be enabled only
at runtime with the new "--repeat-limit" option.
If it is needed, high value in thousands is recommended.
---
src/debug/debugui.c | 3 +
src/debug/log.c | 117 +++++++++++++++++++++++++++++++++-
src/debug/log.h | 8 ++-
src/main.c | 2 +-
src/options.c | 8 +++
tests/debugger/test-dummies.c | 1 +
6 files changed, 135 insertions(+), 4 deletions(-)
diff --git a/src/debug/debugui.c b/src/debug/debugui.c
index e15f3eda..6bc7d1c5 100644
--- a/src/debug/debugui.c
+++ b/src/debug/debugui.c
@@ -1073,6 +1073,8 @@ void DebugUI_Init(void)
const dbgcommand_t *cpucmd, *dspcmd;
int cpucmds, dspcmds;
+ Log_ResetTraceRepeats();
+
/* already initialized? */
if (debugCommands)
return;
@@ -1117,6 +1119,7 @@ void DebugUI_Init(void)
*/
void DebugUI_UnInit(void)
{
+ Log_ResetTraceRepeats();
free(debugCommand);
debugCommands = 0;
}
diff --git a/src/debug/log.c b/src/debug/log.c
index 3e8aeef6..a84d810f 100644
--- a/src/debug/log.c
+++ b/src/debug/log.c
@@ -166,6 +166,15 @@ static flagname_t TraceFlags[] = {
Uint64 LogTraceFlags = TRACE_NONE;
FILE *TraceFile = NULL;
+/* trace line repeat compression limit, current repeat count,
+ * and previous line content for checking repetition
+ */
+static struct {
+ int limit;
+ int count;
+ char prev[256];
+} TraceState;
+
static FILE *hLogFile = NULL;
/* local settings, to be able change them temporarily */
@@ -204,7 +213,7 @@ int Log_Init(void)
hLogFile = File_Open(ConfigureParams.Log.sLogFileName, "w");
TraceFile = File_Open(ConfigureParams.Log.sTraceFileName, "w");
-
+
return (hLogFile && TraceFile);
}
@@ -504,6 +513,100 @@ char *Log_MatchTrace(const char *text, int state)
return NULL;
}
+/**
+ * Enable trace output compression and set after how many repeats,
+ * repeat count & trace line are always output.
+ * Return true for success.
+ */
+bool Log_SetTraceRepeatLimit(const char *value)
+{
+ int limit = atoi(value);
+ if (limit > 2)
+ {
+ fprintf(stderr, "Trace line repeat compression enabled (limit = %d)\n", limit);
+ TraceState.limit = limit;
+ }
+ else
+ {
+ fprintf(stderr, "Trace line repeat compression disabled (limit < 2)\n");
+ TraceState.limit = 0;
+ }
+ return true;
+}
+
+static void printTraceRepeats(void)
+{
+ /* trace output strings include trailing newline */
+ fprintf(TraceFile, "%d repetitions of: %s",
+ TraceState.count, TraceState.prev);
+}
+
+/**
+ * If there are pending repeats that have not been output yet,
+ * output them.
+ */
+static void printPendingTraceRepeats(void)
+{
+ if (likely(TraceState.count == 0))
+ return;
+ if (TraceState.count > 1)
+ printTraceRepeats();
+ else
+ fputs(TraceState.prev, TraceFile);
+}
+
+/**
+ * Output pending trace repeat info and reset repeat info.
+ */
+void Log_ResetTraceRepeats(void)
+{
+ if (TraceFile)
+ printPendingTraceRepeats();
+ TraceState.prev[0] = '\0';
+ TraceState.count = 0;
+}
+
+/**
+ * Do trace output with optional repeat compression
+ */
+void Log_Trace(const char *format, ...)
+{
+ va_list argptr;
+ char line[sizeof(TraceState.prev)];
+
+ if (!TraceFile)
+ return;
+
+ if (!TraceState.limit)
+ {
+ va_start(argptr, format);
+ vfprintf(TraceFile, format, argptr);
+ va_end(argptr);
+ fflush(TraceFile);
+ return;
+ }
+ va_start(argptr, format);
+ vsnprintf(line, sizeof(line), format, argptr);
+ va_end(argptr);
+
+ if (unlikely(strcmp(line, TraceState.prev) == 0))
+ {
+ TraceState.count++;
+ if (unlikely(TraceState.count >= TraceState.limit))
+ {
+ printTraceRepeats();
+ TraceState.count = 0;
+ fflush(TraceFile);
+ }
+ return;
+ }
+ strcpy(TraceState.prev, line);
+ printPendingTraceRepeats();
+ fputs(line, TraceFile);
+ TraceState.count = 0;
+ fflush(TraceFile);
+}
+
#else /* !ENABLE_TRACING */
/** dummy */
@@ -518,4 +621,16 @@ char *Log_MatchTrace(const char *text, int state)
return NULL;
}
+/** dummy */
+bool Log_SetTraceRepeatLimit(const char *value)
+{
+ return false;
+}
+
+/** dummy */
+void Log_ResetTraceRepeats(void) {}
+
+/** dummy */
+void Log_Trace(const char *format, ...) {}
+
#endif /* !ENABLE_TRACING */
diff --git a/src/debug/log.h b/src/debug/log.h
index b8a5794f..91bdfa66 100644
--- a/src/debug/log.h
+++ b/src/debug/log.h
@@ -83,6 +83,10 @@ extern void Log_AlertDlg(LOGTYPE nType, const char *psFormat, ...)
extern LOGTYPE Log_ParseOptions(const char *OptionStr);
extern const char* Log_SetTraceOptions(const char *OptionsStr);
extern char *Log_MatchTrace(const char *text, int state);
+extern bool Log_SetTraceRepeatLimit(const char *value);
+extern void Log_ResetTraceRepeats(void);
+extern void Log_Trace(const char *format, ...)
+ __attribute__ ((format (printf, 1, 2)));
#ifndef __GNUC__
#undef __attribute__
@@ -300,7 +304,7 @@ extern Uint64 LogTraceFlags;
#if ENABLE_TRACING
#define LOG_TRACE(level, ...) \
- if (unlikely(LogTraceFlags & (level))) { fprintf(TraceFile, __VA_ARGS__); fflush(TraceFile); }
+ if (unlikely(LogTraceFlags & (level))) { Log_Trace(__VA_ARGS__); }
#define LOG_TRACE_LEVEL( level ) (unlikely(LogTraceFlags & (level)))
@@ -316,7 +320,7 @@ extern Uint64 LogTraceFlags;
* In code it's used in such a way that it will be optimized away when tracing
* is disabled.
*/
-#define LOG_TRACE_PRINT(...) fprintf(TraceFile , __VA_ARGS__)
+#define LOG_TRACE_PRINT(...) Log_Trace(__VA_ARGS__)
#endif /* HATARI_LOG_H */
diff --git a/src/main.c b/src/main.c
index db8760fd..f028b546 100644
--- a/src/main.c
+++ b/src/main.c
@@ -812,10 +812,10 @@ static void Main_UnInit(void)
SDL_Quit();
/* Close debug log file */
+ DebugUI_UnInit();
Log_UnInit();
Paths_UnInit();
- DebugUI_UnInit();
}
diff --git a/src/options.c b/src/options.c
index 195eec4f..c141d0ab 100644
--- a/src/options.c
+++ b/src/options.c
@@ -197,6 +197,7 @@ enum {
OPT_NATFEATS,
OPT_TRACE,
OPT_TRACEFILE,
+ OPT_TRACE_REPEAT,
OPT_PARSE,
OPT_SAVECONFIG,
OPT_CONTROLSOCKET,
@@ -492,6 +493,8 @@ static const opt_t HatariOptions[] = {
"<flags>", "Activate emulation tracing, see '--trace help'" },
{ OPT_TRACEFILE, NULL, "--trace-file",
"<file>", "Save trace output to <file> (default=stderr)" },
+ { OPT_TRACE_REPEAT, NULL, "--repeat-limit",
+ "<x>", "Set trace line repeat compression limit (>1 = enable compression)" },
{ OPT_PARSE, NULL, "--parse",
"<file>", "Parse/execute debugger commands from <file>" },
{ OPT_SAVECONFIG, NULL, "--saveconfig",
@@ -2204,6 +2207,11 @@ bool Opt_ParseParameters(int argc, const char * const argv[])
NULL);
break;
+ case OPT_TRACE_REPEAT:
+ i += 1;
+ ok = Log_SetTraceRepeatLimit(argv[i]);
+ break;
+
case OPT_CONTROLSOCKET:
i += 1;
errstr = Control_SetSocket(argv[i]);
diff --git a/tests/debugger/test-dummies.c b/tests/debugger/test-dummies.c
index 60c978a3..488a63fa 100644
--- a/tests/debugger/test-dummies.c
+++ b/tests/debugger/test-dummies.c
@@ -7,6 +7,7 @@
#include "log.h"
Uint64 LogTraceFlags = 0;
FILE *TraceFile;
+void Log_Trace(const char *format, ...) { }
/* fake Hatari configuration variables for number parsing */
#include "configuration.h"
--
2.30.2