Switch some logging on critical paths to the new logging system

arm/cpu.go

@@ -177,14 +177,23 @@ func (cpu *Cpu) Exception(exc Exception) {
 		num := cpu.Read16(uint32(pc-2)) & 0xFF
 		if hle := cpu.swiHle[num]; hle != nil {
 			// cpu.breakpoint("hle")
-			log.ModCpu.WithField("num", num).Infof("SWI - HLE emulation")
+			log.ModCpu.InfoZ("SWI - HLE emulation").
+				Uint16("num", num).
+				Uint16("exc", uint16(exc)).
+				End()
 			delay := hle(cpu)
 			cpu.Clock += delay + 3
 			return
 		}
-		log.ModCpu.WithField("num", num).Infof("SWI")
+		log.ModCpu.InfoZ("SWI").
+			Uint16("num", num).
+			End()
 	} else {
-		log.ModCpu.Infof("Exception: exc=%v, LR=%v, arch=%v", exc, pc, cpu.arch)
+		log.ModCpu.InfoZ("exception").
+			Int("exc", int(exc)).
+			Hex32("LR", uint32(pc)).
+			Int("arch", int(cpu.arch)).
+			End()
 	}
 
 	*cpu.RegSpsrForMode(newmode) = cpu.Cpsr.r

divisor.go

@@ -1,7 +1,6 @@
 package main
 
 import (
-	"fmt"
 	"ndsemu/emu/hwio"
 	log "ndsemu/emu/logger"
 )
@@ -64,13 +63,12 @@ func (div *HwDivisor) calc() {
 			div.Res.Value = uint64(int64(res))
 			div.Mod.Value = uint64(int64(mod))
 		}
-		modDiv.WithDelayedFields(func() log.Fields {
-			return log.Fields{
-				"div": fmt.Sprintf("%d/%d", int32(div.Numer.Value), int32(div.Denom.Value)),
-				"res": int64(div.Res.Value),
-				"mod": int64(div.Mod.Value),
-			}
-		}).Infof("32-bit division")
+		modDiv.InfoZ("32-bit division").
+			Int32("num", int32(div.Numer.Value)).
+			Int32("den", int32(div.Denom.Value)).
+			Int64("res", int64(div.Res.Value)).
+			Int64("mod", int64(div.Mod.Value)).
+			End()
 		return
 	}
 
@@ -97,13 +95,12 @@ func (div *HwDivisor) calc() {
 		div.Mod.Value = uint64(int64(div.Numer.Value) % denom)
 	}
 
-	modDiv.WithDelayedFields(func() log.Fields {
-		return log.Fields{
-			"div": fmt.Sprintf("%d/%d", int64(div.Numer.Value), denom),
-			"res": int64(div.Res.Value),
-			"mod": int64(div.Mod.Value),
-		}
-	}).Infof("64-bit division")
+	modDiv.InfoZ("64-bit division").
+		Int64("num", int64(div.Numer.Value)).
+		Int64("den", denom).
+		Int64("res", int64(div.Res.Value)).
+		Int64("mod", int64(div.Mod.Value)).
+		End()
 }
 
 func (div *HwDivisor) ReadSQRTRES(_ uint32) uint32 {

dma.go

@@ -167,15 +167,15 @@ func (dma *HwDmaChannel) xfer() {
 		if repeat {
 			dma.debugRepeat = true
 		}
-		log.ModDma.WithFields(log.Fields{
-			"sad":   emu.Hex32(sad),
-			"dad":   emu.Hex32(dad),
-			"cnt":   emu.Hex32(cnt),
-			"sinc":  sinc,
-			"dinc":  dinc,
-			"irq":   irq,
-			"wsize": wordsize,
-		}).Infof("transfer")
+		log.ModDma.InfoZ("transfer").
+			Hex32("sad", sad).
+			Hex32("dad", dad).
+			Hex32("cnt", cnt).
+			Uint16("sinc", sinc).
+			Uint16("dinc", dinc).
+			Bool("irq", irq).
+			Uint32("wsize", wordsize).
+			End()
 	}
 	if dad == 0 {
 		// nds9.Cpu.Exception(arm.ExceptionDataAbort)

gxcmd.go

@@ -3,7 +3,6 @@ package main
 import (
 	"fmt"
 	"ndsemu/emu"
-	log "ndsemu/emu/logger"
 	"ndsemu/raster3d"
 )
 
@@ -54,6 +53,10 @@ func (f fcolor) ToClampedColor() (c color) {
 	return
 }
 
+func (c color) To32bit() uint32 {
+	return uint32(c[0]) | uint32(c[1])<<8 | uint32(c[2])<<16
+}
+
 func (v vector) String() string {
 	return fmt.Sprintf("v3d(%v,%v,%v,%v)", v[0], v[1], v[2], v[3])
 }
@@ -211,9 +214,9 @@ func (gx *GeometryEngine) CalcCmdCycles(code GxCmdCode) int64 {
 
 func (gx *GeometryEngine) recalcClipMtx() {
 	gx.clipmtx = matMul(gx.mtx[1], gx.mtx[0])
-	modGx.Infof("proj mtx: %v", gx.mtx[0])
-	modGx.Infof("pos mtx: %v", gx.mtx[1])
-	modGx.Infof("clip mtx: %v", gx.clipmtx)
+	// modGx.Infof("proj mtx: %v", gx.mtx[0])
+	// modGx.Infof("pos mtx: %v", gx.mtx[1])
+	// modGx.Infof("clip mtx: %v", gx.clipmtx)
 }
 
 func (gx *GeometryEngine) cmdNop(parms []GxCmd) {}
@@ -224,7 +227,7 @@ func (gx *GeometryEngine) cmdNop(parms []GxCmd) {}
 
 func (gx *GeometryEngine) cmdMtxMode(parms []GxCmd) {
 	gx.mtxmode = int(parms[0].parm & 3)
-	modGx.Infof("mtx mode: %d", gx.mtxmode)
+	// modGx.Infof("mtx mode: %d", gx.mtxmode)
 }
 
 func (gx *GeometryEngine) cmdMtxLoad4x4(parms []GxCmd) {
@@ -459,7 +462,7 @@ func (gx *GeometryEngine) cmdBeginVtxs(parms []GxCmd) {
 	gx.displist.polyattr = gx.polyattr
 	gx.displist.primtype = int(parms[0].parm & 3)
 	gx.displist.cnt = 0
-	modGx.Infof("begin vtx prim=%d, attr=%08x", gx.displist.primtype, gx.displist.polyattr)
+	// modGx.Infof("begin vtx prim=%d, attr=%08x", gx.displist.primtype, gx.displist.polyattr)
 }
 
 func (gx *GeometryEngine) cmdEndVtxs(parms []GxCmd) {
@@ -551,13 +554,11 @@ func (gx *GeometryEngine) pushVertex(v vector) {
 	gx.displist.lastvtx = v
 	vw := gx.clipmtx.VecMul(v)
 
-	modGx.WithDelayedFields(func() log.Fields {
-		return log.Fields{
-			"obj": fmt.Sprintf("%.2f,%.2f,%.2f", v[0].ToFloat64(), v[1].ToFloat64(), v[2].ToFloat64()),
-			"wrd": fmt.Sprintf("%.2f,%.2f,%.2f,%.2f", vw[0].ToFloat64(), vw[1].ToFloat64(), vw[2].ToFloat64(), vw[3].ToFloat64()),
-			"col": gx.displist.color,
-		}
-	}).Info("vertex")
+	modGx.InfoZ("vertex").
+		Vector12("obj", v).
+		Vector12("wrd", vw).
+		Hex32("rgb", gx.displist.color.To32bit()).
+		End()
 
 	gx.e3d.CmdVertex(raster3d.Primitive_Vertex{
 		X: vw[0], Y: vw[1], Z: vw[2], W: vw[3],
@@ -629,8 +630,7 @@ func (gx *GeometryEngine) cmdVtx16(parms []GxCmd) {
 	v[1].V = int32(int16(parms[0].parm >> 16))
 	v[2].V = int32(int16(parms[1].parm))
 	v[3] = emu.NewFixed12(1)
-	modGx.Infof("v16: %08x %08x -> %v\n", parms[0].parm, parms[1].parm, v)
-
+	modGx.DebugZ("vtx16").Hex32("p0", parms[0].parm).Hex32("p1", parms[1].parm).Vector12("v", v).End()
 	gx.pushVertex(v)
 }
 
@@ -640,8 +640,7 @@ func (gx *GeometryEngine) cmdVtx10(parms []GxCmd) {
 	v[1].V = int32(((parms[0].parm>>10)&0x3FF)<<22) >> 16
 	v[2].V = int32(((parms[0].parm>>20)&0x3FF)<<22) >> 16
 	v[3] = emu.NewFixed12(1)
-	modGx.Infof("v10: %08x -> %v\n", parms[0].parm, v)
-
+	modGx.DebugZ("vtx10").Hex32("p0", parms[0].parm).Vector12("v", v).End()
 	gx.pushVertex(v)
 }
 
@@ -651,8 +650,7 @@ func (gx *GeometryEngine) cmdVtxXY(parms []GxCmd) {
 	v[1].V = int32(int16(parms[0].parm >> 16))
 	v[2].V = gx.displist.lastvtx[2].V
 	v[3] = emu.NewFixed12(1)
-	modGx.Infof("vxy: %08x -> %v\n", parms[0].parm, v)
-
+	modGx.DebugZ("vxy").Hex32("p0", parms[0].parm).Vector12("v", v).End()
 	gx.pushVertex(v)
 }
 
@@ -662,8 +660,7 @@ func (gx *GeometryEngine) cmdVtxXZ(parms []GxCmd) {
 	v[1].V = gx.displist.lastvtx[1].V
 	v[2].V = int32(int16(parms[0].parm >> 16))
 	v[3] = emu.NewFixed12(1)
-	modGx.Infof("vxz: %08x -> %v\n", parms[0].parm, v)
-
+	modGx.DebugZ("vxz").Hex32("p0", parms[0].parm).Vector12("v", v).End()
 	gx.pushVertex(v)
 }
 
@@ -673,8 +670,7 @@ func (gx *GeometryEngine) cmdVtxYZ(parms []GxCmd) {
 	v[1].V = int32(int16(parms[0].parm))
 	v[2].V = int32(int16(parms[0].parm >> 16))
 	v[3] = emu.NewFixed12(1)
-	modGx.Infof("vyz: %08x -> %v\n", parms[0].parm, v)
-
+	modGx.DebugZ("vyz").Hex32("p0", parms[0].parm).Vector12("v", v).End()
 	gx.pushVertex(v)
 }
 
@@ -688,8 +684,7 @@ func (gx *GeometryEngine) cmdVtxDiff(parms []GxCmd) {
 	v[1].V = gx.displist.lastvtx[1].V + yd
 	v[2].V = gx.displist.lastvtx[2].V + zd
 	v[3] = emu.NewFixed12(1)
-	modGx.Infof("vdiff: %08x -> %v\n", parms[0].parm, v)
-
+	modGx.DebugZ("vdiff").Hex32("p0", parms[0].parm).Vector12("v", v).End()
 	gx.pushVertex(v)
 }
 
@@ -758,13 +753,13 @@ func (gx *GeometryEngine) cmdNormal(parms []GxCmd) {
 		if gx.displist.polyattr&(1<<i) == 0 {
 			continue
 		}
-		modGx.WithDelayedFields(func() log.Fields {
-			return log.Fields{
-				"light": gx.lights[i],
-				"diff":  gx.lights[i].dir.Dot(n),
-				"shine": gx.lights[i].half.Dot(n),
-			}
-		}).Infof("light")
+		// modGx.WithDelayedFields(func() log.Fields {
+		// 	return log.Fields{
+		// 		"light": gx.lights[i],
+		// 		"diff":  gx.lights[i].dir.Dot(n),
+		// 		"shine": gx.lights[i].half.Dot(n),
+		// 	}
+		// }).Infof("light")
 		difflvl := gx.lights[i].dir.Dot(n)
 		difflvl.V = -difflvl.V
 		if difflvl.V < 0 {
@@ -790,14 +785,13 @@ func (gx *GeometryEngine) cmdNormal(parms []GxCmd) {
 	}
 
 	gx.displist.color = color.ToClampedColor()
-	modGx.WithDelayedFields(func() log.Fields {
-		return log.Fields{
-			"n":      n,
-			"color":  color,
-			"lights": emu.Hex8(uint8(gx.displist.polyattr & 0xF)),
-			"mat":    gx.material,
-		}
-	}).Infof("normal")
+	modGx.InfoZ("normal").
+		Vector12("n", n).
+		Fixed12("r", color[0]).
+		Fixed12("g", color[1]).
+		Fixed12("b", color[2]).
+		Hex8("lights", uint8(gx.displist.polyattr&0xF)).
+		End()
 }
 
 func (gx *GeometryEngine) cmdShininess(parms []GxCmd) {

irq.go

@@ -53,8 +53,8 @@ func NewHwIrq(name string, cpu *arm.Cpu) *HwIrq {
 	return irq
 }
 
-func (irq *HwIrq) Log() log.Entry {
-	return log.ModIrq.WithField("name", irq.Name)
+func (irq *HwIrq) Log(msg string) *log.EntryZ {
+	return log.ModIrq.InfoZ(msg).String("name", irq.Name)
 }
 
 func (irq *HwIrq) WriteIME(_, _ uint32) {
@@ -63,21 +63,18 @@ func (irq *HwIrq) WriteIME(_, _ uint32) {
 }
 
 func (irq *HwIrq) updateLineStatus() {
-	// if irq.Cpu == nds9.Cpu {
-	// 	irq.Log().Info("", irq.Ime, irq.Ie, irq.If)
-	// }
 	irqstat := irq.Ime.Value != 0 && (irq.Ie.Value&irq.If.Value) != 0
 	if irqstat {
 		if (irq.Ie.Value&irq.If.Value)&^uint32(IrqTimers|IrqVBlank) != 0 {
-			irq.Log().Infof("trigger %08x", irq.If.Value&irq.Ie.Value)
+			irq.Log("trigger").Hex32("value", irq.If.Value&irq.Ie.Value).End()
 		}
 	}
 	irq.Cpu.SetLine(arm.LineIrq, irqstat)
 }
 
 func (irq *HwIrq) WriteIE(_, ie uint32) {
 	if ie&^uint32(IrqVBlank|IrqTimers|IrqIpcRecvFifo) != 0 {
-		irq.Log().Infof("IE: %08x", ie&^uint32(IrqVBlank|IrqTimers|IrqIpcRecvFifo))
+		irq.Log("IE written").Hex32("value", ie&^uint32(IrqVBlank|IrqTimers|IrqIpcRecvFifo)).End()
 	}
 	irq.updateLineStatus()
 }
@@ -88,7 +85,7 @@ func (irq *HwIrq) WriteIF(old, ifx uint32) {
 	// acknowledge the irqs in the write mask
 	irq.If.Value = old &^ ifx
 	if ifx&^uint32(IrqTimers) != 0 {
-		irq.Log().Infof("Irq ACK: %08x", ifx)
+		irq.Log("IRQ ack").Hex32("value", ifx).End()
 	}
 	irq.updateLineStatus()
 }

touchscreen.go

@@ -2,7 +2,6 @@ package main
 
 import (
 	"encoding/binary"
-	"ndsemu/emu"
 	log "ndsemu/emu/logger"
 	"ndsemu/emu/spi"
 )
@@ -40,12 +39,13 @@ func (ff *HwTouchScreen) SpiTransfer(data []byte) ([]byte, spi.ReqStatus) {
 	bits8 := (cmd>>3)&1 != 0
 	adchan := (cmd >> 4) & 7
 
-	modTsc.WithFields(log.Fields{
-		"8bits":   bits8,
-		"ref":     ref,
-		"powdown": powdown,
-		"value":   emu.Hex8(cmd),
-	}).Infof("reading channel %s", tscChanNames[adchan])
+	modTsc.InfoZ("reading channel").
+		String("ch", tscChanNames[adchan]).
+		Hex8("value", cmd).
+		Bool("8bits", bits8).
+		Uint8("ref", ref).
+		Uint8("powdown", powdown).
+		End()
 
 	// Output value is always generated in the 12-bit range, and it is then
 	// optionally truncated to 8 bit