<< Click to Display Table of Contents >> Navigation:  ASA-EMulatR Reference Guide > Introduction > Appendix > Appendix K – Instruction Trace and Console Logging

This appendix is the authoritative reference for the ASA-EMulatR trace and logging subsystems. The trace subsystem (CpuTrace) records every instruction executed by the emulated Alpha AXP CPU to persistent log files in two complementary formats. The console logging subsystem (LoggingMacros) records emulator-level diagnostic messages to the application console. Both subsystems are active across all phases of execution — from Phase 14 SRM decompression through normal SRM console firmware execution — and are the primary tools for post-mortem analysis, instruction-level debugging, and performance measurement.

 

---

 

K.1 CpuTrace Architecture

 

CpuTrace is a static singleton class providing thread-safe, dual-format instruction logging. It writes to two files simultaneously: a human-readable DEC-style listing (.lst) and a machine-parsable structured log (.log). Both files are written on every instruction — they are always synchronized. CpuTrace is initialized once at emulator startup via CpuTrace::initialize() and remains active for the lifetime of the process.

 

All public methods are static. There is no instance to create or manage. Thread safety is provided by a QMutex held for the duration of each write operation. A static line counter triggers a flush every 4096 lines to reduce I/O pressure without sacrificing durability.

 

Key design decisions:

 

No qDebug() in the trace path. High-volume instruction trace lines are written directly to QTextStream and never pass through qDebug(). Routing trace through qDebug() doubles every write — once to the installed message handler and once to the stream. At 5.7 million instructions per decompressor run, that overhead is measurable. The qInstallMessageHandler path is reserved for emulator-level diagnostic messages only.

 

AXP_DEBUG gate for grain-level trace. Verbose per-grain execution logging (register values, intermediate computations) is wrapped in #ifdef AXP_DEBUG blocks. When AXP_DEBUG is not defined in CMakeLists.txt, these blocks compile out entirely. The outer CpuTrace::instruction() call at the pipeline level always fires regardless of AXP_DEBUG — it is not a debug-only path.

 

Inline static QElapsedTimer. m_timer is declared inline static in the header (C++17). No .cpp definition is required. This eliminates the LNK2001 link error that occurs when a static member is declared but not defined in a translation unit.

 

---

 

K.2 Trace File Formats

 

K.2.1 DEC-Style Listing (.lst)

 

The .lst file is a fixed-width human-readable listing in the style of DEC Alpha hardware debug tools. Each instruction occupies one line. The format is optimized for visual scanning — column alignment allows the eye to track PC progression, instruction encoding, and register results without parsing.

 

File header (3 lines):

CPU TRACE LOG - DEC Style ListingGenerated: Fri Mar 6 19:00:07 2026---------------------------------------------------------------

 

Instruction line format:

SSSSSSSS PPPPPPPPPPPPPPPP RRRRRRRR MMMMMM OOOOOOOOOOOOOOOOOOOO RESULT

 

 

Representative excerpt — copy loop exit sequence (ES40 V6.2, 2026-03-06):

05767318 00000000009002b8 40211521 SUBQ R1, #0x08, R1 R1 = 0x000000000000000005767319 00000000009002bc 7c601000 HW_LD R3, 0x000(R0)05767320 00000000009002c0 e8800003 BLT R4, 0x00000000009002d005767321 00000000009002c4 40011400 ADDQ R0, #0x08, R0 R0 = 0x000000000040000005767322 00000000009002c8 f43ffff8 BNE R1, 0x00000000009002ac05767323 00000000009002cc 6c1a1000 HW_ST R0, 0x000(R26)05767324 00000000009002d0 e8800003 BLT R4, 0x00000000009002e005767325 00000000009002d4 47e0041e BIS R31, R0, R30 R30 = 0x000000000040000005767326 00000000009002d8 201a05c0 LDA R0, 5c0(R26) R0 = 0x00000000000005c005767327 00000000009002dc 6be04000 JSR R31, (R0) -> 0x00000000000005c0

 

The result field is absent for instructions with no register writeback (stores, unresolved branches, NOPs). Branch targets are shown as -> 0x... when the branch is taken. When a branch is not taken the result field is empty.

 

K.2.2 Machine-Parsable Log (.log)

 

The .log file is a structured key=value format suitable for automated parsing, grep, and scripted analysis. Each record type is identified by a leading tag.

 

File header (2 lines):

# CPU TRACE LOG - Machine Parsable# Generated: Fri Mar 6 19:00:07 2026

 

Record types:

 

 

INS record example:

INS cycle=5767327 pc=00000000009002dc instr=6be04000 mnem=JSR ops="R31, (R0)" result="-> 0x00000000000005c0"

 

REG record example:

REG cycle=5767325 r30=0000000000400000

 

Elapsed time banner example:

# Elapsed 00:16:39.224

 

The cycle= field in INS records is a decimal integer matching the sequence field in the .lst file. Both files can be correlated line-for-line using the cycle number. The pc= field is always 16 hex digits zero-padded. The instr= field is always 8 hex digits zero-padded.

 

Known issue — QString::arg comma in result field. When the result string contains a comma (e.g. a multi-register result), Qt emits a QString::arg: Argument missing warning to the console. This is a cosmetic issue in the log formatting code and does not affect trace correctness. The INS record is still written correctly — only the Qt warning is spurious. This will be corrected in a future revision by concatenating the result field rather than passing it as a .arg() parameter.

 

---

 

K.3 Trace Mask Reference

 

The trace mask is a 32-bit bitmask that controls which categories of trace records are written. It is set via CpuTrace::setTraceMask(uint32_t) and read via CpuTrace::getTraceMask(). The default mask at initialization is TRACE_ALL.

 

 

Recommended masks for common scenarios:

 

// Instruction trace only -- minimum overheadCpuTrace::setTraceMask(CpuTrace::TRACE_INSTR);// Instruction + event -- useful for fault/flush analysisCpuTrace::setTraceMask(CpuTrace::TRACE_INSTR | CpuTrace::TRACE_EVENT);// Full debug -- all categories (default, maximum file size)CpuTrace::setTraceMask(CpuTrace::TRACE_ALL);// Suppress all trace -- maximum throughputCpuTrace::setTraceMask(CpuTrace::TRACE_NONE);

 

The trace mask can be changed at runtime without restarting the emulator. Calling setTraceMask(TRACE_NONE) before the SRM decompressor run and setTraceMask(TRACE_ALL) after Phase 14 completes significantly reduces decompressor run time in debug builds — the copy loop executes 524,288 iterations and trace I/O is the dominant overhead.

 

---

 

K.4 Elapsed Time and Timing Fields

 

K.4.1 Elapsed Time Format

 

CpuTrace::elapsedTime() returns a formatted string representing the wall-clock time elapsed since CpuTrace::startElapsedTime() was called. The format is:

 

hh:mm:ss.mmm

 

where hh is zero-padded hours, mm is zero-padded minutes, ss is zero-padded seconds, and mmm is zero-padded milliseconds. The format is fixed-width and suitable for log correlation and lexicographic sort.

 

Examples:

00:00:00.031 -- 31 ms (copy loop entered)00:00:00.056 -- 56 ms (copy loop phase detection fired)00:16:39.224 -- 16 min 39.224 sec (decompression complete)

 

API:

// Start the elapsed timer (call at decompress() entry)CpuTrace::startElapsedTime();// Get formatted string for log outputQString t = CpuTrace::elapsedTime(); // e.g. "00:16:39.224"// Get raw milliseconds for calculationsqint64 ms = CpuTrace::elapsedMs();// Write "# Elapsed hh:mm:ss.mmm" banner to machine log + flushCpuTrace::writeElapsedToMachineLine();

 

K.4.2 Phase Milestone Timing

 

The decompressor emits four phase milestone log lines, each prefixed with the elapsed time in hh:mm:ss.mmm format. These are written via INFO_LOG and appear in the console log only — they are not written to the trace files.

 

 

Note on copy loop step count: The copy loop exit milestone currently reports 8 steps due to a fetch-vs-commit PC detection issue. The actual copy loop executes 524,288 quadword iterations. See Appendix J, Section J.3.3 for full explanation. The timing fields (copyLoopMs) are correct regardless of the step count inaccuracy.

 

---

 

K.5 Console Log Format

 

K.5.1 Log Levels

 

The console logging subsystem uses four levels, implemented as macros in coreLib/LoggingMacros.h. Each macro prepends a level tag and the component name to the message string.

 

 

K.5.2 Console Line Format

 

Each console log line follows this format:

 

[LEVEL] [YYYY-MM-DD hh:mm:ss.ffffff] [LEVEL ] [ComponentName] Message

 

Example lines:

[DEBUG] [2026-03-06 19:00:08.864295] [INFO ] [SrmRomLoader] === SRM Decompression starting ===[DEBUG] [2026-03-06 19:00:08.864295] [INFO ] [SrmRomLoader] ROM payload : 2799616 bytes[DEBUG] [2026-03-06 19:00:08.864295] [INFO ] [SrmRomLoader] Mirror PA : 0x0[DEBUG] [2026-03-06 19:00:08.864295] [INFO ] [SrmRomLoader] Load PA : 0x900000[DEBUG] [2026-03-06 19:00:08.896067] [INFO ] [SrmRomLoader] [T+00:00:00.031] Copy loop entered -- step 158[DEBUG] [2026-03-06 19:20:11.302307] [INFO ] [SrmRomLoader] Decompression: 100%[DEBUG] [2026-03-06 19:20:11.525940] [INFO ] [SrmRomLoader] [T+00:16:39.224] Decompression complete[DEBUG] [2026-03-06 19:20:11.704657] [INFO ] [SrmRomLoader] Final PC : 0x5c0[DEBUG] [2026-03-06 19:20:12.097118] [INFO ] [SrmRomLoader] PAL_BASE : 0x900000[DEBUG] [2026-03-06 19:20:12.366973] [INFO ] [SrmRomLoader] Total steps : 5767331

 

The leading [DEBUG] prefix is emitted by the Qt message handler installed at startup — it reflects the Qt message type routing through qInstallMessageHandler. The second [INFO ] / [WARN ] tag is the application-level severity from the logging macro. The COMPONENT_NAME define in each .cpp file controls the component tag (e.g. #define COMPONENT_NAME "SrmRomLoader").

 

K.5.3 Progress Reporting

 

The decompressor emits progress percentage messages through the ProgressFn callback. The call site in Emulatr_Init.cpp logs every 10% increment:

 

[INFO ] [SrmRomLoader] Decompression: 30% (at ~4 min 32 sec)[INFO ] [SrmRomLoader] Decompression: 60% (at ~9 min 08 sec)[INFO ] [SrmRomLoader] Decompression: 90% (at ~13 min 38 sec)[INFO ] [SrmRomLoader] Decompression: 100% (at ~20 min 11 sec)

 

Progress is emitted between batch boundaries (every 1,800,000 steps). Because the copy loop and decompressor engine run within a single batch, the 10%/20% early progress points may not fire if the batch boundary is not reached. The 30% first emission seen in the verified run reflects this — the first batch boundary after the copy loop completes is already at approximately 30% of total work.

 

---

 

K.6 Phase Milestone Reference

 

The following table is the complete reference for all phase milestone messages emitted during Phase 14 SRM firmware load. Timestamps are from the verified ES40 V6.2 decompressor run on 2026-03-06 in a debug build with full trace I/O enabled.

 

 

(*) Copy loop step count inaccuracy — see J.3 - SRM-D Snapshot Mechanics  Section J.3.3.

 

---

 

K.7 Interpreting Decompressor Trace Output

 

K.7.1 Trace File Sizes and Storage

 

A complete decompressor run at TRACE_ALL produces large trace files. The ES40 V6.2 verified run on 2026-03-06 produced:

 

 

These files are stored in the project git repository. They are available as compressed ZIP.

 

A curated sample covering the copy loop exit and boot handoff sequence is included in the repository at:

 

docs/traces/sample_decompressor_exit.lst

 

K.7.2 Navigating a Large Trace

 

The recommended tool for searching large trace files on Windows is ripgrep (rg). Install via:

 

winget install BurntSushi.ripgrep.MSVC

 

Useful search patterns:

 

# Find all executions of a specific PCrg "009002dc" tracescpu_trace.lst# Find all branch-taken instructionsrg "\-\> 0x" tracescpu_trace.lst# Find all HW_ST instructionsrg "HW_ST" tracescpu_trace.lst# Find last N lines (loop exit region)rg "" tracescpu_trace.lst | tail -20# Find R1 reaching zerorg "R1 = 0x0000000000000000" tracescpu_trace.lst# Count total instructionsrg -c "^[0-9]" tracescpu_trace.lst

 

Key sequence numbers for the ES40 V6.2 verified run:

 

 

---

See Also: J.3 - SRM-D Snapshot Mechanics  (decompressor phase timing, copy loop exit sequence); Appendix G - Instruction Grain Mechanics (grain execution and AXP_DEBUG trace injection); coreLib/cpuTrace.h; coreLib/cpuTrace.cpp; coreLib/LoggingMacros.h; docs/traces/sample_decompressor_exit.lst; github.com/timothypeer/ASA-EMulatR/releases (full trace archive).