2021-10-20 18:41:09

by Naresh Kamboju

[permalink] [raw]
Subject: [Next] WARNING: CPU: 1 PID: 219 at include/linux/seqlock.h:271 gnet_stats_add_basic+0x2e0/0x548

Following kernel crash noticed on linux next 20211020 tag.
while booting on qemu_arm devices.

Crash log,
Starting Entropy Daemon based on the HAVEGE algorithm...
[ 15.611450] ------------[ cut here ]------------
[ 15.614631] WARNING: CPU: 1 PID: 219 at include/linux/seqlock.h:271
gnet_stats_add_basic+0x2e0/0x548
[ 15.619863] Modules linked in: fuse
[ 15.621820] CPU: 1 PID: 219 Comm: NetworkManager Not tainted
5.15.0-rc6-next-20211020 #1
[ 15.629011] Hardware name: Generic DT based system
[ 15.632132] Backtrace:
[ 15.633763] [<c159a598>] (dump_backtrace) from [<c159a7b0>]
(show_stack+0x20/0x24)
[ 15.640696] r7:00000009 r6:00000000 r5:c1c896e0 r4:60000013
[ 15.644135] [<c159a790>] (show_stack) from [<c15a41bc>]
(dump_stack_lvl+0x60/0x78)
[ 15.649336] [<c15a415c>] (dump_stack_lvl) from [<c15a41ec>]
(dump_stack+0x18/0x1c)
[ 15.656049] r7:00000009 r6:0000010f r5:c12ea968 r4:c1c796b4
[ 15.659501] [<c15a41d4>] (dump_stack) from [<c0356838>] (__warn+0xe0/0x144)
[ 15.665905] [<c0356758>] (__warn) from [<c159b7d0>]
(warn_slowpath_fmt+0x84/0xb8)
[ 15.670799] r8:00000009 r7:c12ea968 r6:0000010f r5:c1c796b4 r4:00000000
[ 15.674824] [<c159b750>] (warn_slowpath_fmt) from [<c12ea968>]
(gnet_stats_add_basic+0x2e0/0x548)
[ 15.682438] r9:00000000 r8:c12eb178 r7:00000000 r6:c53b99d0
r5:c3365ea0 r4:00000000
[ 15.687144] [<c12ea688>] (gnet_stats_add_basic) from [<c12eb178>]
(___gnet_stats_copy_basic+0x94/0x18c)
[ 15.695278] r10:00000001 r9:c4d4d780 r8:c3365ea0 r7:00000000
r6:00000000 r5:c53b9a68
[ 15.700138] r4:c53b99d0
[ 15.701596] [<c12eb0e4>] (___gnet_stats_copy_basic) from
[<c12eb298>] (gnet_stats_copy_basic+0x28/0x30)
[ 15.709271] r10:00000000 r9:c5220cc0 r8:00000000 r7:c5408000
r6:00000000 r5:c5220cc0
[ 15.716754] r4:c3365e00
[ 15.718375] [<c12eb270>] (gnet_stats_copy_basic) from [<c137e5b0>]
(tc_fill_qdisc+0x29c/0x45c)
[ 15.723901] [<c137e314>] (tc_fill_qdisc) from [<c137e808>]
(tc_dump_qdisc_root+0x98/0x1bc)
[ 15.728747] r10:00000000 r9:c5220cc0 r8:c5053bb8 r7:00000000
r6:00000000 r5:00000000
[ 15.736183] r4:00000001
[ 15.738107] [<c137e770>] (tc_dump_qdisc_root) from [<c137f2ac>]
(tc_dump_qdisc+0x174/0x25c)
[ 15.745388] r10:00000001 r9:c234bb40 r8:c5220cc0 r7:00000000
r6:c5053bb8 r5:00000000
[ 15.749667] r4:c33f0000
[ 15.751277] [<c137f138>] (tc_dump_qdisc) from [<c1396460>]
(netlink_dump+0x154/0x364)
[ 15.758400] r10:00000000 r9:00007f00 r8:c5053bb8 r7:c4d4d780
r6:00007f00 r5:c5220cc0
[ 15.762750] r4:c5053800
[ 15.764050] [<c139630c>] (netlink_dump) from [<c1396fa4>]
(__netlink_dump_start+0x174/0x224)
[ 15.771348] r10:00000000 r9:c5053bb8 r8:00000000 r7:c53b9c7c
r6:c5220d80 r5:c5205000
[ 15.776145] r4:c5053800
[ 15.777715] [<c1396e30>] (__netlink_dump_start) from [<c131d180>]
(rtnetlink_rcv_msg+0x2f4/0x540)
[ 15.785106] r9:00000000 r8:c137f138 r7:c5220d80 r6:c4d4d780
r5:00000000 r4:c5205000
[ 15.791886] [<c131ce8c>] (rtnetlink_rcv_msg) from [<c1399600>]
(netlink_rcv_skb+0xc4/0x11c)
[ 15.796838] r10:c4d4d780 r9:c5053a44 r8:00000024 r7:c5205000
r6:c4d4d780 r5:c131ce8c
[ 15.801860] r4:c5220d80
[ 15.803413] [<c139953c>] (netlink_rcv_skb) from [<c1317b2c>]
(rtnetlink_rcv+0x20/0x24)
[ 15.810282] r8:00000000 r7:c5220d80 r6:c5053800 r5:00000024 r4:c304f800
[ 15.816716] [<c1317b0c>] (rtnetlink_rcv) from [<c1398c98>]
(netlink_unicast+0x1a0/0x264)
[ 15.822014] [<c1398af8>] (netlink_unicast) from [<c1398f68>]
(netlink_sendmsg+0x20c/0x460)
[ 15.827255] r10:c5053800 r9:00000000 r8:00000000 r7:c5220d80
r6:c4d4d780 r5:c53b9f48
[ 15.834244] r4:00000024
[ 15.835804] [<c1398d5c>] (netlink_sendmsg) from [<c12d0318>]
(____sys_sendmsg+0x1e0/0x290)
[ 15.843564] r10:c4d4d780 r9:c53b9dcc r8:00000000 r7:00000000
r6:c46adc00 r5:c1398d5c
[ 15.848266] r4:c53b9f48
[ 15.849821] [<c12d0138>] (____sys_sendmsg) from [<c12d233c>]
(___sys_sendmsg+0xb0/0xdc)
[ 15.857074] r10:00000128 r9:00000000 r8:c4d4d780 r7:00000000
r6:c46adc00 r5:c53b9f48
[ 15.862000] r4:00000000
[ 15.863630] [<c12d228c>] (___sys_sendmsg) from [<c12d2514>]
(sys_sendmsg+0x5c/0x98)
[ 15.869879] r9:c4d4d780 r8:c03002a4 r7:befe879c r6:c4d4d780
r5:c46adc00 r4:00000000
[ 15.874816] [<c12d24b8>] (sys_sendmsg) from [<c03000c0>]
(ret_fast_syscall+0x0/0x1c)
[ 15.881956] Exception stack(0xc53b9fa8 to 0xc53b9ff0)
[ 15.884954] 9fa0: 00000000 befe879c 00000007
befe879c 00000000 00000000
[ 15.891833] 9fc0: 00000000 befe879c 00000007 00000128 b6a62000
00000001 00000005 0027fe18
[ 15.897081] 9fe0: 00000000 befe8740 00000000 b6d71ec0
[ 15.900493] r7:00000128 r6:00000007 r5:befe879c r4:00000000
[ 15.906386] irq event stamp: 36305
[ 15.907882] hardirqs last enabled at (36313): [<c03e31c8>]
__up_console_sem+0x60/0x70
[ 15.911674] hardirqs last disabled at (36320): [<c03e31b4>]
__up_console_sem+0x4c/0x70
[ 15.918671] softirqs last enabled at (36304): [<c0301fec>]
__do_softirq+0x32c/0x560
[ 15.922707] softirqs last disabled at (36261): [<c0360034>]
__irq_exit_rcu+0x154/0x178
[ 15.922869] ---[ end trace 3190ec354e2b2e34 ]---

Full log,
https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20211020/testrun/6177894/suite/linux-log-parser/test/check-kernel-warning-3786488/log
https://lkft.validation.linaro.org/scheduler/job/3786488#L775

Build config:
https://builds.tuxbuild.com/1zlLmMyDukg9DNVY8NUNkQ1d2ff/config

Reported-by: Linux Kernel Functional Testing <[email protected]>


steps to reproduce:
1) https://builds.tuxbuild.com/1zlLmMyDukg9DNVY8NUNkQ1d2ff/tuxmake_reproducer.sh
2) boot qemu_arm with OE rootfs as showing in below command line.
/usr/bin/qemu-system-aarch64 -cpu host,aarch64=off -machine
virt-2.10,accel=kvm -nographic -net
nic,model=virtio,macaddr=BA:DD:AD:CC:09:02 -net tap -m 2048 -monitor
none -kernel kernel/zImage --append "console=ttyAMA0 root=/dev/vda rw"
-hda rootfs/rpb-console-image-lkft-am57xx-evm-20211006160523.rootfs.ext4
-m 4096 -smp 2 -nographic

--
Linaro LKFT
https://lkft.linaro.org


Subject: [PATCH net-next] net: stats: Read the statistics in ___gnet_stats_copy_basic() instead of adding.

Since the rework, the statistics code always adds up the byte and packet
value(s). On 32bit architectures a seqcount_t is used in
gnet_stats_basic_sync to ensure that the 64bit values are not modified
during the read since two 32bit loads are required. The usage of a
seqcount_t requires a lock to ensure that only one writer is active at a
time. This lock leads to disabled preemption during the update.

The lack of disabling preemption is now creating a warning as reported
by Naresh since the query done by gnet_stats_copy_basic() is in
preemptible context.

For ___gnet_stats_copy_basic() there is no need to disable preemption
since the update is performed on stack and can't be modified by another
writer. Instead of disabling preemption, to avoid the warning,
simply create a read function to just read the values and return as u64.

Reported-by: Naresh Kamboju <[email protected]>
Fixes: 67c9e6270f301 ("net: sched: Protect Qdisc::bstats with u64_stats")
Signed-off-by: Sebastian Andrzej Siewior <[email protected]>
---
net/core/gen_stats.c | 43 +++++++++++++++++++++++++++++++++++++------
1 file changed, 37 insertions(+), 6 deletions(-)

diff --git a/net/core/gen_stats.c b/net/core/gen_stats.c
index 15c270e22c5ef..a10335b4ba2d0 100644
--- a/net/core/gen_stats.c
+++ b/net/core/gen_stats.c
@@ -171,20 +171,51 @@ void gnet_stats_add_basic(struct gnet_stats_basic_sync *bstats,
}
EXPORT_SYMBOL(gnet_stats_add_basic);

+static void gnet_stats_read_basic(u64 *ret_bytes, u64 *ret_packets,
+ struct gnet_stats_basic_sync __percpu *cpu,
+ struct gnet_stats_basic_sync *b, bool running)
+{
+ unsigned int start;
+
+ if (cpu) {
+ u64 t_bytes = 0, t_packets = 0;
+ int i;
+
+ for_each_possible_cpu(i) {
+ struct gnet_stats_basic_sync *bcpu = per_cpu_ptr(cpu, i);
+ unsigned int start;
+ u64 bytes, packets;
+
+ do {
+ start = u64_stats_fetch_begin_irq(&bcpu->syncp);
+ bytes = u64_stats_read(&bcpu->bytes);
+ packets = u64_stats_read(&bcpu->packets);
+ } while (u64_stats_fetch_retry_irq(&bcpu->syncp, start));
+
+ t_bytes += bytes;
+ t_packets += packets;
+ }
+ *ret_bytes = t_bytes;
+ *ret_packets = t_packets;
+ return;
+ }
+ do {
+ if (running)
+ start = u64_stats_fetch_begin_irq(&b->syncp);
+ *ret_bytes = u64_stats_read(&b->bytes);
+ *ret_packets = u64_stats_read(&b->packets);
+ } while (running && u64_stats_fetch_retry_irq(&b->syncp, start));
+}
+
static int
___gnet_stats_copy_basic(struct gnet_dump *d,
struct gnet_stats_basic_sync __percpu *cpu,
struct gnet_stats_basic_sync *b,
int type, bool running)
{
- struct gnet_stats_basic_sync bstats;
u64 bstats_bytes, bstats_packets;

- gnet_stats_basic_sync_init(&bstats);
- gnet_stats_add_basic(&bstats, cpu, b, running);
-
- bstats_bytes = u64_stats_read(&bstats.bytes);
- bstats_packets = u64_stats_read(&bstats.packets);
+ gnet_stats_read_basic(&bstats_bytes, &bstats_packets, cpu, b, running);

if (d->compat_tc_stats && type == TCA_STATS_BASIC) {
d->tc_stats.bytes = bstats_bytes;
--
2.33.0

2021-10-21 11:51:35

by patchwork-bot+netdevbpf

[permalink] [raw]
Subject: Re: [PATCH net-next] net: stats: Read the statistics in ___gnet_stats_copy_basic() instead of adding.

Hello:

This patch was applied to netdev/net-next.git (master)
by David S. Miller <[email protected]>:

On Thu, 21 Oct 2021 11:59:19 +0200 you wrote:
> Since the rework, the statistics code always adds up the byte and packet
> value(s). On 32bit architectures a seqcount_t is used in
> gnet_stats_basic_sync to ensure that the 64bit values are not modified
> during the read since two 32bit loads are required. The usage of a
> seqcount_t requires a lock to ensure that only one writer is active at a
> time. This lock leads to disabled preemption during the update.
>
> [...]

Here is the summary with links:
- [net-next] net: stats: Read the statistics in ___gnet_stats_copy_basic() instead of adding.
https://git.kernel.org/netdev/net-next/c/c5c6e589a8c8

You are awesome, thank you!
--
Deet-doot-dot, I am a bot.
https://korg.docs.kernel.org/patchwork/pwbot.html