slowpath in tcp_recvmsg on pandaboard es

[Iain Lane]

Greetings,

My dmesg/syslog is being spammed with this kind of slowpath warning. I don't notice any other effects. The machine is connected to the internet over both ipv4 and ipv6, and sees a relatively later amount of ipv6 traffic as it's maintaining my local Debian mirror using debmirror. Log snippet attached.

The machine was installed from the desktop armhf+omap4 quantal daily on 20120717 and has been dist-upgraded since.

uname -a:
Linux sherwood 3.4.0-204-omap4 #9-Ubuntu SMP PREEMPT Mon Jul 9 12:56:56 UTC 2012 armv7l armv7l armv7l GNU/Linux

[Iain Lane (laney)]

Better:

Jul 29 12:31:12 sherwood kernel: [182905.038024] ------------[ cut here ]------------
Jul 29 12:31:12 sherwood kernel: [182905.038055] WARNING: at /build/buildd/linux-ti-omap4-3.4.0/net/ipv4/tcp.c:1496 tcp_recvmsg+0x1f8/0xa68()
Jul 29 12:31:12 sherwood kernel: [182905.038055] recvmsg bug: copied 7D5FBDB seq 7D60182 rcvnxt 83C0142 fl 0
Jul 29 12:31:12 sherwood kernel: [182905.038085] Modules linked in: rfcomm bnep bluetooth ppdev lp parport ip6t_REJECT xt_tcpudp nf_conntrack
_ipv6 nf_defrag_ipv6 xt_state arc4 nf_conntrack wl12xx ip6table_filter ip6table_mangle ip6_tables x_tables wlcore mac80211 cfg80211 wlcore_sd
io gpio_keys uas usb_storage
Jul 29 12:31:12 sherwood kernel: [182905.038146] [<c00165cc>] (unwind_backtrace+0x0/0xec) from [<c0587378>] (dump_stack+0x20/0x24)
Jul 29 12:31:12 sherwood kernel: [182905.038177] [<c0587378>] (dump_stack+0x20/0x24) from [<c003f730>] (warn_slowpath_common+0x5c/0x74)
Jul 29 12:31:12 sherwood kernel: [182905.038208] [<c003f730>] (warn_slowpath_common+0x5c/0x74) from [<c003f804>] (warn_slowpath_fmt+0x40/0x48)
Jul 29 12:31:12 sherwood kernel: [182905.038208] [<c003f804>] (warn_slowpath_fmt+0x40/0x48) from [<c04e2678>] (tcp_recvmsg+0x1f8/0xa68)
Jul 29 12:31:12 sherwood kernel: [182905.038238] [<c04e2678>] (tcp_recvmsg+0x1f8/0xa68) from [<c05025a0>] (inet_recvmsg+0xb0/0xc8)
Jul 29 12:31:12 sherwood kernel: [182905.038269] [<c05025a0>] (inet_recvmsg+0xb0/0xc8) from [<c0491908>] (sock_aio_read+0x108/0x128)
Jul 29 12:31:12 sherwood kernel: [182905.038269] [<c0491908>] (sock_aio_read+0x108/0x128) from [<c0138ae4>] (do_sync_read+0xa4/0xe4)
Jul 29 12:31:12 sherwood kernel: [182905.038299] [<c0138ae4>] (do_sync_read+0xa4/0xe4) from [<c01395d0>] (vfs_read+0xc0/0x194)
Jul 29 12:31:12 sherwood kernel: [182905.038299] [<c01395d0>] (vfs_read+0xc0/0x194) from [<c01396ec>] (sys_read+0x48/0x7c)
Jul 29 12:31:12 sherwood kernel: [182905.038604] [<c01396ec>] (sys_read+0x48/0x7c) from [<c000e020>] (ret_fast_syscall+0x0/0x30)
Jul 29 12:31:12 sherwood kernel: [182905.038726] ---[ end trace 5a36fdaca5cbea2f ]---
Jul 29 12:31:12 sherwood kernel: [182905.039123] ------------[ cut here ]------------

[Joseph Salisbury (jsalisbury)]

Are you still seeing this bug with the latest Quantal build?

[Iain Lane (laney)]

Nope. Either I haven't triggered it or it's fixed. :)

[Thomas Kristensen (tkk2112)]

I see this bug alot, I can trigger it almost everytime i try to rsync to my panda, here's the stack trace:

[ 153.825866] ------------[ cut here ]------------
[ 153.830749] WARNING: at net/ipv4/tcp.c:1508 tcp_recvmsg+0x194/0x858()
[ 153.837524] recvmsg bug 2: copied B1705247 seq B1705247 rcvnxt B17678B7 fl 0
[ 153.844970] Modules linked in: omapdce(C) omap_remoteproc remoteproc virtio_rpmsg_bus omapdrm_pvr(O)
[ 153.854644] Backtrace:
[ 153.857208] [<c0012a58>] (dump_backtrace+0x0/0x114) from [<c0465ed0>] (dump_stack+0x20/0x24)
[ 153.866119] r6:c03d7f30 r5:00000009 r4:eb53fd58 r3:c066e404
[ 153.872131] [<c0465eb0>] (dump_stack+0x0/0x24) from [<c003efd8>] (warn_slowpath_common+0x5c/0x74)
[ 153.881469] [<c003ef7c>] (warn_slowpath_common+0x0/0x74) from [<c003f0ac>] (warn_slowpath_fmt+0x40/0x48)
[ 153.891448] r8:eb4c089c r7:00004000 r6:eb5a2840 r5:00000000 r4:eb4c0580
[ 153.898376] r3:00000009
[ 153.901153] [<c003f06c>] (warn_slowpath_fmt+0x0/0x48) from [<c03d7f30>] (tcp_recvmsg+0x194/0x858)
[ 153.910491] r3:b1705247 r2:c05dba55 ...

[Paolo Pisati (p-pisati)]

which kernel are you using?

[Qball Cow (qball-qballcow)]

Happens for me too:
Linux DirkGently 3.4.0-1487-omap4 #6-Ubuntu SMP PREEMPT Mon Oct 1 16:54:59 UTC 2012 armv7l armv7l armv7l GNU/Linux

Latest kernel from the TI PPA.

[Euler D. Graca (eulerdgraca)]

Same problem here. Any intense inbound data transfer will trigger it, but is seems that outbound transfers are good.

Linux panda 3.4.0-1489-omap4 #16-Ubuntu SMP PREEMPT Tue Dec 4 12:51:04 UTC 2012 armv7l armv7l armv7l GNU/Linux

[14189.778228] ------------[ cut here ]------------
[14189.778228] WARNING: at /build/buildd/linux-ti-omap4-3.4.0/net/ipv4/tcp.c:1496 tcp_recvmsg+0x21c/0x9c8()
[14189.778259] recvmsg bug: copied E3E9357C seq E3E935D3 rcvnxt E3E935D8 fl 0
[14189.778259] Modules linked in: wl12xx wlcore mac80211 ppdev lp parport cfg80211 joydev omapdce(C) rpmsg_omx rfcomm omaprpc(C) omap_remoteproc rpmsg_resmgr_common remoteproc bnep omap_rpmsg_resmgr rpmsg_resmgr virtio_rpmsg_bus virtio virtio_ring usbhid hid wlcore_sdio btwilink bluetooth leds_gpio gpio_keys gator btrfs zlib_deflate libcrc32c
[14189.778381] [<c001bc38>] (unwind_backtrace+0x0/0xec) from [<c05a58f0>] (dump_stack+0x20/0x24)
[14189.778411] [<c05a58f0>] (dump_stack+0x20/0x24) from [<c0045044>] (warn_slowpath_common+0x5c/0x74)
[14189.778442] [<c0045044>] (warn_slowpath_common+0x5c/0x74) from [<c0045118>] (warn_slowpath_fmt+0x40/0x48)
[14189.778442] [<c0045118>] (warn_slowpath_fmt+0x40/0x48) from [<c04fa004>] (tcp_recvmsg+0x21c/0x9c8)
[14189.778472] [<c04fa004>] (tcp_recvmsg+0x21c/0x9c8) from [<c051a65c>] (inet_recvmsg+0xb0/0xc8)
[14189.778503] [<c051a65c>] (inet_recvmsg+0xb0/0xc8) from [<c04a58ec>] (do_sock_read+0xd8/0xe8)
[14189.778503] [<c04a58ec>] (do_sock_read+0xd8/0xe8) from [<c04a6854>] (sock_aio_read+0x70/0x78)
[14189.778533] [<c04a6854>] (sock_aio_read+0x70/0x78) from [<c0143268>] (do_sync_readv_writev+0xa4/0xe0)
[14189.778564] [<c0143268>] (do_sync_readv_writev+0xa4/0xe0) from [<c0143508>] (do_readv_writev+0xc8/0x1c0)
[14189.778594] [<c0143508>] (do_readv_writev+0xc8/0x1c0) from [<c01436f0>] (vfs_readv+0x70/0x80)
[14189.778594] [<c01436f0>] (vfs_readv+0x70/0x80) from [<c014374c>] (sys_readv+0x4c/0xd0)
[14189.778625] [<c014374c>] (sys_readv+0x4c/0xd0) from [<c0013200>] (ret_fast_syscall+0x0/0x30)
[14189.778625] ---[ end trace 7497b2171c8532e7 ]---

[kawks (kawks)]

The bug reproduces on the latest kernel by any sufficiently intensive inbound network traffic.

[493647.471008] ------------[ cut here ]------------
[493647.471038] WARNING: at /build/buildd/linux-ti-omap4-3.4.0/net/ipv4/tcp.c:1496 tcp_recvmsg+0x21c/0x9c8()
[493647.471038] recvmsg bug: copied DD1FCC28 seq DD1FD1D0 rcvnxt DD2B2E20 fl 0
[493647.471069] Modules linked in: gpio_keys leds_gpio [last unloaded: wlcore_sdio]
[493647.471099] [<c001bc38>] (unwind_backtrace+0x0/0xec) from [<c05a58f0>] (dump_stack+0x20/0x24)
[493647.471130] [<c05a58f0>] (dump_stack+0x20/0x24) from [<c0045044>] (warn_slowpath_common+0x5c/0x74)
[493647.471130] [<c0045044>] (warn_slowpath_common+0x5c/0x74) from [<c0045118>] (warn_slowpath_fmt+0x40/0x48)
[493647.471160] [<c0045118>] (warn_slowpath_fmt+0x40/0x48) from [<c04fa004>] (tcp_recvmsg+0x21c/0x9c8)
[493647.471191] [<c04fa004>] (tcp_recvmsg+0x21c/0x9c8) from [<c051a65c>] (inet_recvmsg+0xb0/0xc8)
[493647.471191] [<c051a65c>] (inet_recvmsg+0xb0/0xc8) from [<c04a58ec>] (do_sock_read+0xd8/0xe8)
[493647.471221] [<c04a58ec>] (do_sock_read+0xd8/0xe8) from [<c04a6854>] (sock_aio_read+0x70/0x78)
[493647.471252] [<c04a6854>] (sock_aio_read+0x70/0x78) from [<c0142440>] (do_sync_read+0xac/0xe8)
[493647.471252] [<c0142440>] (do_sync_read+0xac/0xe8) from [<c0142ef8>] (vfs_read+0xc8/0x18c)
[493647.471282] [<c0142ef8>] (vfs_read+0xc8/0x18c) from [<c0143008>] (sys_read+0x4c/0x78)
[493647.471313] [<c0143008>] (sys_read+0x4c/0x78) from [<c0013200>] (ret_fast_syscall+0x0/0x30)
[493647.471313] ---[ end trace 346ae6e25f6a5d08 ]---
[493647.471374] ------------[ cut here ]------------
[493647.471405] WARNING: at /build/buildd/linux-ti-omap4-3.4.0/net/ipv4/tcp.c:1508 tcp_recvmsg+0x27c/0x9c8()
[493647.471405] recvmsg bug 2: copied DD1FCC28 seq DD1FCC28 rcvnxt DD2B2E20 fl 0
[493647.471435] Modules linked in: gpio_keys leds_gpio [last unloaded: wlcore_sdio]
[493647.471466] [<c001bc38>] (unwind_backtrace+0x0/0xec) from [<c05a58f0>] (dump_stack+0x20/0x24)
[493647.471496] [<c05a58f0>] (dump_stack+0x20/0x24) from [<c0045044>] (warn_slowpath_common+0x5c/0x74)
[493647.471496] [<c0045044>] (warn_slowpath_common+0x5c/0x74) from [<c0045118>] (warn_slowpath_fmt+0x40/0x48)
[493647.471527] [<c0045118>] (warn_slowpath_fmt+0x40/0x48) from [<c04fa064>] (tcp_recvmsg+0x27c/0x9c8)
[493647.471557] [<c04fa064>] (tcp_recvmsg+0x27c/0x9c8) from [<c051a65c>] (inet_recvmsg+0xb0/0xc8)
[493647.471588] [<c051a65c>] (inet_recvmsg+0xb0/0xc8) from [<c04a58ec>] (do_sock_read+0xd8/0xe8)
[493647.471588] [<c04a58ec>] (do_sock_read+0xd8/0xe8) from [<c04a6854>] (sock_aio_read+0x70/0x78)
[493647.471618] [<c04a6854>] (sock_aio_read+0x70/0x78) from [<c0142440>] (do_sync_read+0xac/0xe8)
[493647.471649] [<c0142440>] (do_sync_read+0xac/0xe8) from [<c0142ef8>] (vfs_read+0xc8/0x18c)
[493647.471649] [<c0142ef8>] (vfs_read+0xc8/0x18c) from [<c0143008>] (sys_read+0x4c/0x78)
[493647.471679] [<c0143008>] (sys_read+0x4c/0x78) from [<c0013200>] (ret_fast_syscall+0x0/0x30)
[493647.471710] ---[ end trace 346ae6e25f6a5d09 ]---

[Steffen Hemer (s-hemer)]

I expirince this from time to time with linux-linaro-lt-omap-3.4-3.4.0 kernel which as far as I know is based on linux-ti-omap4:

Jan 29 14:21:23 linaro-developer kernel: [ 1194.442504] WARNING: at /build/buildd/linux-linaro-lt-omap-3.4-3.4.0/net/ipv4/tcp.c:1508 tcp_recvmsg+0x1b7/0x6d2()
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442535] recvmsg bug 2: copied B7EF3F6 seq B7EF3F6 rcvnxt B80B236 fl 0
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442535] Modules linked in: arc4 wl12xx wlcore mac80211 cfg80211 omapdce(C) rpmsg_omx omaprpc(C) omap_remoteproc rpmsg_resmgr_common remoteproc omap_rpmsg_resmgr rpmsg_resmgr virtio_rpmsg_bus wlcore_sdio btwilink bluetooth usbhid hid
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442687] [<c0011079>] (unwind_backtrace+0x1/0x90) from [<c002c849>] (warn_slowpath_common+0x39/0x50)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442718] [<c002c849>] (warn_slowpath_common+0x39/0x50) from [<c002c8c3>] (warn_slowpath_fmt+0x21/0x2a)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442749] [<c002c8c3>] (warn_slowpath_fmt+0x21/0x2a) from [<c03d05c9>] (tcp_recvmsg+0x1b7/0x6d2)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442779] [<c03d05c9>] (tcp_recvmsg+0x1b7/0x6d2) from [<c03e6b11>] (inet_recvmsg+0x8d/0xac)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442840] [<c03e6b11>] (inet_recvmsg+0x8d/0xac) from [<c0399831>] (sock_recvmsg+0x89/0x9c)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442871] [<c0399831>] (sock_recvmsg+0x89/0x9c) from [<c039a901>] (sys_recvfrom+0x65/0xa4)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442901] [<c039a901>] (sys_recvfrom+0x65/0xa4) from [<c039a953>] (sys_recv+0x13/0x14)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442932] [<c039a953>] (sys_recv+0x13/0x14) from [<c000c121>] (ret_fast_syscall+0x1/0x52)
Jan 29 14:21:23 linaro-developer kernel: [ 1194.442932] ---[ end trace 797ab08fea357dfe ]---

Sometimes it stoppes after somes warnings (don't know why), sometime the log are growing up to gigabytes.

[Winston Smith (smith-winston-101)]

I have also found this issue on a Pandaboard running 3.4.0-1489-omap4, log messages are the same, CPU maxed out and /var/log/messages is about 6GB now!

[Winston Smith (smith-winston-101)]

According to this:

http://permalink.gmane.org/gmane.linux.network/240598

The issue may have been resolved with commit 1ca7ee30630e1022dbcf1b51be20580815ffab73:

http://git.kernel.org/?p=linux/kernel/git/torvalds/linux.git;a=commitdiff;h=1ca7ee30630e1022dbcf1b51be20580815ffab73

I don't believe this commit is in the linux-ti-omap4 tree (at least I tried searching http://dev.omapzoom.org/?p=integration/kernel-ubuntu.git).

[Winston Smith (smith-winston-101)]

Turns out commit 1ca7ee30630e1022dbcf1b51be20580815ffab73 is for newer code not in kernel 3.4.0.

[kovserg (kovserg33)]

I've the same problem:

I've do apt-get dist-upgrate, then apt-get update.
After a while I want to install vlc. Just type apt-get install vlc and wait. When I have low disk space message.
I look at /var/log it was 6.4Gb.
Files kern.log and syslog was filled with message.

...
Apr 11 13:39:48 panda kernel: [ 320.125610] ------------[ cut here ]------------
Apr 11 13:39:48 panda kernel: [ 320.125610] WARNING: at /build/buildd/linux-ti-omap4-3.4.0/net/ipv4/tcp.c:1508 tcp_recvmsg+0x27c/0x9c8()
Apr 11 13:39:48 panda kernel: [ 320.125640] recvmsg bug 2: copied B02CE871 seq B02CE871 rcvnxt B0379F51 fl 0
Apr 11 13:39:48 panda kernel: [ 320.125640] Modules linked in: omapdrm_pvr(O) wl12xx wlcore mac80211 cfg80211 omapdce(C) rpmsg_omx omaprpc(C) bnep joydev rfcomm omap_remoteproc bluetooth rpmsg_resmgr_common remoteproc ppdev lp omap_rpmsg_resmgr rpmsg_resmgr virtio_rpmsg_bus parport virtio virtio_ring dm_multipath wlcore_sdio leds_gpio gpio_keys usbhid hid dm_mirror dm_region_hash dm_log btrfs zlib_deflate libcrc32c
Apr 11 13:39:48 panda kernel: [ 320.125762] [<c001bc38>] (unwind_backtrace+0x0/0xec) from [<c05a6e30>] (dump_stack+0x20/0x24)
Apr 11 13:39:48 panda kernel: [ 320.125793] [<c05a6e30>] (dump_stack+0x20/0x24) from [<c0045120>] (warn_slowpath_common+0x5c/0x74)
Apr 11 13:39:48 panda kernel: [ 320.125823] [<c0045120>] (warn_slowpath_common+0x5c/0x74) from [<c00451f4>] (warn_slowpath_fmt+0x40/0x48)
Apr 11 13:39:48 panda kernel: [ 320.125854] [<c00451f4>] (warn_slowpath_fmt+0x40/0x48) from [<c04faf84>] (tcp_recvmsg+0x27c/0x9c8)
Apr 11 13:39:48 panda kernel: [ 320.125854] [<c04faf84>] (tcp_recvmsg+0x27c/0x9c8) from [<c051b63c>] (inet_recvmsg+0xb0/0xc8)
Apr 11 13:39:48 panda kernel: [ 320.125885] [<c051b63c>] (inet_recvmsg+0xb0/0xc8) from [<c04a6764>] (do_sock_read+0xd8/0xe8)
Apr 11 13:39:48 panda kernel: [ 320.125915] [<c04a6764>] (do_sock_read+0xd8/0xe8) from [<c04a76cc>] (sock_aio_read+0x70/0x78)
Apr 11 13:39:48 panda kernel: [ 320.125946] [<c04a76cc>] (sock_aio_read+0x70/0x78) from [<c01426f0>] (do_sync_read+0xac/0xe8)
Apr 11 13:39:48 panda kernel: [ 320.125976] [<c01426f0>] (do_sync_read+0xac/0xe8) from [<c01431a8>] (vfs_read+0xc8/0x18c)
Apr 11 13:39:48 panda kernel: [ 320.125976] [<c01431a8>] (vfs_read+0xc8/0x18c) from [<c01432b8>] (sys_read+0x4c/0x78)
Apr 11 13:39:48 panda kernel: [ 320.126007] [<c01432b8>] (sys_read+0x4c/0x78) from [<c0013200>] (ret_fast_syscall+0x0/0x30)
Apr 11 13:39:48 panda kernel: [ 320.126007] ---[ end trace 557e6f4cc5b799dd ]---
...

root@panda:/var/log# uname -a
Linux panda 3.4.0-1490-omap4 #8-Ubuntu SMP PREEMPT Tue Apr 2 17:22:09 UTC 2013 armv7l armv7l armv7l GNU/Linux

Can you explain how to fix this issue?

[Winston Smith (smith-winston-101)]

This may be helpful:

https://patchwork.kernel.org/patch/1712661/

[Launchpad Janitor (janitor)]

[Expired for linux-ti-omap4 (Ubuntu) because there has been no activity for 60 days.]

[John Zhang (johnzhanghua)]

This patch will not fix the problem.

https://patchwork.kernel.org/patch/1712661/

I used the one below to fix the issue on Dart Board:

https://gerrit.chromium.org/gerrit/#/c/37666