Gratuitous console debug for sgimips O2; trying to zero in on random hard lock up.

netbsd-sgimips-crime-debug

Index: dev/crime.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/dev/crime.c,v
retrieving revision 1.36
diff -u -r1.36 crime.c
--- dev/crime.c  18 Aug 2011 02:56:21 -0000	1.36
+++ dev/crime.c	18 Mar 2013 21:37:00 -0000
@@ -98,6 +98,8 @@
 static void
 crime_attach(device_t parent, device_t self, void *aux)
 {
+	aprint_debug("XXX2013-RPF crime_attach()!\n");
+
 	struct mainbus_attach_args *ma = aux;
 	struct cpu_info * const ci = curcpu();
 	struct crime_softc *sc = device_private(self);
@@ -196,11 +198,18 @@
 crime_intr_establish(int irq, int level, int (*func)(void *), void *arg)
 {
 
-	if (irq < 16)
+	if (irq < 16) {
+		aprint_error("XXX2013-RPF mace_intr_establish(%d, %d) via crime_intr_establish()!\n",
+			irq, level);
+
 		return mace_intr_establish(irq, level, func, arg);
+	}
+	aprint_debug("XXX2013-RPF crime_intr_establish(%d, %d)!\n", irq, level);
 
-	if (crime[irq].func != NULL)
+	if (crime[irq].func != NULL) {
+		aprint_error("XXX2013-RPF crime_intr_establish() crime irq %d: func was NULL!\n", irq);
 		return NULL;	/* panic("Cannot share CRIME interrupts!"); */
+	}
 
 	crime[irq].func = func;
 	crime[irq].arg = arg;
@@ -219,12 +228,16 @@
 	uint64_t address, stat;
 	int i;
 
+	aprint_error("XXX2013-RPF crime_intr(%u, %u, %u)!\n", pc, status, ipending);
 	crime_intmask = bus_space_read_8(crm_iot, crm_ioh, CRIME_INTMASK);
 	crime_intstat = bus_space_read_8(crm_iot, crm_ioh, CRIME_INTSTAT);
 	crime_ipending = (crime_intstat & crime_intmask);
 
-	if (crime_ipending & 0xffff)
+	if (crime_ipending & 0xffff) {
+	 	aprint_error("XXX2013-RPF -> mace_intr(%llu)\n", 
+			crime_ipending & 0xffff);	
 		mace_intr(crime_ipending & 0xffff);
+	}
 
 	if (crime_ipending & 0xffff0000) {
 	/*
@@ -238,6 +251,8 @@
 			printf("crime: memory error address %" PRIu64 
 			    " status %" PRIu64 "\n", address << 2, stat);
 			crime_bus_reset();
+
+			//panic("XXX2013-RPF memory error");
 		}
 
 		if (crime_ipending & CRIME_INT_CRMERR) {
@@ -248,17 +263,32 @@
 				    bus_space_read_8(crm_iot, crm_ioh,
 				    CRIME_CPU_ERROR_ADDR));
 			crime_bus_reset();
+			//panic("XXX2013-RPF cpu error");
 		}
 	}
 
 	crime_ipending &= ~0xffff;
 
 	if (crime_ipending) {
+		aprint_debug("XXX2013-RPF crime_intr crime_ipending %llu\n", crime_ipending);
 		for (i = 16; i < CRIME_NINTR; i++) {
-			if ((crime_ipending & (1 << i)) &&
-			    crime[i].func != NULL)
-				(*crime[i].func)(crime[i].arg);
+
+			if (crime_ipending & (1 << i)) {
+				if (crime[i].func != NULL) {
+					aprint_debug("C%d:->(%llu)(%p) ", 
+						i, crime_ipending & (1 << i),
+						crime[i].func);
+					(*crime[i].func)(crime[i].arg);
+				} else {
+					aprint_debug("XXX2013-RPF crime_intr GOOD CATCH at [%d]\n", i);
+				}
+			} else {
+				aprint_debug("C%d:%llu ", i, crime_ipending & (1 << i));
+			}
 		}
+		aprint_debug("done\n");
+	} else {
+		aprint_debug("XXX2013-RPF <- !crime_ipending %llu\n", crime_ipending);
 	}
 }
 
@@ -266,7 +296,7 @@
 crime_intr_mask(unsigned int intr)
 {
 	uint64_t mask;
-
+	aprint_debug("XXX2013-RPF crime_intr_mask(%d)!\n", intr);
 	mask = bus_space_read_8(crm_iot, crm_ioh, CRIME_INTMASK);
 	mask |= (1 << intr);
 	bus_space_write_8(crm_iot, crm_ioh, CRIME_INTMASK, mask);
@@ -277,6 +307,7 @@
 {
 	uint64_t mask;
 
+	aprint_debug("XXX2013-RPF crime_intr_unmask(%d)!\n", intr);
 	mask = bus_space_read_8(crm_iot, crm_ioh, CRIME_INTMASK);
 	mask &= ~(1 << intr);
 	bus_space_write_8(crm_iot, crm_ioh, CRIME_INTMASK, mask);
@@ -285,15 +316,19 @@
 void
 crime_bus_reset(void)
 {
+	aprint_error("XXX2013-RPF: crime_bus_reset ...\n");
 
 	bus_space_write_8(crm_iot, crm_ioh, CRIME_CPU_ERROR_STAT, 0);
 	bus_space_write_8(crm_iot, crm_ioh, CRIME_MEM_ERROR_STAT, 0);
+
+	aprint_error("XXX2013-RPF: crime_bus_reset done!\n");
 }
 
 void
 crime_watchdog_reset(void)
 {
 
+//	printf("XXX2013-RPF crime_watchdog_reset()!\n");
 #ifdef DISABLE_CRIME_WATCHDOG
 	bus_space_write_8(crm_iot, crm_ioh, CRIME_WATCHDOG, 0);
 #else
@@ -309,6 +344,7 @@
 {
 	uint64_t reg;
 
+	aprint_debug("XXX2013-RPF crime_watchdog_disable()!\n");
 	bus_space_write_8(crm_iot, crm_ioh, CRIME_WATCHDOG, 0);
 	reg = bus_space_read_8(crm_iot, crm_ioh, CRIME_CONTROL)
 	    & ~CRIME_CONTROL_DOG_ENABLE;
@@ -319,6 +355,7 @@
 crime_reboot(void)
 {
 
+	aprint_debug("XXX2013-RPF crime_reboot()!\n");
 	bus_space_write_8(crm_iot, crm_ioh,  CRIME_CONTROL,
 	    CRIME_CONTROL_HARD_RESET);
 	for (;;)
Index: dev/zs_kgdb.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/dev/zs_kgdb.c,v
retrieving revision 1.15
diff -u -r1.15 zs_kgdb.c
--- dev/zs_kgdb.c	18 Mar 2009 10:22:35 -0000	1.15
+++ dev/zs_kgdb.c	18 Mar 2013 21:37:00 -0000
@@ -137,7 +137,7 @@
 	unit = (kgdb_dev & 2) ? 1 : 0;	/* XXX ??? */
 	channel = kgdb_dev & 1;
 	printf("zs_kgdb_init: attaching to Serial(%d) at %d baud\n",
-		   (kgdb_dev & 3), kgdb_rate);
+		   (int)(kgdb_dev & 3), (int)kgdb_rate);
 
 	zc = zs_get_chan_addr(unit, channel);
 
Index: mace/mace.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/mace/mace.c,v
retrieving revision 1.19
diff -u -r1.19 mace.c
--- mace/mace.c	27 Oct 2012 17:18:10 -0000	1.19
+++ mace/mace.c	18 Mar 2013 21:37:00 -0000
@@ -132,8 +132,11 @@
 	struct mainbus_attach_args *ma = aux;
 	uint32_t scratch;
 
+	aprint_debug("XXX2013-RPF mace_attach()\n");
+
 	sc->sc_dev = self;
 #ifdef BLINK
+	aprint_debug("XXX2013-RPF mace_attach() setting BLINK\n");
 	callout_init(&mace_blink_ch, 0);
 #endif
 
@@ -233,10 +236,15 @@
 {
 	int i;
 
+
+	aprint_debug("XXX2013-RPF mace_intr_establish(%d, %d)!\n", intr, level);
+
 	if (intr < 0 || intr >= 16)
 		panic("invalid interrupt number");
 
-	for (i = 0; i < MACE_NINTR; i++)
+	for (i = 0; i < MACE_NINTR; i++) {
+		aprint_debug("XXX2013-RPF mace_intr_establish(%d, %d)!: [%d] \n",
+			 intr, level, i);
 		if (maceintrtab[i].func == NULL) {
 		        maceintrtab[i].func = func;
 		        maceintrtab[i].arg = arg;
@@ -248,8 +256,10 @@
 			evcnt_attach_dynamic(&maceintrtab[i].evcnt,
 			    EVCNT_TYPE_INTR, NULL,
 			    "mace", maceintrtab[i].evname);
+			aprint_debug("XXX2013-RPF [%d] installing handler irq %d level %d: %s\n", i, (1 << intr), level, maceintrtab[i].evname);
 			break;
 		}
+        }
 
 	crime_intr_mask(intr);
 	aprint_debug("mace: established interrupt %d (level %x)\n",
@@ -262,8 +272,11 @@
 {
 	int intr = -1, level = 0, irq = 0, i;
 
+	aprint_debug("XXX2013-RPF mace_intr_disestablish()!\n");
 	for (i = 0; i < MACE_NINTR; i++)
+		
 		if (&maceintrtab[i] == cookie) {
+			aprint_debug("XXX2013-RPF +++ [%d] matched cookie(%s)\n", i, maceintrtab[i].evname);
 			evcnt_detach(&maceintrtab[i].evcnt);
 			for (intr = 0;
 			    maceintrtab[i].irq == (1 << intr); intr++);
@@ -300,25 +313,58 @@
 
 	/* irq 4 is the ISA cascade interrupt.  Must handle with care. */
 	if (irqs & (1 << 4)) {
+		aprint_debug("XXX2013-RPF -> IRQ4 mace_intr(%d) is IRQ 4!!! \n", irqs);
+
 		isa_mask = mips3_ld((volatile uint64_t *)MIPS_PHYS_TO_KSEG1(MACE_BASE
 		    + MACE_ISA_INT_MASK));
 		isa_irq = mips3_ld((volatile uint64_t *)MIPS_PHYS_TO_KSEG1(MACE_BASE
 		    + MACE_ISA_INT_STATUS));
+
+		aprint_debug("XXX2013-RPF -> IRQ4 mace_intr(%d) completed mips3_ld() \n", irqs);
+		
 		for (i = 0; i < MACE_NINTR; i++) {
+
 			if ((maceintrtab[i].irq == (1 << 4)) &&
-			    (isa_irq & maceintrtab[i].intrmask)) {
-		  		(maceintrtab[i].func)(maceintrtab[i].arg);
-				maceintrtab[i].evcnt.ev_count++;
-	        	}
+					(isa_irq & maceintrtab[i].intrmask)) {
+				if (maceintrtab[i].func != NULL) {
+					aprint_debug("M4:%d:->(%p) ", i, maceintrtab[i].func);
+					(maceintrtab[i].func)(maceintrtab[i].arg);
+					maceintrtab[i].evcnt.ev_count++;
+				} else {
+					aprint_debug("XXX2013-RPF IRQ4 GOOD CATCH at [%d] irq %d;\n",
+						i, irqs);
+				}
+			} else {
+				aprint_debug("M4:%d:%d ", i, irqs);
+			}
 		}
+		aprint_debug("done\n");
 		irqs &= ~(1 << 4);
 	}
 
-	for (i = 0; i < MACE_NINTR; i++)
+	aprint_debug("XXX2013-RPF -> mace_inst(%d): processing non-IRQ 4\n", irqs);
+
+	for (i = 0; i < MACE_NINTR; i++) {
+
 		if ((irqs & maceintrtab[i].irq)) {
-		  	(maceintrtab[i].func)(maceintrtab[i].arg);
+
+			if (maceintrtab[i].func != NULL) {
+
+				aprint_debug("M%d:->(%p) ", i, maceintrtab[i].func);
+
+				(maceintrtab[i].func)(maceintrtab[i].arg);
+
+			} else {
+				aprint_debug("XXX2013-RPF GOOD CATCH at [%d] irq %d;\n",
+					i, irqs);
+			}
+
 			maceintrtab[i].evcnt.ev_count++;
+		} else {
+			aprint_debug("M%d:%d ", i, irqs);
 		}
+	}
+	aprint_debug("done\n");
 }
 
 #if defined(BLINK)
Index: mace/mavb.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/mace/mavb.c,v
retrieving revision 1.9
diff -u -r1.9 mavb.c
--- mace/mavb.c	27 Oct 2012 17:18:10 -0000	1.9
+++ mace/mavb.c	18 Mar 2013 21:37:01 -0000
@@ -38,7 +38,8 @@
 
 #include <dev/ic/ad1843reg.h>
 
-#undef MAVB_DEBUG
+/* #undef MAVB_DEBUG */
+#define MAVB_DEBUG
 
 #ifdef MAVB_DEBUG
 #define DPRINTF(l,x)	do { if (mavb_debug & (l)) printf x; } while (0)
Index: sgimips/bus.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/sgimips/bus.c,v
retrieving revision 1.65
diff -u -r1.65 bus.c
--- sgimips/bus.c	2 Oct 2012 23:54:54 -0000	1.65
+++ sgimips/bus.c	18 Mar 2013 21:37:01 -0000
@@ -906,9 +906,12 @@
 		addr = map->dm_segs[i].ds_addr;
 
 #ifdef BUS_DMA_DEBUG
+		aprint_debug("XXX2013-RPF _bus_dmamap_sync_mips1: flushing segment %d\n", i);
+/*
 		printf("bus_dmamap_sync_mips1: flushing segment %d "
 		    "(0x%lx..0x%lx) ...", i, addr + offset,
 		    addr + offset + minlen - 1);
+*/
 #endif
 		mips_dcache_inv_range(
 		    MIPS_PHYS_TO_KSEG0(addr + offset), minlen);
@@ -1019,9 +1022,14 @@
 		vaddr = map->dm_segs[i]._ds_vaddr;
 
 #ifdef BUS_DMA_DEBUG
+
+		aprint_debug("XXX2013-RPF _bus_dmamap_sync_mips3: flushing segment %d ", i);
+
+/*
 		printf("bus_dmamap_sync_mips3: flushing segment %d "
 		    "(0x%lx+%lx, 0x%lx+0x%lx) (olen = %ld)...", i,
 		    vaddr, offset, vaddr, offset + minlen - 1, len);
+*/
 #endif
 
 		/*
@@ -1071,6 +1079,7 @@
 		}
 #ifdef BUS_DMA_DEBUG
 		printf("\n");
+
 #endif
 		offset = 0;
 		len -= minlen;
Index: sgimips/console.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/sgimips/console.c,v
retrieving revision 1.43
diff -u -r1.43 console.c
--- sgimips/console.c	13 Oct 2012 17:58:54 -0000	1.43
+++ sgimips/console.c	18 Mar 2013 21:37:01 -0000
@@ -222,6 +222,8 @@
 		base = (consdev[7] == '0') ? MACE_ISA_SER1_BASE :
 		    MACE_ISA_SER2_BASE;
 
+		aprint_debug("XXX2013-RPF  mace_serial_init: dbaud %s; speed %d\n", dbaud, speed);
+
 		delay(10000);
 
 		/* XXX: hardcoded MACE iotag */
@@ -240,9 +242,11 @@
 {
 # if (NCOM > 0)
 #  define KGDB_DEVMODE ((TTYDEF_CFLAG & ~(CSIZE | CSTOPB | PARENB)) | CS8)
-	if (mach_type == MACH_SGI_IP32)
+	if (mach_type == MACH_SGI_IP32) {
+		aprint_debug("XXX2013-RPF kgdb_port_init\n");
 		com_kgdb_attach(SGIMIPS_BUS_SPACE_MACE, 0xbf398000, 9600, COM_FREQ, COM_TYPE_NORMAL,
 		    KGDB_DEVMODE);
+        }
 # endif	/* (NCOM > 0) */
 
 # if (NZSC > 0)
Index: sgimips/machdep.c
===================================================================
RCS file: /cvsroot/src/sys/arch/sgimips/sgimips/machdep.c,v
retrieving revision 1.138
diff -u -r1.138 machdep.c
--- sgimips/machdep.c	27 Oct 2012 17:18:10 -0000	1.138
+++ sgimips/machdep.c	18 Mar 2013 21:37:01 -0000
@@ -332,6 +332,8 @@
 
 	cpufreq = arcbios_GetEnvironmentVariable("cpufreq");
 
+	aprint_debug("XXX2013-RPF mach_init(): CPUFREQ %s\n", cpufreq);
+
 	if (cpufreq == 0)
 		panic("no $cpufreq");
 
@@ -906,10 +908,12 @@
 {
 	switch (where) {
 	case 1:		/* Entry to DDB, turn watchdog off */
+		aprint_debug("XXX2013-RPF dbb_trap_hook enabled\n");
 		(void)(*platform.watchdog_disable)();
 		break;
 
 	case 0:		/* Exit from DDB, turn watchdog back on */
+		aprint_debug("XXX2013-RPF dbb_trap_hook disabled\n");
 		(void)(*platform.watchdog_enable)();
 		break;
 	}