refactor tracing out of Emulator, try to make it less insane

Author: none

TODO

@@ -15,8 +15,10 @@ Things to investigate / fix:
   ✔ suppress read traces for instruction fetches @done (20-02-02 18:24)
   ✔ newlib sbrk is busted; make stack bigger (room for stack + heap) & grow up from _end @done (20-02-08 23:32)
   ☐ exceptions in callbacks seem to trash the emulator state; probably better to hard-abort out of them
-  ☐ decide between public attributes and property methods. Device._name, size, address - anything not computed.
+  ✔ decide between public attributes and property methods. Device._name, size, address - anything not computed. @done (20-02-15 09:35)
   ☐ lots of Emulator functionality needs an instance, but that's inconvenient; maybe classmethods? module-level functions?
+  ☐ symbolication for e.g. address zero is printing vector names
+    ☐ MAP operations should not symbolicate
 
 Features:
   ✔ need new memory model, support multiple disjoint memories (RAM, ROM), > 16MiB @done (20-01-28 15:54)
@@ -34,6 +36,9 @@ Features:
   ✔ factor ROM loading into emu.add_memory rather than duplicating in the target @done (20-02-08 09:35)
 
 Tracing:
+  Needs a complete rethink
+  ☐ trace message via NatFeat
+  ☐ tracing on/off for-X-cycles via NatFeat
   ☐ device read/write
   ☐ memory read/write
   ☐ register mapping
@@ -46,7 +51,6 @@ Tracing:
   ☐ spurious interrupt
   ☐ quantum start / end
   ☐ emulator, device debug message
-  ☐ 
 Devices:
   ☐ root_device should signal bus error on failed register decode
   ✔ always call device.tick after handling register access @done (20-02-04 22:48)
@@ -63,8 +67,8 @@ Devices:
     ☐ migrate existing tick logic to callbacks @high
   ✔ hash register/size/direction to handler rather than just address to read/write handlers @done (20-02-13 22:33)
   ☐ support 'fallback' handlers (16-bit access to 8 or 32-bit registers, etc.)
-  ☐ --trace-io is global, would be nice to have per-dev tracing effective here
-  ☐ Device.__trace/__diagnostic is a mess, rethink -> use logging framework?
+  ✔ --trace-io is global, would be nice to have per-dev tracing effective here @done (20-02-18 23:15)
+  ✔ Device.__trace/__diagnostic is a mess, rethink -> use logging framework? @done (20-02-18 23:15)
   68681:
    ✔ don't assume 'off-by-one' mapping, configure for low-byte, high-byte and packed @done (20-02-08 09:18)
    ☐ implement echo & loopback modes @low

consoleserver.py

@@ -2,14 +2,14 @@
 # Console server application - listens on port 6809 and emulates a VT102
 #
 
-import sys
-import os
 import curses
-import vt102
-import socket
+import os
 import selectors
 import signal
+import socket
+import sys
 import time
+import vt102
 
 
 class ConsoleServer():
@@ -114,12 +114,9 @@ def _fmt(self, val):
         return str
 
     def _handle_input(self, input):
-        # self.trace('in ' + self._fmt(input))
         self._buffered_input += chr(input)
 
     def _handle_output(self, output):
-        # self.trace('out ' + self._fmt(output))
-
         # vt102 is only 7-bit clean
         output &= 0x7f
         self._buffered_output += chr(output)
@@ -144,8 +141,6 @@ def _update(self):
         input = self._win.getch()
         if input != -1:
             if input in ConsoleServer.input_keymap:
-                # self.trace('translate {} -> {}'.format(input,
-                #                                        ConsoleServer.input_keymap[input]))
                 for c in ConsoleServer.input_keymap[input]:
                     self._handle_input(ord(c))
             else:

device.py

@@ -3,8 +3,10 @@
 #
 
 import sys
+
 from musashi import m68k
 from register import Register
+from trace import Trace
 
 
 class Device(object):
@@ -17,13 +19,15 @@ class Device(object):
     __emu = None
     __root_device = None
     __debug = False
-    __trace_io = False
+    __trace = None
 
     __console_output_handler = None
     __console_input_handler = None
 
     def __init__(self, args, name, required_options=None, **options):
         self.name = name
+        if Device.__trace is None:
+            Device.__trace = Trace.get_tracer()
 
         if required_options is not None:
             for optname in required_options:
@@ -56,11 +60,11 @@ def add_device(cls, args, dev, **options):
 
         if Device.__root_device is None:
             # one-time init
+            Register.init(args)
             m68k.set_int_ack_callback(Device.__cb_int)
             m68k.mem_set_device_handler(Device.__cb_access)
-            Device.__debug = 'device' in args.debug_device
+            Device.__debug = 'Device' in args.debug_device
             Device.__emu = options['emulator']
-            Register.init(args, Device.__emu)
 
             Device.__root_device = dev(args=args, **options)
             Device.__root_device.add_system_devices(args)
@@ -91,7 +95,7 @@ def add_register(self, name, offset, size, access, handler):
             self.size = implied_size
 
         if self.debug or self.__class__.__debug:
-            Device.__emu.trace('MAP_REG', address=reg.address, info=f'{repr(reg)}')
+            Device.trace(action='MAP_REG', address=reg.address, info=f'{reg}')
 
     def add_registers(self, registers):
         """
@@ -106,32 +110,10 @@ def __cb_access(cls, operation, address, size, value):
             value = Register.access(address, size, operation, value)
         except KeyError:
             # XXX bus error?
-            Device.__trace('DECODE', f'no register to handle {operation}:{address:#x}/{size}')
+            Device.trace('DECODE', f'no register to handle {operation}:{address:#x}/{size}')
 
         return value
 
-    ########################################
-    # Logging
-
-    def trace(self, address=None, info=''):
-        """
-        Emit a debug trace message
-        """
-        if self.debug:
-            Device.__emu.trace(self.name, address=address, info=info)
-
-    def diagnostic(self, address=None, info=''):
-        Device.__emu.trace(f'{self.name}!!', info=info)
-
-    @classmethod
-    def __trace(cls, address=None, info=''):
-        if Device.__debug:
-            Device.__emu.trace('device', address=address, info=info)
-
-    @classmethod
-    def __diagnostic(cls, address=None, info=''):
-        Device.__emu.trace('device!!', address=address, info=info)
-
     ########################################
     # Device callbacks
 
@@ -237,9 +219,9 @@ def __set_ipl(cls):
                 # an unmasked interrupt we need to end the timeslice to get its
                 # attention
                 m68k.end_timeslice()
-                Device.__trace(info=f'un-masked IPL {ipl} from {asserting_dev.name}')
+                Device.trace(info=f'un-masked IPL {ipl} from {asserting_dev.name}')
             else:
-                Device.__trace(info=f'masked IPL {ipl} from {asserting_dev.name}')
+                Device.trace(info=f'masked IPL {ipl} from {asserting_dev.name}')
         m68k.set_irq(ipl)
 
     @classmethod
@@ -251,9 +233,9 @@ def __cb_int(cls, interrupt):
             if dev._asserted_ipl == interrupt:
                 vector = dev.get_vector(interrupt)
                 if vector != m68k.IRQ_SPURIOUS:
-                    Device.__trace(info=f'INTERRUPT, vector {vector}')
+                    Device.trace(info=f'INTERRUPT, vector {vector}')
                     return vector
-        Device.__trace(info='SPURIOUS_INTERRUPT')
+        Device.trace(info='SPURIOUS_INTERRUPT')
         return m68k.IRQ_SPURIOUS
 
     ########################################
@@ -328,6 +310,18 @@ def root_device(self):
     def devices(self):
         return self.__class__.__devices
 
+    ########################################
+    # Tracing
+
+    def trace(self, address=None, info=''):
+        if self.debug:
+            Device.__trace.trace(action=self.name, address=address, info=info)
+
+    @classmethod
+    def trace(cls, action='', address=None, info=''):
+        if cls.__debug:
+            cls.__trace.trace(action=action, address=address, info=info)
+
     ########################################
     # Subclass protocol
 

devices/CompactFlash.py

@@ -1,6 +1,6 @@
-import sys
 import io
 import struct
+import sys
 
 from device import Device
 from musashi import m68k
@@ -248,16 +248,15 @@ def _write_command(self, value):
         else:
             self._r_status = STATUS_ERR
             self._r_error = ERROR_ABORT
-            self._trace_io('IOERR', 'command {:02x} not supported'.format(value))
+            self.trace(info=f'ERROR: command {value:02x} not supported')
 
     def _trace_io(self, action):
-        self.trace(action, 'count {} LBA {}'.format(
-            self._r_sector_count, self._r_lba))
+        self.trace(info=f'{action} count {self._r_sector_count} LBA {self._r_lba}')
 
     def _do_io(self, mode):
         # if we're in the FAULT state (no file, eg.) all I/O fails
         if self._r_status & STATUS_DF:
-            self.trace('IOERR', 'no device')
+            self.trace(info=f'ERROR: no device')
             self._r_status |= STATUS_ERR
             self._r_error = ERROR_UNCORRECTABLE
             return
@@ -271,7 +270,7 @@ def _do_io(self, mode):
             self._bytes_remaining = 256 * SECTOR_SIZE
 
         if (file_byte_offset + self._bytes_remaining) > self._file_size:
-            self.trace('IOERR', 'access beyond end of device')
+            self.trace(info=f'ERROR: access beyond end of device')
             self._r_status |= STATUS_ERR
             self._r_error = ERROR_UNCORRECTABLE
 
@@ -291,15 +290,15 @@ def _io_read(self, width):
         elif self._current_mode == AMODE_READ:
             pass
         else:
-            self.trace('IOERR', 'data read when not reading / identifying')
+            self.trace(info=f'ERROR: data read when not reading / identifying')
             return 0
 
         if width == m68k.MEM_SIZE_8:
             count = 1
         else:
             count = 2
         if self._bytes_remaining < count:
-            self.trace('IOERR', 'read beyond sector buffer')
+            self.trace(info=f'ERROR: read beyond sector buffer')
             return 0
 
         if self._current_mode == AMODE_READ:
@@ -327,7 +326,7 @@ def _io_read(self, width):
 
     def _io_write(self, width, value):
         if self._current_mode != AMODE_WRITE:
-            self.trace('IOERR', 'data write when not writing')
+            self.trace(info=f'ERROR: data write when not writing')
             return 0
 
         data = bytearray()
@@ -336,7 +335,7 @@ def _io_write(self, width, value):
             data.append(value >> 8)
 
         if self._bytes_remaining < len(data):
-            self.trace('IOERR', 'write beyond sector buffer')
+            self.trace(info=f'ERROR: write beyond sector buffer')
             return
 
         self._file_handle.write(data)

devices/MC68681.py

@@ -115,7 +115,7 @@ def _update_isr(self):
             isr |= self.INT_TXRDY
         if self._rxEnable:
             if len(self._rxfifo) > (1 if self._mr1 & self.MR1_FFULL_EN else 0):
-                isr |= self.INT_RXDRY_FFULL
+                isr |= self.INT_RXRDY_FFULL
         self._parent.update_channel_isr(self._port, isr)
 
     def _handle_console_input(self, input):

devices/p90ce201.py

@@ -1,11 +1,8 @@
+from collections import deque
 import sys
+
 from device import Device
-from collections import deque
-from musashi.m68k import (
-    M68K_IRQ_SPURIOUS,
-    M68K_IRQ_AUTOVECTOR,
-    MEM_SIZE_8,
-)
+from musashi.m68k import m68k
 
 ADDR_P90Syscon = 0x80001000
 ADDR_P90ICU = 0x80001020

devices/simple.py

@@ -1,6 +1,6 @@
-from device import Device
 from collections import deque
 
+from device import Device
 from musashi import m68k
 
 
@@ -132,23 +132,23 @@ def _write_countdown(self, value):
             self.deassert_ipl()
             self._deadline = 0
             self.callback_cancel('count')
-            self.trace('timer cancelled')
+            self.trace(info='timer cancelled')
         else:
             self._deadline = self.current_cycle + value * self._scaler
             self.callback_at(self._deadline, 'count', self._callback)
-            self.trace(f'timer set for {self._deadline}, now {self.current_cycle}')
+            self.trace(info=f'timer set for {self._deadline}, now {self.current_cycle}')
 
     def _write_vector(self, value):
         self._r_vector = value
 
     def _callback(self):
         if (self._deadline > 0):
             if (self._deadline <= self.current_cycle):
-                self.trace('timer expired')
+                self.trace(info='timer expired')
                 self.assert_ipl()
                 self._deadline = 0
             else:
-                self.trace('spurious callback')
+                self.trace(info='spurious callback')
                 self.callback_at(self._deadline, 'count', self._callback)
 
     def reset(self):