Panic in dpaa2_ni_poll_task

[mcbridematt]

Commit: 0e7b9be

This happened to me just now. Same environment as #3.

I'm not sure if the textdump is helpful or not. I will try and setup my install to properly generate a minidump

Fatal data abort:
  x0: ffff00011cd4c000
  x1:                0
  x2: ffff00011d094020
  x3:              152
  x4:                0
  x5:                d
  x6: 9c58ea23fe5fba08
  x7:    8ebb800fc9c58
  x8: ffff00011d094000
  x9: ffff00011d094000
 x10:                3
 x11:                3
 x12:                0
 x13:                0
 x14:                0
 x15:                8
 x16: ffff00016862ad48 (__stop_set_modmetadata_set + 448)
 x17: ffff00000059264c (if_inc_counter + 0)
 x18: ffff00010e3b1840
 x19: ffff00011cd4c000
 x20: ffff00011c9f1000
 x21: ffffa00002d4ec00
 x22: ffff00000091a4b3 (console_pausestr + 366c)
 x23: ffff0000008c3829 (do_execve.fexecv_proc_title + 26782)
 x24: ffff000000bc1000 (sccs + 8)
 x25:                1
 x26:               25
 x27: ffff000000e71000 (epoch_array + 1e00)
 x28: ffff000000e1c0e0 (thread0_st + 0)
 x29: ffff00010e3b1840
  sp: ffff00010e3b1840
  lr: ffff0000007e83d8 (dpaa2_ni_poll_task + c0)
 elr: ffff0000007e84b4 (dpaa2_ni_poll_task + 19c)
spsr:         60000045
 far:                0
 esr:         96000004
panic: vm_fault failed: ffff0000007e84b4 error 1
cpuid = 3
time = 1651998794
KDB: stack backtrace:
db_trace_self() at db_trace_self
db_trace_self_wrapper() at db_trace_self_wrapper+0x30
vpanic() at vpanic+0x174
panic() at panic+0x44
data_abort() at data_abort+0x2f0
handle_el1h_sync() at handle_el1h_sync+0x10
--- exception, esr 0x96000004
dpaa2_ni_poll_task() at dpaa2_ni_poll_task+0x19c
taskqueue_run_locked() at taskqueue_run_locked+0x178
taskqueue_thread_loop() at taskqueue_thread_loop+0xc8
fork_exit() at fork_exit+0x74
fork_trampoline() at fork_trampoline+0x14
KDB: enter: panic

[mcbridematt]

I can almost consistently trigger this by running 2 x iperf3 flows through the machine simultaneously
(Two ports "client", two ports "server")

I can't get a exact backtrace from the minidump (the stack disappears due to the fault), but I believe the problem is the call to fq->consume on line 2565 in 0e0f350.
This is inside dpaa2_ni_consume_frames which appears to have been inlined inside dpaa2_ni_poll_task.

freebsd-src/sys/dev/dpaa2/dpaa2_ni.c

Lines 2561 to 2567 in 0e0f350

	} else if (rc == EALREADY || rc == ENOENT) {
	if (dq != NULL) {
	fd = &dq->fdr.fd;
	fq = (struct dpaa2_ni_fq *) dq->fdr.desc.fqd_ctx;
	fq->consume(chan, fq, fd);
	frames++;
	}

I can upload the vmcore / minidump if you would like.

[dsalychev]

fq->consume points to one of those three functions:

freebsd-src/sys/dev/dpaa2/dpaa2_ni.c

Lines 1098 to 1106 in 0e0f350

	case DPAA2_NI_QUEUE_TX_CONF:
	/* One queue per channel. */
	fq = &chan->txc_queue;
	fq->consume = dpaa2_ni_tx_conf;
	fq->chan = chan;
	fq->flowid = chan->flowid;
	fq->tc = 0; /* ignored */
	fq->type = queue_type;

freebsd-src/sys/dev/dpaa2/dpaa2_ni.c

Lines 1109 to 1127 in 0e0f350

	case DPAA2_NI_QUEUE_RX:
	KASSERT(sc->attr.num.rx_tcs <= DPAA2_NI_MAX_TCS,
	("too many Rx traffic classes: rx_tcs=%d\n",
	sc->attr.num.rx_tcs));
	chan->rxq_n = 0;
	/* One queue per Rx traffic class within a channel. */
	for (int i = 0; i < sc->attr.num.rx_tcs; i++) {
	fq = &chan->rx_queues[i];
	fq->consume = dpaa2_ni_rx;
	fq->chan = chan;
	fq->flowid = chan->flowid;
	fq->tc = (uint8_t) i;
	fq->type = queue_type;
	chan->rxq_n++;
	}

freebsd-src/sys/dev/dpaa2/dpaa2_ni.c

Lines 1129 to 1138 in 0e0f350

	case DPAA2_NI_QUEUE_RX_ERR:
	/* One queue per network interface. */
	fq = &sc->rxe_queue;
	fq->consume = dpaa2_ni_rx_err;
	fq->chan = chan;
	fq->flowid = 0; /* ignored */
	fq->tc = 0; /* ignored */
	fq->type = queue_type;
	break;

Could you add a debug output to understand which one was called at the moment when the kernel panicked?

[mcbridematt]

I have remote (serial) debug working with kgdb now, so I can inspect the variables in dpaa2_ni_consume_frames when the panic occurs.

fq is 0 (NULL) which is why this results in an exception/abort. In fact, most values of dq->fdr (where fq) is are:

print *dq
$2 = {{common = {verb = 96 '`', _reserved = "\003", '\000' <repeats 61 times>}, fdr = {desc = {verb = 96 '`', stat = 3 '\003', seqnum = 0, oprid = 0, _reserved = 0 '\000', tok = 0 '\000', fqid = 0, _reserved1 = 0, fq_byte_cnt = 0,
        fq_frm_cnt = 0, fqd_ctx = 0}, fd = {addr = 0, data_length = 0, bpid_ivp_bmt = 0, offset_fmt_sl = 0, frame_ctx = 0, ctrl = 0, flow_ctx = 0}}, scn = {verb = 96 '`', stat = 3 '\003', state = 0 '\000', _reserved = 0 '\000',
      rid_tok = 0, ctx = 0}}}

(kgdb) bt
#0  kdb_enter (why=<optimized out>, msg=<optimized out>) at /usr/src/freebsd-src/sys/kern/subr_kdb.c:506
#1  0xffff000000468ce8 in vpanic (fmt=0xffff00000091e329 "vm_fault failed: %lx error %d", ap=...) at /usr/src/freebsd-src/sys/kern/kern_shutdown.c:963
#2  0xffff000000468a58 in panic (fmt=0x12 <error: Cannot access memory at address 0x12>) at /usr/src/freebsd-src/sys/kern/kern_shutdown.c:899
#3  0xffff000000776150 in data_abort (td=0xffffa0000c807000, frame=0xffff0000f9fd66a0, esr=2516582404, far=<optimized out>, lower=0) at /usr/src/freebsd-src/sys/arm64/arm64/trap.c:364
#4  0xffff0000007750e0 in do_el1h_sync (td=0xffffa0000c807000, frame=0xffff0000f9fd66a0) at /usr/src/freebsd-src/sys/arm64/arm64/trap.c:462
#5  <signal handler called>
#6  0xffff0000007d1578 in dpaa2_ni_consume_frames (chan=0xffff000101d8e000, src=<optimized out>, consumed=<optimized out>) at /usr/src/freebsd-src/sys/dev/dpaa2/dpaa2_ni.c:2565
#7  dpaa2_ni_poll_task (arg=0xffff000101d8e000, count=<optimized out>) at /usr/src/freebsd-src/sys/dev/dpaa2/dpaa2_ni.c:2423
#8  0xffff0000004c9718 in taskqueue_run_locked (queue=queue@entry=0xffffa0000a85c300) at /usr/src/freebsd-src/sys/kern/subr_taskqueue.c:477
#9  0xffff0000004ca6c8 in taskqueue_thread_loop (arg=arg@entry=0xffff000101d86798) at /usr/src/freebsd-src/sys/kern/subr_taskqueue.c:794
#10 0xffff00000041fdf8 in fork_exit (callout=0xffff0000004ca5fc <taskqueue_thread_loop>, arg=0xffff000101d86798, frame=0xffff0000f9fd6990) at /usr/src/freebsd-src/sys/kern/kern_fork.c:1102
#11 <signal handler called>
(kgdb) frame 6
#6  0xffff0000007d1578 in dpaa2_ni_consume_frames (chan=0xffff000101d8e000, src=<optimized out>, consumed=<optimized out>) at /usr/src/freebsd-src/sys/dev/dpaa2/dpaa2_ni.c:2565
2565                                    KASSERT((
(kgdb) info locals
retries = 1
fq = 0x0
rc = 37
dq = 0xffff0001020d8000
fd = 0xffff0001020d8020
frames = <optimized out>
(kgdb) print *dq
$8 = {{common = {verb = 96 '`', _reserved = "\003", '\000' <repeats 61 times>}, fdr = {desc = {verb = 96 '`', stat = 3 '\003', seqnum = 0, oprid = 0, _reserved = 0 '\000', tok = 0 '\000', fqid = 0, _reserved1 = 0, fq_byte_cnt = 0,
        fq_frm_cnt = 0, fqd_ctx = 0}, fd = {addr = 0, data_length = 0, bpid_ivp_bmt = 0, offset_fmt_sl = 0, frame_ctx = 0, ctrl = 0, flow_ctx = 0}}, scn = {verb = 96 '`', stat = 3 '\003', state = 0 '\000', _reserved = 0 '\000',
      rid_tok = 0, ctx = 0}}}
(kgdb) print *fd
$9 = {addr = 0, data_length = 0, bpid_ivp_bmt = 0, offset_fmt_sl = 0, frame_ctx = 0, ctrl = 0, flow_ctx = 0}

I added a KASSERT((fq != 0),...) just before fq->consume to confirm this, and the assert trigged as expected:

panic: dpaa2_ni_consume_frames: fq is 0
cpuid = 7
time = 1652643273
KDB: stack backtrace:
db_trace_self() at db_trace_self
db_trace_self_wrapper() at db_trace_self_wrapper+0x30
kdb_backtrace() at kdb_backtrace+0x38
vpanic() at vpanic+0x17c
panic() at panic+0x44
dpaa2_ni_poll_task() at dpaa2_ni_poll_task+0x2c0
taskqueue_run_locked() at taskqueue_run_locked+0xac
taskqueue_thread_loop() at taskqueue_thread_loop+0xc8
fork_exit() at fork_exit+0x74
fork_trampoline() at fork_trampoline+0x14
KDB: enter: panic

(kgdb) frame 3
#3  0xffff0000007d167c in dpaa2_ni_consume_frames (chan=0xffff0000fca59000, src=<optimized out>, consumed=<optimized out>) at /usr/src/freebsd-src/sys/dev/dpaa2/dpaa2_ni.c:2565
2565                                    KASSERT((fq != 0), ("%s: fq is 0", __func__));
(kgdb) print fq
$1 = <optimized out>
(kgdb) info locals
retries = 0
fq = <optimized out>
rc = 37
dq = 0xffff0000fcda1000
fd = 0xffff0000fcda1020
frames = <optimized out>
(kgdb) print *dq
$2 = {{common = {verb = 96 '`', _reserved = "\003", '\000' <repeats 61 times>}, fdr = {desc = {verb = 96 '`', stat = 3 '\003', seqnum = 0, oprid = 0, _reserved = 0 '\000', tok = 0 '\000', fqid = 0, _reserved1 = 0, fq_byte_cnt = 0,
        fq_frm_cnt = 0, fqd_ctx = 0}, fd = {addr = 0, data_length = 0, bpid_ivp_bmt = 0, offset_fmt_sl = 0, frame_ctx = 0, ctrl = 0, flow_ctx = 0}}, scn = {verb = 96 '`', stat = 3 '\003', state = 0 '\000', _reserved = 0 '\000',
      rid_tok = 0, ctx = 0}}}
(kgdb) print *fd
$3 = {addr = 0, data_length = 0, bpid_ivp_bmt = 0, offset_fmt_sl = 0, frame_ctx = 0, ctrl = 0, flow_ctx = 0}

[dsalychev]

Hmm, verb = 96 (0x60) means Frame Dequeue Response, but stat = 3 means that the FQ is empty and no frames were delivered to this Volatile Dequeue command. It's just a null response I haven't checked. Please, try 173aa2a.

[mcbridematt]

I think that fixed it! I've run the 4-port iperf stresstest for several long intervals, including a 10 hour one that just completed.

dpni0  1.5K <Link#1>      00:0a:fa:24:24:a3        0     0     0        42G        0     0          0     0
dpni1  1.5K <Link#2>      00:0a:fa:24:24:a4        0     0     0        43G        0     0          0     0
dpni2  1.5K <Link#3>      00:0a:fa:24:24:a5        0     0     0       2.4T        0     0          0     0
dpni3  1.5K <Link#4>      00:0a:fa:24:24:a6        0     0     0       2.4T        0     0          0     0
bridg  1.5K <Link#12>     58:9c:fc:10:0f:76     1.4G     0     0        85G     3.6G     0       4.9T     0

The next panic I have come across is #8 but that appears to be more sporadic.