Skip site navigation (1)Skip section navigation (2)
Date:      Sat, 20 May 2017 02:01:55 -0700
From:      Mark Millard <markmi@dsl-only.net>
To:        Justin Hibbits <jhibbits@FreeBSD.org>, Nathan Whitehorn <nwhitehorn@freebsd.org>
Cc:        FreeBSD PowerPC ML <freebsd-ppc@freebsd.org>, FreeBSD Current <freebsd-current@freebsd.org>
Subject:   Re: TARGET_ARCH=powerpc head -r317820 production-style kernel: periodic panics always in pid=11 (the Idle threads)
Message-ID:  <81F7A2D8-4C3A-426D-B957-9DC937006D88@dsl-only.net>
In-Reply-To: <1F50B6D9-4E41-4367-860D-E2A0E13AE661@dsl-only.net>
References:  <831804AB-1BEB-40C7-BA8B-94DF07E314E5@dsl-only.net> <1F50B6D9-4E41-4367-860D-E2A0E13AE661@dsl-only.net>

next in thread | previous in thread | raw e-mail | index | archive | help
On 2017-May-19, at 9:42 PM, Mark Millard <markmi@dsl-only.net> wrote:

> On 2017-May-9, at 2:00 PM, Mark Millard <markmi@dsl-only.net> wrote:
>=20
> . . .
>> fatal kernel trap:
>>  exception       =3D 0x903a64e (unknown)
>>  srr0            =3D 0x7ff760
>>  srr1            =3D 0xc1007c
>>  lr              =3D 0x907f
>>  curthread       =3D 0x147d6c0
>>         pid =3D 11, comm =3D idle: cpu0
>> [ thread pid 11 tid 100003 ]
>> Stopped at      ffs_truncate+0x1080:    stw     r11, 0xf8(r31)
>>=20
>> 1 contains (cpu1 instead of cpu0, so different tid):
>>=20
>> fatal kernel trap:
>>  exception       =3D 0x903a64e (unknown)
>>  srr0            =3D 0x7ff760
>>  srr1            =3D 0xc1007c
>>  lr              =3D 0x907f
>>  curthread       =3D 0x147d360
>>         pid =3D 11, comm =3D idle: cpu1
>> [ thread pid 11 tid 100004 ]
>> Stopped at      ffs_truncate+0x1080:    stw     r11, 0xf8(r31)
>>=20
>> 1 contains:
>=20
> I've discovered where to find the trapframe
> in the vmcore.* files for these specific
> examples with 0x903a64e as the exception
> and such.
>=20
> In the vmcore the memory image starts at
> byte offset 0x1000.
>=20
> To see the values reported the only
> place in the image file to start that
> produces those values at the offsets
> for in side the powerpc trapframe is:
>=20
> offset 0x1001 in the vmcore.* file.
>=20
> So memory address 0x1 is being used
> as the trapframe address when that
> odd exception information is being
> displayed. Yep: misaligned.
>=20
> The decoding is not of the actual
> trapframe: it is garbage that is
> not to be believed.
>=20
>=20
> Note: I lucked out after the above and
> got a somewhat different odd trap information
> that lead to actually getting a backtrace
> that included the actual pid 11 cpu 1 kernel
> thread stack bt associated with that odd
> information display.

Typo: That should have been "cpu 2".

> I'll send a separate reply for that information
> as it will take some transcribing from camera
> pictures and such.


As indicated, I got a different odd trap report
that gave a backtrace. . .

fatal user trap

exception =3D 0x4210000 (unknown)
srr0      =3D 0xc1007c09
srr1      =3D 0x3a64e80
lr        =3D 0xc0807fc9
curthread =3D 0x147d000
pid =3D 11, comm =3D idle: cpu 2

Now at this point it attempted to
db_print_loc_and_inst and got
another exception (at offset +0x60
in the routine).

So the backtrace has both the
consequences of that and what lead
up to that: an EXI trap was
attempting to report trap frame
information but was using a bad
address for the supposed frame.

The details of the backtrace:

panic: data storage interrupt trap
cpuid =3D 2
time =3D 145187154
KDB: stack backtrace
0xdf5ef2c0: at kdb_backtrace+0x5c
0xdf5ef3a0: at panic+0x54
0xdf5ef3f0: at trap_fatal+0x1cc
0xdf5ef420: at powerpc_interrupt+0x180
0xdf5ef5c0: kernel DSI read trap @ 0xc1007c09
            by db_disasm+0x30:
            srr1=3D0x1032
            r1  =3D0xdf5ef6b0
            cr  =3D0x24009022
            xer =3D0
            ctr =3D0x1852cc
            sr  =3D0x40000000
0xdf5ef6b0: at 0x1007480
0xdf5ef6d0: at db_print_loc_and_inst+0x60
0xdf5ef700: at db_trap+0x104
0xdf5ef790: at kdb_trap+0x1bc
0xdf5ef810: at trap_fatal+0x1b0
0xdf5ef840: at trap+0x1184
0xdf5ef870: kernel EXI trap
            by cpu_idle_60x+0x88:
            srr1=3D0x1032
            r1  =3D0xdf5ef930
            cr  =3D0x40000042
            xer =3D0x20000000
            ctr =3D0x8e3bd8
saved LR(0x2) is invalid.

So an EXI trap was attempting to
report a trap frame.

(Note: the LR's for pid 11 cpu threads
normally report an invalid LR in ddb.)



The actual EXI trapframe starts at 013f0878 in
vmcore.5:

013f0870  df 5e f9 30 00 10 08 f8  00 04 90 32 df 5e f9 30  =
|.^.0.......2.^.0|
013f0880  01 47 d0 00 00 00 00 00  25 94 48 3f 00 00 00 00  =
|.G......%.H?....|
013f0890  25 94 48 3f 00 4a a9 c8  00 00 00 00 00 00 00 44  =
|%.H?.J.........D|
013f08a0  01 fc a0 55 00 00 90 32  df 5d 1d 00 00 00 00 00  =
|...U...2.]......|
013f08b0  00 d4 bd ec 00 cb 98 98  00 c9 66 bc 00 c4 5d 08  =
|..........f...].|
013f08c0  00 c9 66 bc 00 d4 c5 3c  df 5e f9 e0 00 eb a7 80  =
|..f....<.^......|
013f08d0  00 c9 66 bc 01 47 d0 00  df 5e f9 8c 00 00 00 06  =
|..f..G...^......|
013f08e0  00 00 00 06 00 eb b5 80  00 00 00 00 00 8e 3b d8  =
|..............;.|
013f08f0  00 d2 6b f0 df 5e f9 30  00 8e 3b f4 40 00 00 42  =
|..k..^.0..;.@..B|
013f0900  20 00 00 00 00 8e 3b d8  00 8e 3c 60 00 00 90 32  | =
.....;...<`...2|
013f0910  00 00 05 00 41 a1 d5 d4  42 00 00 00 00 00 00 00  =
|....A...B.......|

So:

r0    =3D 0x00049032
r1    =3D 0xdf5ef930
r2    =3D 0x0147d000
r3    =3D 0x00000000
r4    =3D 0x2594483f
r5    =3D 0x00000000
r6    =3D 0x2594483f
r7    =3D 0x004aa9c8
r8    =3D 0x00000000
r9    =3D 0x00000044
r10   =3D 0x01fca055
r11   =3D 0x00009032
r12   =3D 0xdf5d1d00
r13   =3D 0x00000000
r14   =3D 0x00d4bdec
r15   =3D 0x00cb9898
r16   =3D 0x00c966bc
r17   =3D 0x00c45d08
r18   =3D 0x00c966bc
r19   =3D 0x00d4c53c
r20   =3D 0xdf5ef9e0
r21   =3D 0x00eba780
r22   =3D 0x00c966bc
r23   =3D 0x1047d000
r24   =3D 0xdf5ef98c
r25   =3D 0x00000006 (this value shows up later in a bad spot)
r26   =3D 0x00000006 (this value shows up next to that)
r27   =3D 0x00ebb580
r28   =3D 0x00000000
r29   =3D 0x008e3bd8
r30   =3D 0x00d26bf0
r31   =3D 0xdf5ef930
lr    =3D 0x008e3bf4
cr    =3D 0x40000042
xer   =3D 0x20000000
ctr   =3D 0x008e3bd8
srr0  =3D 0x008e3c60
srr1  =3D 0x00009032
exc   =3D 0x00000500
dar   =3D 0x41a1d5d4
dsisr =3D 0x42000000

Other elements of the stack leading to this are:

013f0920  45 8b a7 b5 b1 fd 96 be  00 00 00 00 00 00 00 04  =
|E...............|
013f0930  df 5e f9 50 00 00 00 06  00 00 00 06 00 eb b5 80  =
|.^.P............|
                    (odd lr value; value repeats
                     above, not  ; here. r25/r26
                     a multiple  ; pair saved
                     of 4 even.  ; in those?
                     matches r25 ; matches r26
                     in trapframe; in trapframe)

013f0940  00 00 00 00 00 d4 ca 34  00 d2 6b f0 df 5e f9 50  =
|.......4..k..^.P|
013f0950  df 5e f9 70 00 8e 31 7c  00 00 00 02 00 eb b5 80  =
|.^.p..1|........|
013f0960  00 f2 d5 fc 00 00 00 06  00 d1 ca ac df 5e f9 70  =
|.............^.p|
013f0970  df 5e fa 50 00 53 6e 58  df 5e f9 80 00 00 00 00  =
|.^.P.SnX.^......|
. . .
013f0a50  df 5e fa 80 00 4a 3c b4  df 5e fa 60 fa 50 05 af  =
|.^...J<..^.`.P..|
013f0a60  df 5e fa 80 00 00 00 00  00 00 00 00 00 00 00 00  =
|.^..............|
013f0a70  00 00 00 00 00 00 00 00  00 00 00 00 00 00 00 00  =
|................|
013f0a80  00 00 00 00 00 8f 18 90  00 53 69 84 00 00 00 00  =
|.........Si.....|

=46rom which I get from the stack
backpointer/lr-value pairs(via objdump
on the kernel):

00000006: ????????????????????
008e317c: cpu_idle+0x58
00536e58: scheduletd+0x4d4
004a3cb4: fork_exit+0xf8
008f1890: fork_trampoline+0x10

But cpu_idle+0x58 is the bl ,cpu_activeclock>
in the below and the prior bctrl after
the bl <cpu_idleclock> is what made the
call.

008e3124 <cpu_idle> stwu    r1,-32(r1)
008e3128 <cpu_idle+0x4> mflr    r0
008e312c <cpu_idle+0x8> stw     r29,20(r1)
008e3130 <cpu_idle+0xc> stw     r30,24(r1)
008e3134 <cpu_idle+0x10> stw     r31,28(r1)
008e3138 <cpu_idle+0x14> stw     r0,36(r1)
008e313c <cpu_idle+0x18> mr      r31,r1
008e3140 <cpu_idle+0x1c> bcl-    20,4*cr7+so,008e3144 <cpu_idle+0x20>
008e3144 <cpu_idle+0x20> mflr    r30
008e3148 <cpu_idle+0x24> lwz     r0,-36(r30)
008e314c <cpu_idle+0x28> add     r30,r0,r30
008e3150 <cpu_idle+0x2c> lwz     r29,-32768(r30)
008e3154 <cpu_idle+0x30> lwz     r0,0(r29)
008e3158 <cpu_idle+0x34> cmpwi   cr7,r0,0
008e315c <cpu_idle+0x38> beq-    cr7,008e3198 <cpu_idle+0x74>
008e3160 <cpu_idle+0x3c> cmpwi   cr7,r3,0
008e3164 <cpu_idle+0x40> bne-    cr7,008e3188 <cpu_idle+0x64>
008e3168 <cpu_idle+0x44> bl      005002a4 <critical_enter>
008e316c <cpu_idle+0x48> bl      008ad894 <cpu_idleclock>
008e3170 <cpu_idle+0x4c> lwz     r29,0(r29)
008e3174 <cpu_idle+0x50> mtctr   r29
008e3178 <cpu_idle+0x54> bctrl
008e317c <cpu_idle+0x58> bl      008ad794 <cpu_activeclock>

But ctr was reported as: 0x8e3bd8
which is cpu_idle_60x.

(So no surprises so far.)

The code through the reported cpu_idle_60x+0x88
is:

008e3bd8 <cpu_idle_60x> stwu    r1,-32(r1)
008e3bdc <cpu_idle_60x+0x4> mflr    r0
008e3be0 <cpu_idle_60x+0x8> stw     r30,24(r1)
008e3be4 <cpu_idle_60x+0xc> stw     r31,28(r1)
008e3be8 <cpu_idle_60x+0x10> stw     r0,36(r1)
008e3bec <cpu_idle_60x+0x14> mr      r31,r1
008e3bf0 <cpu_idle_60x+0x18> bcl-    20,4*cr7+so,008e3bf4 =
<cpu_idle_60x+0x1c>
008e3bf4 <cpu_idle_60x+0x1c> mflr    r30
008e3bf8 <cpu_idle_60x+0x20> lwz     r0,-32(r30)
008e3bfc <cpu_idle_60x+0x24> add     r30,r0,r30
008e3c00 <cpu_idle_60x+0x28> lwz     r9,-32756(r30)
008e3c04 <cpu_idle_60x+0x2c> lwz     r0,0(r9)
008e3c08 <cpu_idle_60x+0x30> cmpwi   cr7,r0,0
008e3c0c <cpu_idle_60x+0x34> beq-    cr7,008e3c78 <cpu_idle_60x+0xa0>
008e3c10 <cpu_idle_60x+0x38> mfmsr   r11
008e3c14 <cpu_idle_60x+0x3c> mfsprg  r0,7
008e3c18 <cpu_idle_60x+0x40> rlwinm  r9,r0,16,16,31
008e3c1c <cpu_idle_60x+0x44> cmpwi   cr7,r9,68
008e3c20 <cpu_idle_60x+0x48> beq-    cr7,008e3c4c <cpu_idle_60x+0x74>
008e3c24 <cpu_idle_60x+0x4c> cmplwi  cr7,r9,68
008e3c28 <cpu_idle_60x+0x50> bgt-    cr7,008e3c40 <cpu_idle_60x+0x68>
008e3c2c <cpu_idle_60x+0x54> cmpwi   cr7,r9,57
008e3c30 <cpu_idle_60x+0x58> beq-    cr7,008e3c4c <cpu_idle_60x+0x74>
008e3c34 <cpu_idle_60x+0x5c> cmpwi   cr7,r9,60
008e3c38 <cpu_idle_60x+0x60> bne+    cr7,008e3c64 <cpu_idle_60x+0x8c>
008e3c3c <cpu_idle_60x+0x64> b       008e3c4c <cpu_idle_60x+0x74>
008e3c40 <cpu_idle_60x+0x68> addi    r0,r9,-32768
008e3c44 <cpu_idle_60x+0x6c> cmplwi  cr7,r0,4
008e3c48 <cpu_idle_60x+0x70> bgt-    cr7,008e3c64 <cpu_idle_60x+0x8c>
008e3c4c <cpu_idle_60x+0x74> oris    r0,r11,4
008e3c50 <cpu_idle_60x+0x78> dssall
008e3c54 <cpu_idle_60x+0x7c> sync   =20
008e3c58 <cpu_idle_60x+0x80> mtmsr   r0
008e3c5c <cpu_idle_60x+0x84> isync
008e3c60 <cpu_idle_60x+0x88> b       008e3c78 <cpu_idle_60x+0xa0>

So that is the context for the EXI trap.
The "mtsmr r0" merged in PSL_POW to the
msr value when it was originally not
set. (r11 vs. r0 value comparison in
the trapframe.)

Why it would be going from without
POW for so long and then merging in
POW I do not know. (Or may be I just
did not find code that turns POW
back off on occasion.)

Still setting POW in msr seems to be
what is unique to the failure context.
Mkes me wonder if smu_doorbell_intr
and its irq is somehow involved.

There is no obvious, local tie to
r25 and r26 in/for the spots identified
earlier for the 013f0930 line of the
thread stack area.



Interestingly when I looked up POW in
mtsmsr use what I found reported:

Synchronization Required Prior: implementation dependent
Synchronization Required After: implementation dependent

The source code looks like:

static void
cpu_idle_60x(sbintime_t sbt)
{
        register_t msr;
        uint16_t vers;

        if (!powerpc_pow_enabled)
                return;

        msr =3D mfmsr();
        vers =3D mfpvr() >> 16;

#ifdef AIM
        switch (vers) {
        case IBM970:
        case IBM970FX:
        case IBM970MP:
        case MPC7447A:
        case MPC7448:
        case MPC7450:
        case MPC7455:
        case MPC7457:
                __asm __volatile("\
                            dssall; sync; mtmsr %0; isync"
                            :: "r"(msr | PSL_POW));
                break;
        default:
                powerpc_sync();
                mtmsr(msr | PSL_POW);
                isync();
                break;
        }
#endif
}

I've not yet figured out how to check
that the details are right here for
IBM970MP used via 32-bit FreeBSD.

=3D=3D=3D
Mark Millard
markmi at dsl-only.net





Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?81F7A2D8-4C3A-426D-B957-9DC937006D88>