IP27 lock up issue, maybe timer related?

IP27 lock up issue, maybe timer related?

[Joshua Kinard]

Some more digging I did over the weekend on the IP27 lock up issue led to some
new observations.

First off, I ended up changing the IRIX-style HUB_S/HUB_L macros to use
__raw_readq/__raw_writeq, since I know those versions disable local interrupts,
and was running out of ideas to try.  That appears to have cleaned up the
register state when I crash the machine and I appear to get usable data out of
several registers now (but I have to send an NMI to the CPU first, so it's some
neat hardware trick).

This leads to only one CPU appearing to be affected either by a data bus error
or getting "stuck".  Stuck meaning, in a few instances, three CPUs were last in
an idle loop and one was at the bottom of arch_local_irq_restore from
arch/mips/lib/mips-atomic.c.  In other instances, two or more CPUs were stuck
in arch_local_irq_restore.

In the stuck case, a constant theme I keep noticing is one of the register
values holds the address 0x9200000001030100, which is PI_RT_COUNT in I/O space
(Hub's realtime counter) on node 1.  It looks like some kind of clash where a
previous timer interrupt is leaving behind stale data in the registers, and the
resumed state of the CPU tries to use that data and halts.  E.g., in one crash
using a mainline kernel with minor patching to make it work, this is the POD
"why" and register dump off CPU 2A and 2B (node 1, or 2nd node board):

2A 000: POD MSC Dex> why
2A 000:  EPC    : 0xa800000000326fa8 (0xa800000000326fa8)
2A 000:  ERREPC : 0xc00000001fc5ad5c (0xc00000001fc5ad5c)
2A 000:  CACERR : 0x0000000000012108
2A 000:  Status : 0x0000000024407c80
2A 000:  BadVA  : 0xc0000000009c55c8 (0xc0000000009c55c8)
2A 000:  RA     : 0xc00000001fc13500 (0xc00000001fc13500)
2A 000:  SP     : 0xa800000000103650
2A 000:  A0     : 0x0000000024400080
2A 000:  Cause  : 0x0000000000008000 (INT:8-------)
2A 000:  Reason : 249 (NMI while executing in PROM.)
2A 000:  POD mode was called from: 0xc00000001fc02508 (0xc00000001fc02508)

2A 000: POD MSC Dex> pr
2A 000: r00/r0: 0x0000000000000000    r01/at: 0x0000000000000000
2A 000: r02/v0: 0x0000000000000000    r03/v1: 0x0000000000000001
2A 000: r04/a0: 0x0000000024400080    r05/a1: 0xffff920000000103
2A 000: r06/a2: 0x000000000000000a    r07/a3: 0x0000000000000000
2A 000: r08/a4: 0x0000000000000000    r09/a5: 0x0000000000000020
2A 000: r10/a6: 0xa8000000001036e0    r11/a7: 0x0000000000000000
2A 000: r12/t0: 0x000000000000002a    r13/t1: 0x000000000000004c
2A 000: r14/t2: 0x0000000000000068    r15/t3: 0x00000140a4436020
2A 000: r16/s0: 0x0000000000dd7210    r17/s1: 0x000000000000008c
2A 000: r18/s2: 0xffffffffffffffff    r19/s3: 0xc00000001fc74d70
2A 000: r20/s4: 0x00000000000f4240    r21/s5: 0xa800000000103a0f
2A 000: r22/s6: 0x0000000000000000    r23/s7: 0x00000000000000fc
2A 000: r24/t8: 0x0000000000000001    r25/t9: 0x0000000000000001
2A 000: r26/k0: 0x9200000001220050    r27/k1: 0x000000000000001e
2A 000: r28/gp: 0xc00000001fce5028    r29/sp: 0xa800000000103650
2A 000: r30/fp: 0x0000000000000000    r31/ra: 0xc00000001fc13500

2B 000: POD MSC Dex> why
2B 000:  EPC    : 0xa800000000326fa8 (0xa800000000326fa8)
2B 000:  ERREPC : 0xc00000001fc5ad4c (0xc00000001fc5ad4c)
2B 000:  CACERR : 0x0000000008080c10
2B 000:  Status : 0x0000000024407c80
2B 000:  BadVA  : 0xc0000000007f8768 (0xc0000000007f8768)
2B 000:  RA     : 0xc00000001fc398d8 (0xc00000001fc398d8)
2B 000:  SP     : 0xa8000000001033e0
2B 000:  A0     : 0x0000000024400080
2B 000:  Cause  : 0x0000000000008000 (INT:8-------)
2B 000:  Reason : 249 (NMI while executing in PROM.)
2B 000:  POD mode was called from: 0xc00000001fc02508 (0xc00000001fc02508)

2B 000: r00/r0: 0x0000000000000000    r01/at: 0x0000000000000000
2B 000: r02/v0: 0x00000000000000fe    r03/v1: 0x0000000000000001
2B 000: r04/a0: 0x0000000024400080    r05/a1: 0x9200000001030100
2B 000: r06/a2: 0x000000000000000a    r07/a3: 0x0000000000000000
2B 000: r08/a4: 0x0000000000000002    r09/a5: 0xa800000000103578
2B 000: r10/a6: 0x0000000000000060    r11/a7: 0xa8000000001035d8
2B 000: r12/t0: 0x00000000000f4240    r13/t1: 0x0000000000000002
2B 000: r14/t2: 0x0000000000000001    r15/t3: 0x0000000000000001
2B 000: r16/s0: 0x9200000001a20000    r17/s1: 0x00000000000000e3
2B 000: r18/s2: 0x00000000000000eb    r19/s3: 0x00000000011ad00c
2B 000: r20/s4: 0x00000000000000eb    r21/s5: 0x0000000000000000
2B 000: r22/s6: 0x0000000000000000    r23/s7: 0x00000000000000fc
2B 000: r24/t8: 0x0000000000000004    r25/t9: 0x0000000000000001
2B 000: r26/k0: 0x9200000001220058    r27/k1: 0x000000000000001e
2B 000: r28/gp: 0xc00000001fce5028    r29/sp: 0xa8000000001033e0
2B 000: r30/fp: 0x0000000000000000    r31/ra: 0xc00000001fc398d8

The address 0xa800000000326fa8 in both CPU's EPC register is
arch_local_irq_restore, line 109:

    a800000000326f90 <arch_local_irq_restore>:
    a800000000326f90:       40016000        mfc0    at,$12
    a800000000326f94:       30840001        andi    a0,a0,0x1
    a800000000326f98:       3421001f        ori     at,at,0x1f
    a800000000326f9c:       3821001f        xori    at,at,0x1f
    a800000000326fa0:       00812025        or      a0,a0,at
    a800000000326fa4:       40846000        mtc0    a0,$12
--> a800000000326fa8:       03e00008        jr      ra
    a800000000326fac:       00000000        nop

This bit of assembly only uses registers a0 and at, which in the above register
dump, a0 appears to hold some older value of $12 (CP0_STATUS), and at is
zero'ed out (possibly from the NMI restart).  Additionally, k0 is pointing at
the I/O address for a LED soldered on the node board for each CPU, and for CPU
2B, s0 holds an I/O address to HUB's MD register space, specifically the MSC
UART (so both are probably junk data from my use of MSC in POD Dex mode).

What's interesting to me in this specific instance is register a1 on CPU 2B
holds PI_RT_COUNT (0x9200000001030100), but on CPU 2A, the same value looks
like it's been overwritten by shifting right 16 bits and 63:48 filled in with
1's.  That's not used by arch_local_irq_restore, but it may have been used by a
previous state of the CPU, which is why I suspect the registers are getting
accidentally clobbered.

The constant theme is seeing PI_RT_COUNT's address popping into registers that
look like they contain data from other CPU states, which suggests to me that
it's some kind of race that may involve changing the CPU's interrupt state as
well as the IP27 timer code, because I know that on IP27, we have one counter,
but two compare registers, and the timer interrupt is always firing.  However,
in hub_rt_read, all reads from PI_RT_COUNT appear to be locked to the first CPU
on the nodeboard via REMOTE_HUB_L:

static u64 hub_rt_read(struct clocksource *cs)
{
	return REMOTE_HUB_L(cputonasid(0), PI_RT_COUNT);
}

I wonder if this clashes at all with rt_next_event, in which both CPUs can
access PI_RT_COUNT locally with LOCAL_HUB_L:

static int rt_next_event(unsigned long delta, struct clock_event_device *evt)
{
	unsigned int cpu = smp_processor_id();
	int slice = cputoslice(cpu);
	unsigned long cnt;

	cnt = LOCAL_HUB_L(PI_RT_COUNT);
	cnt += delta;
	LOCAL_HUB_S(PI_RT_COMPARE_A + PI_COUNT_OFFSET * slice, cnt);

	return LOCAL_HUB_L(PI_RT_COUNT) >= cnt ? -ETIME : 0;
}

If you take this as a possible contention point, and then hammer the system
with lots of I/O activity, such as writing out a large file to disk, and maybe
keep transmitting data over serial or ethernet, you get to a point where you
somehow deadlock the HUB on a specific nodeboard.  Which stops the system dead
because Linux doesn't currently set up detailed HUB link error reporting, so we
don't get signaled about one HUB losing contact with the other HUB.

Does that sound at all plausible?

-- 
Joshua Kinard
Gentoo/MIPS
kumba@gentoo.org
6144R/F5C6C943 2015-04-27
177C 1972 1FB8 F254 BAD0 3E72 5C63 F4E3 F5C6 C943

"The past tempts us, the present confuses us, the future frightens us.  And our
lives slip away, moment by moment, lost in that vast, terrible in-between."

--Emperor Turhan, Centauri Republic