Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

"Failed to pull frames" when using multiple DPNIs #1

Closed
mcbridematt opened this issue Apr 26, 2022 · 11 comments
Closed

"Failed to pull frames" when using multiple DPNIs #1

mcbridematt opened this issue Apr 26, 2022 · 11 comments
Assignees
Labels
bug Something isn't working

Comments

@mcbridematt
Copy link

Hardware: Ten64
MC firmware: 10.20
Commit: 6efa7d1

When more than one interface / DPNI is transferring data, the following errors appear in the system console / dmesg:

dpaa2_ni0: failed to pull frames: chan_id=15, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni0: failed to pull frames: chan_id=15, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni0: failed to pull frames: chan_id=15, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni0: failed to pull frames: chan_id=15, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni0: failed to pull frames: chan_id=15, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16
dpaa2_ni1: failed to pull frames: chan_id=23, error=16

An example use case is when the system is being used as a router between two network interfaces.
I don't see any evidence of packet loss which is good.

This message is printed by dpaa2_ni_poll_task around line 2367:

error = dpaa2_swp_pull(swp, chan->id, chan->store.paddr,
ETH_STORE_FRAMES);
if (error) {
device_printf(chan->ni_dev, "failed to pull frames: "
"chan_id=%d, error=%d\n", chan->id, error);
break;
}

@dsalychev dsalychev added the bug Something isn't working label Apr 26, 2022
@dsalychev dsalychev self-assigned this Apr 26, 2022
@dsalychev
Copy link

dsalychev commented Apr 29, 2022

It seems those errors appear when different DPNIs use the same DPIO (struct dpaa2_swp). Driver keeps the software portal busy executing a Volatile Dequeue command for too long, i.e.

			/* Make VDQ command available again. */
			atomic_xchg(&swp->vdq.avail, 1);

is set too late, I think.
EDIT: It's my guess though. I'll check it and prepare a patch.

@dsalychev
Copy link

dsalychev commented Apr 29, 2022

@mcbridematt Could you try the latest commit? I don't have this error reported starting from efe105c.

@mcbridematt
Copy link
Author

@dsalychev Yes, no more errors after updating the kernel. I'll move some devices behind this machine and see how it goes.

@mcbridematt
Copy link
Author

FYI, for a system that did 4.9TB of traffic over 14 hours I still got a few warnings in dmesg:

dmesg | grep 'failed to pull frames'  | wc -l
     590

590 / 5TB is a very small rate, but I don't know enough to judge how important the warning message is.

@mcbridematt mcbridematt reopened this May 17, 2022
@dsalychev
Copy link

Could you show an output of sysctl dev.dpaa2_ni.0 (for dpni0) for all of the interfaces reported the errors? I'm particularly interested in

dev.dpaa2_ni.0.stats.in_discarded_frames: 18
dev.dpaa2_ni.0.stats.in_nobuf_discards: 0

@mcbridematt
Copy link
Author

After a 1hr iperf run that logged around 70 failed to pull frames messages, none of the interfaces had discards

dev.dpaa2_ni.1.stats.in_all_frames: 75934381
dev.dpaa2_ni.1.stats.in_all_bytes: 5011725630
dev.dpaa2_ni.1.stats.in_multi_frames: 0
dev.dpaa2_ni.1.stats.eg_all_frames: 157009142
dev.dpaa2_ni.1.stats.eg_all_bytes: 237634857392
dev.dpaa2_ni.1.stats.eg_multi_frames: 0
dev.dpaa2_ni.1.stats.in_filtered_frames: 0
dev.dpaa2_ni.1.stats.in_discarded_frames: 0
dev.dpaa2_ni.1.stats.in_nobuf_discards: 0
dev.dpaa2_ni.1.stats.tx_sg_frames: 157009292
dev.dpaa2_ni.1.stats.tx_single_buf_frames: 0
dev.dpaa2_ni.1.stats.rx_ieoi_err_frames: 0
dev.dpaa2_ni.1.stats.rx_enq_rej_frames: 0
dev.dpaa2_ni.1.stats.rx_sg_buf_frames: 0
dev.dpaa2_ni.1.stats.rx_single_buf_frames: 75934511
dev.dpaa2_ni.1.stats.rx_anomaly_frames: 0
dev.dpaa2_ni.1.channels.7.tx_dropped: 0
dev.dpaa2_ni.1.channels.7.tx_frames: 0
dev.dpaa2_ni.1.channels.6.tx_dropped: 0
dev.dpaa2_ni.1.channels.6.tx_frames: 0
dev.dpaa2_ni.1.channels.5.tx_dropped: 0
dev.dpaa2_ni.1.channels.5.tx_frames: 0
dev.dpaa2_ni.1.channels.4.tx_dropped: 0
dev.dpaa2_ni.1.channels.4.tx_frames: 0
dev.dpaa2_ni.1.channels.3.tx_dropped: 0
dev.dpaa2_ni.1.channels.3.tx_frames: 0
dev.dpaa2_ni.1.channels.2.tx_dropped: 0
dev.dpaa2_ni.1.channels.2.tx_frames: 0
dev.dpaa2_ni.1.channels.1.tx_dropped: 0
dev.dpaa2_ni.1.channels.1.tx_frames: 0
dev.dpaa2_ni.1.channels.0.tx_dropped: 0
dev.dpaa2_ni.1.channels.0.tx_frames: 157009437
dev.dpaa2_ni.1.%parent: dpaa2_rc0
dev.dpaa2_ni.1.%pnpinfo:
dev.dpaa2_ni.1.%location:
dev.dpaa2_ni.1.%driver: dpaa2_ni
dev.dpaa2_ni.1.%desc: DPAA2 Network Interface
dev.dpaa2_ni.2.stats.in_all_frames: 165393160
dev.dpaa2_ni.2.stats.in_all_bytes: 250312613260
dev.dpaa2_ni.2.stats.in_multi_frames: 0
dev.dpaa2_ni.2.stats.eg_all_frames: 48486702
dev.dpaa2_ni.2.stats.eg_all_bytes: 3200223070
dev.dpaa2_ni.2.stats.eg_multi_frames: 0
dev.dpaa2_ni.2.stats.in_filtered_frames: 0
dev.dpaa2_ni.2.stats.in_discarded_frames: 0
dev.dpaa2_ni.2.stats.in_nobuf_discards: 0
dev.dpaa2_ni.2.stats.tx_sg_frames: 48486702
dev.dpaa2_ni.2.stats.tx_single_buf_frames: 0
dev.dpaa2_ni.2.stats.rx_ieoi_err_frames: 0
dev.dpaa2_ni.2.stats.rx_enq_rej_frames: 0
dev.dpaa2_ni.2.stats.rx_sg_buf_frames: 0
dev.dpaa2_ni.2.stats.rx_single_buf_frames: 165392672
dev.dpaa2_ni.2.stats.rx_anomaly_frames: 0
dev.dpaa2_ni.2.channels.7.tx_dropped: 0
dev.dpaa2_ni.2.channels.7.tx_frames: 0
dev.dpaa2_ni.2.channels.6.tx_dropped: 0
dev.dpaa2_ni.2.channels.6.tx_frames: 0
dev.dpaa2_ni.2.channels.5.tx_dropped: 0
dev.dpaa2_ni.2.channels.5.tx_frames: 0
dev.dpaa2_ni.2.channels.4.tx_dropped: 0
dev.dpaa2_ni.2.channels.4.tx_frames: 0
dev.dpaa2_ni.2.channels.3.tx_dropped: 0
dev.dpaa2_ni.2.channels.3.tx_frames: 0
dev.dpaa2_ni.2.channels.2.tx_dropped: 0
dev.dpaa2_ni.2.channels.2.tx_frames: 0
dev.dpaa2_ni.2.channels.1.tx_dropped: 0
dev.dpaa2_ni.2.channels.1.tx_frames: 0
dev.dpaa2_ni.2.channels.0.tx_dropped: 0
dev.dpaa2_ni.2.channels.0.tx_frames: 48486702

(This is with the buffer commits reverted: 19d8245, 846462f, 48d302a)

@dsalychev
Copy link

These are good news. I'll try to prepare a debug code to check whether those frames were processed at all and not dropped silently after an error returned by dpaa2_swp_pull().

@dsalychev
Copy link

@mcbridematt Could you test with 1a7aba9?

@mcbridematt
Copy link
Author

@dsalychev I now see a few 'timeout to consume frames' errors as well, is that expected?

dpaa2_ni0: dpaa2_ni_poll_task: failed to pull frames: chan_id=16, error=16
dpaa2_ni0: dpaa2_ni_poll_task: failed to pull frames: chan_id=23, error=16
dpaa2_ni0: dpaa2_ni_poll_task: failed to pull frames: chan_id=23, error=16
dpaa2_ni0: dpaa2_ni_poll_task: timeout to consume frames: chan_id=23
dpaa2_ni1: dpaa2_ni_poll_task: failed to pull frames: chan_id=4, error=16
dpaa2_ni0: dpaa2_ni_poll_task: failed to pull frames: chan_id=16, error=16
dpaa2_ni0: dpaa2_ni_poll_task: failed to pull frames: chan_id=23, error=16
dpaa2_ni1: dpaa2_ni_poll_task: timeout to consume frames: chan_id=24
dpaa2_ni0: dpaa2_ni_poll_task: timeout to consume frames: chan_id=23
dpaa2_ni1: dpaa2_ni_poll_task: failed to pull frames: chan_id=4, error=16
dpaa2_ni0: dpaa2_ni_poll_task: failed to pull frames: chan_id=16, error=16

sysctls:

dev.dpaa2_ni.0.stats.in_all_frames: 33739237
dev.dpaa2_ni.0.stats.in_all_bytes: 2227163082
dev.dpaa2_ni.0.stats.in_multi_frames: 0
dev.dpaa2_ni.0.stats.eg_all_frames: 76976026
dev.dpaa2_ni.0.stats.eg_all_bytes: 116515198666
dev.dpaa2_ni.0.stats.eg_multi_frames: 0
dev.dpaa2_ni.0.stats.in_filtered_frames: 0
dev.dpaa2_ni.0.stats.in_discarded_frames: 0
dev.dpaa2_ni.0.stats.in_nobuf_discards: 0
dev.dpaa2_ni.0.stats.buf_free: 0
dev.dpaa2_ni.0.stats.buf_num: 2800
dev.dpaa2_ni.0.stats.tx_sg_frames: 76976026
dev.dpaa2_ni.0.stats.tx_single_buf_frames: 0
dev.dpaa2_ni.0.stats.rx_ieoi_err_frames: 0
dev.dpaa2_ni.0.stats.rx_enq_rej_frames: 0
dev.dpaa2_ni.0.stats.rx_sg_buf_frames: 0
dev.dpaa2_ni.0.stats.rx_single_buf_frames: 33739234
dev.dpaa2_ni.0.stats.rx_anomaly_frames: 0
...
dev.dpaa2_ni.0.channels.0.tx_frames: 76976026
dev.dpaa2_ni.1.stats.in_all_frames: 32743170
dev.dpaa2_ni.1.stats.in_all_bytes: 2161390320
dev.dpaa2_ni.1.stats.in_multi_frames: 0
dev.dpaa2_ni.1.stats.eg_all_frames: 75728550
dev.dpaa2_ni.1.stats.eg_all_bytes: 114619322702
dev.dpaa2_ni.1.stats.eg_multi_frames: 0
dev.dpaa2_ni.1.stats.in_filtered_frames: 0
dev.dpaa2_ni.1.stats.in_discarded_frames: 0
dev.dpaa2_ni.1.stats.in_nobuf_discards: 0
dev.dpaa2_ni.1.stats.buf_free: 0
dev.dpaa2_ni.1.stats.buf_num: 2800
dev.dpaa2_ni.1.stats.tx_sg_frames: 75728550
dev.dpaa2_ni.1.stats.tx_single_buf_frames: 0
dev.dpaa2_ni.1.stats.rx_ieoi_err_frames: 0
dev.dpaa2_ni.1.stats.rx_enq_rej_frames: 0
dev.dpaa2_ni.1.stats.rx_sg_buf_frames: 0
dev.dpaa2_ni.1.stats.rx_single_buf_frames: 32743170
dev.dpaa2_ni.1.stats.rx_anomaly_frames: 0
...
dev.dpaa2_ni.1.channels.0.tx_frames: 75728550

dsalychev pushed a commit that referenced this issue Aug 19, 2022
This and the follow-up routing-related changes target to remove or
 reduce `struct rt_addrinfo` usage and use recently-landed nhop(9)
 KPI instead.
Traditionally `rt_addrinfo` structure has been used to propagate all necessary
information between the protocol/rtsock and a routing layer. Many
functions inside routing subsystem uses it internally. However, using
this structure became somewhat complicated, as there are too many ways
of specifying a single state and verifying data consistency is hard.
For example, arerouting flgs consistent with mask/gateway sockaddr pointers?
Is mask really a host mask? Are sockaddr "valid" (e.g. properly zeroed, masked,
have proper length)? Are they mutable? Is the suggested interface specified
 by the interface index embedded into the sockadd_dl gateway, or passed
 as RTAX_IFP parameter, or directly provided by rti_ifp or it needs to
 be derived from the ifa?
These (and other similar) questions have to be considered every time when
 a function has `rt_addrinfo` pointer as an argument.

The new approach is to bring more control back to the protocols and
construct the desired routing objects themselves - in the end, it's the
protocol/subsystem who knows the desired outcome.

This specific diff changes the following:
* add explicit basic low-level radix operations:
 add_route() (renamed from add_route_nhop())
 delete_route() (factored from change_route_nhop())
 change_route() (renamed from change_route_nhop)
* remove "info" parameter from change_route_conditional() as a part
 of reducing rt_addrinfo usage in the internal KPIs
* add lookup_prefix_rt() wrapper for doing re-lookups after
 RIB lock/unlock

Differential Revision: https://reviews.freebsd.org/D36070
MFC after:	2 weeks
dsalychev pushed a commit that referenced this issue Oct 11, 2022
Simplify epair_clone_create() and epair_clone_destroy() by
 factoring out epair softc allocation / desctruction and
 interface setup/teardown into separate functions.

Reviewed By: kp, zlei.huang_gmail.com
Differential Revision: https://reviews.freebsd.org/D36614
MFC after:	2 weeks
@dsalychev
Copy link

dsalychev commented Mar 1, 2023

@mcbridematt
I've an experimental branch: https://github.com/mcusim/freebsd-src/tree/ten64

Could you try to run a stress test? I've been fighting another panic (Undefined instruction: ..., panic: Unknown kernel exception 0 esr_el1 2000000) and my Ten64 survived the last night under stress test. I wonder whether it helps to solve the issues with frames consuming.

dsalychev pushed a commit that referenced this issue Mar 20, 2023
* Add ifc_find_cloner()
* Rename current ifc_find_cloner() to ifc_find_cloner_in_vnet()
* Add ifc_find_cloner_match()

This change simplifies the code a bit and reduces the diff to
 the netlink interface cloners merge (D39032).

Reviewed by:	glebius, kp
Differential Revision: https://reviews.freebsd.org/D39046
MFC after:	2 weeks
dsalychev pushed a commit that referenced this issue Apr 3, 2023
Under certain loads, the following panic is hit:

    panic: page fault
    KDB: stack backtrace:
    #0 0xffffffff805db025 at kdb_backtrace+0x65
    #1 0xffffffff8058e86f at vpanic+0x17f
    #2 0xffffffff8058e6e3 at panic+0x43
    #3 0xffffffff808adc15 at trap_fatal+0x385
    #4 0xffffffff808adc6f at trap_pfault+0x4f
    #5 0xffffffff80886da8 at calltrap+0x8
    #6 0xffffffff80669186 at vgonel+0x186
    #7 0xffffffff80669841 at vgone+0x31
    #8 0xffffffff8065806d at vfs_hash_insert+0x26d
    #9 0xffffffff81a39069 at sfs_vgetx+0x149
    #10 0xffffffff81a39c54 at zfsctl_snapdir_lookup+0x1e4
    #11 0xffffffff8065a28c at lookup+0x45c
    #12 0xffffffff806594b9 at namei+0x259
    #13 0xffffffff80676a33 at kern_statat+0xf3
    #14 0xffffffff8067712f at sys_fstatat+0x2f
    #15 0xffffffff808ae50c at amd64_syscall+0x10c
    #16 0xffffffff808876bb at fast_syscall_common+0xf8

The page fault occurs because vgonel() will call VOP_CLOSE() for active
vnodes. For this reason, define vop_close for zfsctl_ops_snapshot. While
here, define vop_open for consistency.

After adding the necessary vop, the bug progresses to the following
panic:

    panic: VERIFY3(vrecycle(vp) == 1) failed (0 == 1)
    cpuid = 17
    KDB: stack backtrace:
    #0 0xffffffff805e29c5 at kdb_backtrace+0x65
    #1 0xffffffff8059620f at vpanic+0x17f
    #2 0xffffffff81a27f4a at spl_panic+0x3a
    #3 0xffffffff81a3a4d0 at zfsctl_snapshot_inactive+0x40
    #4 0xffffffff8066fdee at vinactivef+0xde
    #5 0xffffffff80670b8a at vgonel+0x1ea
    #6 0xffffffff806711e1 at vgone+0x31
    #7 0xffffffff8065fa0d at vfs_hash_insert+0x26d
    #8 0xffffffff81a39069 at sfs_vgetx+0x149
    #9 0xffffffff81a39c54 at zfsctl_snapdir_lookup+0x1e4
    #10 0xffffffff80661c2c at lookup+0x45c
    #11 0xffffffff80660e59 at namei+0x259
    #12 0xffffffff8067e3d3 at kern_statat+0xf3
    #13 0xffffffff8067eacf at sys_fstatat+0x2f
    #14 0xffffffff808b5ecc at amd64_syscall+0x10c
    #15 0xffffffff8088f07b at fast_syscall_common+0xf8

This is caused by a race condition that can occur when allocating a new
vnode and adding that vnode to the vfs hash. If the newly created vnode
loses the race when being inserted into the vfs hash, it will not be
recycled as its usecount is greater than zero, hitting the above
assertion.

Fix this by dropping the assertion.

FreeBSD-issue: https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=252700
Reviewed-by: Andriy Gapon <avg@FreeBSD.org>
Reviewed-by: Mateusz Guzik <mjguzik@gmail.com>
Reviewed-by: Alek Pinchuk <apinchuk@axcient.com>
Reviewed-by: Ryan Moeller <ryan@iXsystems.com>
Signed-off-by: Rob Wing <rob.wing@klarasystems.com>
Co-authored-by: Rob Wing <rob.wing@klarasystems.com>
Submitted-by: Klara, Inc.
Sponsored-by: rsync.net
Closes #14501
dsalychev pushed a commit that referenced this issue Jun 9, 2023
Cleanup compiler warnings in preparation to set Wextra and remove WARNS?=2

Differential Revision: https://reviews.freebsd.org/D40238
MFC after:	2 weeks
@mcbridematt
Copy link
Author

Not seen on commit a85d6c9

dsalychev pushed a commit that referenced this issue Aug 3, 2023
Avoid locking issues when if_allmulti() calls the driver's if_ioctl,
because that may acquire sleepable locks (while we hold a non-sleepable
rwlock).

Fortunately there's no pressing need to hold the mroute lock while we
do this, so we can postpone the call slightly, until after we've
released the lock.

This avoids the following WITNESS warning (with iflib drivers):

	lock order reversal: (sleepable after non-sleepable)
	 1st 0xffffffff82f64960 IPv4 multicast forwarding (IPv4 multicast forwarding, rw) @ /usr/src/sys/netinet/ip_mroute.c:1050
	 2nd 0xfffff8000480f180 iflib ctx lock (iflib ctx lock, sx) @ /usr/src/sys/net/iflib.c:4525
	lock order IPv4 multicast forwarding -> iflib ctx lock attempted at:
	#0 0xffffffff80bbd6ce at witness_checkorder+0xbbe
	#1 0xffffffff80b56d10 at _sx_xlock+0x60
	#2 0xffffffff80c9ce5c at iflib_if_ioctl+0x2dc
	#3 0xffffffff80c7c395 at if_setflag+0xe5
	#4 0xffffffff82f60a0e at del_vif_locked+0x9e
	#5 0xffffffff82f5f0d5 at X_ip_mrouter_set+0x265
	#6 0xffffffff80bfd402 at sosetopt+0xc2
	#7 0xffffffff80c02105 at kern_setsockopt+0xa5
	#8 0xffffffff80c02054 at sys_setsockopt+0x24
	#9 0xffffffff81046be8 at amd64_syscall+0x138
	#10 0xffffffff8101930b at fast_syscall_common+0xf8

See also:	https://redmine.pfsense.org/issues/12079
Reviewed by:	mjg
Sponsored by:	Rubicon Communications, LLC ("Netgate")
Differential Revision:	https://reviews.freebsd.org/D41209
dsalychev pushed a commit that referenced this issue Feb 1, 2024
Specifically, altering the console list with conscontrol has some weird
behavior:

1. If you remove the first configured console, /dev/console will become
  unconfigured
2. Any console added becomes the /dev/console

In a multicons situation, #1 is clearly a bug and #2 is perhaps slightly
less clear.  If we have ttyu0, ttyv0, then it seems obvious that one
would want ttyv0 to take over the console if ttyu0 is removed.  If we
add ttyu0 back in, then it's debatable whether it should take over the
console or not.

Fix it now to make the /dev/console selection more FIFO-ish, with
respect to how conscontrol affects it.  A `primary` verb for
conscontrol(8) might be a good addition.
dsalychev pushed a commit that referenced this issue Nov 18, 2024
Avoid calling _callout_stop_safe with a non-sleepable lock held when
detaching by initializing callout_init_rw() with CALLOUT_SHAREDLOCK.

It avoids the following WITNESS warning when stopping the service:

    # service ipfilter stop
    calling _callout_stop_safe with the following non-sleepable locks held:
    shared rw ipf filter load/unload mutex (ipf filter load/unload mutex) r = 0 (0xffff0000417c7530) locked @ /usr/src/sys/netpfil/ipfilter/netinet/fil.c:7926
    stack backtrace:
    #0 0xffff00000052d394 at witness_debugger+0x60
    #1 0xffff00000052e620 at witness_warn+0x404
    #2 0xffff0000004d4ffc at _callout_stop_safe+0x8c
    #3 0xffff0000f7236674 at ipfdetach+0x3c
    #4 0xffff0000f723fa4c at ipf_ipf_ioctl+0x788
    #5 0xffff0000f72367e0 at ipfioctl+0x144
    #6 0xffff00000034abd8 at devfs_ioctl+0x100
    #7 0xffff0000005c66a0 at vn_ioctl+0xbc
    #8 0xffff00000034b2cc at devfs_ioctl_f+0x24
    #9 0xffff0000005331ec at kern_ioctl+0x2e0
    #10 0xffff000000532eb4 at sys_ioctl+0x140
    #11 0xffff000000880480 at do_el0_sync+0x604
    #12 0xffff0000008579ac at handle_el0_sync+0x4c

PR:		282478
Suggested by:	markj
Reviewed by:	cy
Approved by:	emaste (mentor)
MFC after:	1 week
dsalychev pushed a commit that referenced this issue Dec 13, 2024
Switch from creating the msr instructions to manage PAN to use the
"msr pan, #1" instruction directly. When this was added clang didn't
have support to assemble the instructions. This appears to have been
added to clang 13 which is sufficiently old enough.

Binutils releases from around the same time appear to have added this
instruction so any modern gcc should also support this instruction.

Sponsored by:	Arm Ltd
Differential Revision:	https://reviews.freebsd.org/D47817
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests

2 participants