On Sun, Jul 23, 2017 at 5:35 AM, Trevor Cordes <tre...@tecnopolis.ca> wrote:
> Hi! I've bisected a bug I'm seeing to:
> c21b48cc1bbf2f5af3ef54ada559f7fadf8b508b
> net: adjust skb->truesize in ___pskb_trim()
>
> The bug manifests as my NFS4 (TCP) client mount hanging after 5-10s of
> heavy read data transfer, which also produces: kernel BUG at
> ./include/linux/mm.h:462 (see full trace at bottom)
>
> I must reboot to regain nfs access. I can make this bug occur on demand
> by just playing some video from the nfs export and skipping around for
> 5-10s or so.
>
> Every 10 or so times this bug occurs the entire system hard freezes and
> even magic SysRq won't work.
>
> This bug started for me in Fedora 24 as soon as 4.11.x was put out. F24
> 4.10.x does not have this bug, and that is what I am currently using. I am
> currently taking the final step of rpmbuilding the F24 src rpm with a
> patch to undo c21b48, just to confirm it for sure. But it will take all
> day to build, so I thought I'd report my bisect right now.
>
> I've had a RHBZ up for this:
> https://bugzilla.redhat.com/show_bug.cgi?id=1455086
>
> That BZ has some info as to my mount/export options. My setup *must* be
> different from normal as I see no other person on the net reporting this
> bug. My mount options might be a little tweaked, I guess; also FYI, this
> box uses a strict iptables setup, if that could matter. I also use NFS4
> only, with TCP, and strictly-preset ports to be more iptables friendly.
>
> Thanks!
>
> Complete bug trace below (have dozens of these from tests if more are
> needed, but stack trace is the same *every* time):
>
> Jul 23 05:34:14 pog kernel: [ 118.789187] page:fffff662c8761a00 count:0
> mapcount:0 mapping: (null) index:0x0
> Jul 23 05:34:14 pog kernel: [ 118.789196] flags: 0x17ffffc0000000()
> Jul 23 05:34:14 pog kernel: [ 118.789201] raw: 0017ffffc0000000
> 0000000000000000 0000000000000000 00000000ffffffff
> Jul 23 05:34:14 pog kernel: [ 118.789204] raw: dead000000000100
> dead000000000200 0000000000000000 0000000000000000
> Jul 23 05:34:14 pog kernel: [ 118.789206] page dumped because:
> VM_BUG_ON_PAGE(page_ref_count(page) == 0)
> Jul 23 05:34:14 pog kernel: [ 118.789218] ------------[ cut here
> ]------------
> Jul 23 05:34:14 pog kernel: [ 118.789221] kernel BUG at
> ./include/linux/mm.h:462!
> Jul 23 05:34:14 pog kernel: [ 118.789224] invalid opcode: 0000 [#1] SMP
> Jul 23 05:34:14 pog kernel: [ 118.789226] Modules linked in: rpcsec_gss_krb5
> nfsv4 xfrm4_tunnel tunnel4 ipcomp xfrm_ipcomp esp4 ah4 dns_resolver af_key
> nfs fscache 8021q garp mrp stp llc cfg80211 rfkill nf_nat_pptp
> nf_nat_proto_gre nf_conntrack_pptp nf_conntrack_proto_gre
> nf_conntrack_netbios_ns nf_conntrack_broadcast xt_mac nf_log_ipv4
> nf_log_common xt_LOG xt_limit xt_conntrack xt_nat ipt_MASQUERADE
> nf_nat_masquerade_ipv4 xt_REDIRECT nf_nat_redirect iptable_nat
> nf_conntrack_ipv4
> nf_defrag_ipv4 ip6t_REJECT nf_reject_ipv6 ip6table_filter ip6_tables asc7621
> nf_nat_ipv4 nf_nat nf_conntrack libcrc32c xt_TCPMSS iptable_mangle
> iptable_raw iptable_security snd_hda_codec_hdmi snd_hda_codec_idt
> snd_hda_codec_generic snd_hda_intel snd_hda_codec coretemp ppdev iTCO_wdt
> gpio_ich iTCO_vendor_support snd_hda_core kvm_intel snd_hwdep kvm snd_seq
> Jul 23 05:34:14 pog kernel: [ 118.789288] snd_seq_device irqbypass joydev
> snd_pcm nfsd pcspkr snd_timer i2c_i801 snd parport_pc acpi_cpufreq tpm_tis
> parport shpchp tpm_tis_core soundcore lpc_ich tpm auth_rpcgss nfs_acl lockd
> grace sunrpc raid1 raid0 firewire_ohci serio_raw firewire_core ata_generic
> pata_acpi crc_itu_t aic7xxx e1000e e1000 scsi_transport_spi ptp pps_core
> pata_marvell floppy
> Jul 23 05:34:14 pog kernel: [ 118.789327] CPU: 2 PID: 541 Comm: kworker/2:1H
> Not tainted 4.11.0-rc8+ #13
> Jul 23 05:34:14 pog kernel: [ 118.789330] Hardware name:
> /D975XBX2, BIOS BX97520J.86A.2838.2008.0903.1859 09/03/2008
> Jul 23 05:34:14 pog kernel: [ 118.789362] Workqueue: xprtiod
> xs_tcp_data_receive_workfn [sunrpc]
> Jul 23 05:34:14 pog kernel: [ 118.789366] task: ffff8d2919184880 task.stack:
> ffffb168813a8000
> Jul 23 05:34:14 pog kernel: [ 118.789372] RIP: 0010:page_frag_free+0x6d/0x80
> Jul 23 05:34:14 pog kernel: [ 118.789375] RSP: 0018:ffffb168813abd10 EFLAGS:
> 00010246
> Jul 23 05:34:14 pog kernel: [ 118.789378] RAX: 000000000000003e RBX:
> fffff662c88c6d80 RCX: 0000000000000006
> Jul 23 05:34:14 pog kernel: [ 118.789380] RDX: 0000000000000000 RSI:
> 0000000000000000 RDI: ffff8d292fd0e0a0
> Jul 23 05:34:14 pog kernel: [ 118.789383] RBP: ffffb168813abd10 R08:
> 00000000000c0ad6 R09: 00000000000003f4
> Jul 23 05:34:14 pog kernel: [ 118.789385] R10: ffff8d291a556d00 R11:
> ffffffffb222ac2d R12: ffff8d291a556d00
> Jul 23 05:34:14 pog kernel: [ 118.789388] R13: 0000000000000008 R14:
> ffff8d291d868340 R15: 0000000000002d40
> Jul 23 05:34:14 pog kernel: [ 118.789391] FS: 0000000000000000(0000)
> GS:ffff8d292fd00000(0000) knlGS:0000000000000000
> Jul 23 05:34:14 pog kernel: [ 118.789394] CS: 0010 DS: 0000 ES: 0000 CR0:
> 0000000080050033
> Jul 23 05:34:14 pog kernel: [ 118.789396] CR2: 00007f7597990008 CR3:
> 000000021e710000 CR4: 00000000000006e0
> Jul 23 05:34:14 pog kernel: [ 118.789399] Call Trace:
> Jul 23 05:34:14 pog kernel: [ 118.789406] skb_free_head+0x28/0x30
> Jul 23 05:34:14 pog kernel: [ 118.789410] skb_release_data+0xf5/0x130
> Jul 23 05:34:14 pog kernel: [ 118.789413] skb_release_all+0x24/0x30
> Jul 23 05:34:14 pog kernel: [ 118.789415] __kfree_skb+0x12/0x20
> Jul 23 05:34:14 pog kernel: [ 118.789420] tcp_read_sock+0x11a/0x1e0
> Jul 23 05:34:14 pog kernel: [ 118.789437] ? xs_tcp_setup_socket+0x400/0x400
> [sunrpc]
> Jul 23 05:34:14 pog kernel: [ 118.789453] ? xs_tcp_setup_socket+0x400/0x400
> [sunrpc]
> Jul 23 05:34:14 pog kernel: [ 118.789470]
> xs_tcp_data_receive_workfn+0xbb/0x160 [sunrpc]
> Jul 23 05:34:14 pog kernel: [ 118.789474] process_one_work+0x197/0x450
> Jul 23 05:34:14 pog kernel: [ 118.789478] worker_thread+0x4e/0x4a0
> Jul 23 05:34:14 pog kernel: [ 118.789482] kthread+0x109/0x140
> Jul 23 05:34:14 pog kernel: [ 118.789485] ? process_one_work+0x450/0x450
> Jul 23 05:34:14 pog kernel: [ 118.789488] ? kthread_park+0x90/0x90
> Jul 23 05:34:14 pog kernel: [ 118.789492] ret_from_fork+0x2c/0x40
> Jul 23 05:34:14 pog kernel: [ 118.789494] Code: 47 1c 85 c0 74 19 f0 ff 4f
> 1c 74 02 5d c3 48 8b 07 31 f6 f6 c4 80 75 15 e8 41 fb ff ff 5d c3 48 c7 c6 40
> 0e c4 b1 e8 83 07 03 00 <0f> 0b 8b 77 6c eb e6 48 8b 05 15 e2 c3 00 eb a4 0f
> 1f 00 66 66
> Jul 23 05:34:14 pog kernel: [ 118.789542] RIP: page_frag_free+0x6d/0x80 RSP:
> ffffb168813abd10
> Jul 23 05:34:14 pog kernel: [ 118.789620] ---[ end trace 7be02f8b337d1e80
> ]---
> Jul 23 05:34:19 pog kernel: [ 123.294692] nfs: server 192.168.100.2 not
> responding, still trying
>
Hi Trevor, thanks for the report and bisection !
This commit exposed at least one bug, have you tried the following fix :
e44699d2c28067f69698ccb68dd3ddeacfebc434 ("net: handle
NAPI_GRO_FREE_STOLEN_HEAD case also in napi_frags_finish()")
If this commit does not help, please provide what kind of NIC you are using.
Thanks.
