Log Formatting

8b941cd7…5c7512f8

I’ve been comparing my log output to the disassembled boot ROM. It would probably be nifty and convenient to just have my output include the assembly encoding of the instructions I’m executing. At first it was jibberish, but there aren’t that many assembly instructions and I’m going to be working with them so I shouldn’t forget.

Something like the following. Put the assembly commands on the left, followed by the initial instruction pointer index, then the original machine code, and finally the values of any relevant registers and memory locations. Using the assembly-style $ hex prefix instead of 0x.

asm                 ; i     ; machine code ; registers
LD C, $11           ; $000F ; $0E1123      ; C' = $11
BIT 7, H            ; $0012 ; $BCFF        ; H = 0xFA  ; Z' = true
JR NZ, -5           ; $0014 ; $FFFF        ; Z = false

Here I’m using C' to indicate a new value for the C register. I like this, but I think the z80 architechture actually has additional registers with names including C', so that may be confusing. Consider something else like C₀ and C₁. Or I could be explicit about the change, like C = 0 => 1.

Rust’s built-in string formatting is most-directly influenced by Python; that’s simple enough.

I want to keep track of all of the code for the current instruction. I might add a second instruction pointer. The existing one, .next_code (renamed from .i), will continue to point to the next code address/index, but we’ll add a second .last_instruction pointing to the first byte of the current/latest opcode. Taking a [.last_instruction, .next_code] slice of the memory will give us all of the current machine code for the log. Except that… “slicing” memory isn’t a primitive operation; reading memory can have side effects. So instead, I should just keep a buffer with the current machine code as I read it.

I’ll add debug_current_code: vec![] and debug_current_op_addr: u16 fields to our struct, and a couple of methods that we’ll now use for reading from the instruction pointer:

fn read_instruction(&mut self) -> u8 {
    self.debug_current_code.clear();
    self.debug_current_op_addr = self.i;
    self.read_immediate_u8()
}

fn read_immediate_u8(&mut self) -> u8 {
    let value = self.get_memory(self.i);
    self.debug_current_code.push(value);
    self.i += 1;
    value
}

And a print_current_code function for logging messages with the instruction pointer and codes on the side:

fn print_current_code(&self, asm: String, info: String) {
    print!("{:32}", asm);
    print!(" ; ${:04x}", self.debug_current_op_addr);
    let code = self.debug_current_code.clone().into_iter().map(|c| { format!("{:02x}", c) }).collect::<Vec<String>>().join("");
    print!(" ; ${:8}", code);
    print!(" ; {}", info);
    println!();
}

After updating the opcode implementations to use print_current_code, like this:

0x38 => {
    let delta = self.read_immediate_u8() as i8;
    self.print_current_code(
        format!("JR C, {}", delta),
        format!("C = {}", self.c_flag()));
    if self.c_flag() {
        self.relative_jump(delta as i32);
    }
}

We have the desired output. It looks nice! Here’s the beginning:

LOAD SP $fe, $ff                 ; $0000 ; $31feff   ;
XOR A A                          ; $0003 ; $af       ; A₀ = $00, A₁ = $00
LOAD HL, $ff, $9f                ; $0004 ; $21ff9f   ;
LD (HL-), A                      ; $0007 ; $32       ; HL₀ = $9fff, A = $00
  ; video_ram[$1fff] = $00
BIT 7, H                         ; $0008 ; $cb7c     ; Z₁ = false
JR NZ, -5                        ; $000a ; $20fb     ; Z = false

For comparison, here is the equivalent part from Ignacio Sánchez Ginés’s disassembly of the boot ROM:

  LD SP,$fffe      ; $0000  Setup Stack
  XOR A            ; $0003  Zero the memory from $8000-$9FFF (VRAM)
  LD HL,$9fff      ; $0004
Addr_0007:
  LD (HL-),A       ; $0007
  BIT 7,H          ; $0008
  JR NZ, Addr_0007 ; $000a