From mboxrd@z Thu Jan 1 00:00:00 1970 From: Carsten Emde Subject: [OSADL QA 3.18.7-rt2 #2] BUG: scheduling while atomic: nfsd and irq/30-eth0 Date: Wed, 04 Mar 2015 22:27:43 +0100 Message-ID: <54F778CF.1090201@osadl.org> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Cc: rt-users To: Sebastian Andrzej Siewior Return-path: Received: from toro.web-alm.net ([62.245.132.31]:32790 "EHLO toro.web-alm.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752325AbbCDVaL (ORCPT ); Wed, 4 Mar 2015 16:30:11 -0500 Sender: linux-rt-users-owner@vger.kernel.org List-ID: An NFS server occasionally runs into "BUG: scheduling while atomic". The message appears about once every 2 to 4 minutes at heavy NFS traffic. There are only two different patterns, one through nfsd and the other through the network interrupt thread. I applied Steven's patch https://lkml.org/lkml/2014/1/16/366 to get as much information as possible. Thanks, Carsten. irq/30-eth0: [ 9346.799757] BUG: scheduling while atomic: irq/30-eth0/1123/0x00000002 [ 9346.799791] Modules linked in: eeprom nfsd lockd grace nfs_acl exportfs auth_rpcgss oid_registry sunrpc ip6t_REJECT nf_reject_ipv6 bluetooth nf_conntrack_ipv6 rfkill nf_defrag_ipv6 ip6table_filter cpufreq_ondemand ip6_tables it87 hwmon_vid coretemp snd_hda_codec_hdmi snd_hda_codec_via snd_hda_codec_generic snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep r8169 mii iTCO_wdt iTCO_vendor_support snd_seq snd_seq_device snd_pcm snd_timer xhci_pci xhci_hcd wmi i2c_i801 serio_raw lpc_ich mfd_core snd microcode pcspkr soundcore acpi_cpufreq ipv6 i915 drm_kms_helper drm video i2c_algo_bit i2c_core [ 9346.799804] Preemption disabled at:[] svc_xprt_enqueue+0x16/0x18 [sunrpc] [ 9346.799804] [ 9346.799807] CPU: 2 PID: 1123 Comm: irq/30-eth0 Tainted: G W 3.18.7-rt2-nodebug #32 [ 9346.799808] Hardware name: System manufacturer System Product Name/P8H61-I, BIOS 0403 02/11/2011 [ 9346.799810] ffff8800adc49cb0 ffff880137d5b6e8 ffffffff814c6c96 0000000000000000 [ 9346.799811] ffff88013b28aa00 ffff880137d5b6f8 ffffffff814c3e55 ffff880137d5b778 [ 9346.799813] ffffffff814c8427 ffff880137d5b728 ffffffff810862a6 ffff880137d58000 [ 9346.799813] Call Trace: [ 9346.799818] [] dump_stack+0x4f/0x7c [ 9346.799820] [] __schedule_bug+0x9a/0xad [ 9346.799822] [] __schedule+0x8f/0x55a [ 9346.799824] [] ? __rt_mutex_adjust_prio+0x26/0x2a [ 9346.799826] [] ? _raw_spin_unlock_irqrestore+0x19/0x2c [ 9346.799828] [] schedule+0x7a/0x8d [ 9346.799830] [] rt_spin_lock_slowlock+0x150/0x1df [ 9346.799832] [] rt_spin_lock_fastlock.constprop.12+0x1f/0x21 [ 9346.799834] [] rt_spin_lock+0xe/0x10 [ 9346.799840] [] svc_xprt_do_enqueue+0x7d/0x14c [sunrpc] [ 9346.799845] [] svc_xprt_enqueue+0x16/0x18 [sunrpc] [ 9346.799851] [] svc_tcp_data_ready+0x2b/0x52 [sunrpc] [ 9346.799854] [] tcp_rcv_established+0x344/0x44d [ 9346.799856] [] tcp_v4_do_rcv+0x86/0x251 [ 9346.799858] [] ? sk_filter+0xaf/0xba [ 9346.799860] [] tcp_v4_rcv+0x50d/0x7ab [ 9346.799862] [] ? xfrm4_policy_check.constprop.4+0x52/0x52 [ 9346.799863] [] ? xfrm4_policy_check.constprop.4+0x52/0x52 [ 9346.799865] [] ip_local_deliver_finish+0xd9/0x178 [ 9346.799867] [] ? xfrm4_policy_check.constprop.4+0x52/0x52 [ 9346.799868] [] NF_HOOK.constprop.3+0x4c/0x53 [ 9346.799870] [] ip_local_deliver+0x4f/0x54 [ 9346.799872] [] ip_rcv_finish+0x32a/0x341 [ 9346.799873] [] ? inet_add_protocol+0x43/0x43 [ 9346.799875] [] NF_HOOK.constprop.3+0x4c/0x53 [ 9346.799876] [] ip_rcv+0x319/0x376 [ 9346.799879] [] __netif_receive_skb_core+0x4a9/0x4e8 [ 9346.799881] [] ? read_tsc+0x9/0xb [ 9346.799883] [] __netif_receive_skb+0x5a/0x5f [ 9346.799884] [] netif_receive_skb_internal+0x87/0x8e [ 9346.799887] [] ? inet_gro_complete+0xc9/0xd3 [ 9346.799888] [] napi_gro_complete+0xbf/0xca [ 9346.799889] [] napi_gro_flush+0x51/0x6d [ 9346.799890] [] napi_complete+0x1e/0x36 [ 9346.799894] [] rtl8169_poll+0x521/0x53f [r8169] [ 9346.799897] [] ? debug_smp_processor_id+0x17/0x19 [ 9346.799898] [] ? preempt_count_add+0x55/0xe9 [ 9346.799900] [] net_rx_action+0x91/0x1ac [ 9346.799902] [] ? check_preemption_disabled+0x9b/0x132 [ 9346.799905] [] do_current_softirqs+0x15f/0x26f [ 9346.799907] [] ? irq_thread_fn+0x41/0x41 [ 9346.799908] [] __local_bh_enable+0x4b/0x6e [ 9346.799910] [] local_bh_enable+0xe/0x10 [ 9346.799911] [] irq_forced_thread_fn+0x4e/0x5a [ 9346.799913] [] irq_thread+0x8e/0x16c [ 9346.799914] [] ? irq_finalize_oneshot.part.5+0x9f/0x9f [ 9346.799915] [] ? wake_threads_waitq+0x2e/0x2e [ 9346.799918] [] kthread+0xc4/0xcc [ 9346.799919] [] ? __init_kthread_worker+0x50/0x50 [ 9346.799922] [] ret_from_fork+0x7c/0xb0 [ 9346.799923] [] ? __init_kthread_worker+0x50/0x50 [ 9346.799925] --------------------------- [ 9346.799925] | preempt count: 00000002 ] [ 9346.799926] | 2-level deep critical section nesting: [ 9346.799926] ---------------------------------------- [ 9346.799931] .. [] .... svc_xprt_do_enqueue+0x53/0x14c [sunrpc] [ 9346.799936] .....[] .. ( <= svc_xprt_enqueue+0x16/0x18 [sunrpc]) [ 9346.799938] .. [] .... __schedule+0x49/0x55a [ 9346.799939] .....[] .. ( <= schedule+0x7a/0x8d) [ 9346.799939] nfsd: [ 9545.948169] BUG: scheduling while atomic: nfsd/1358/0x00000002 [ 9545.948195] Modules linked in: eeprom nfsd lockd grace nfs_acl exportfs auth_rpcgss oid_registry sunrpc ip6t_REJECT nf_reject_ipv6 bluetooth nf_conntrack_ipv6 rfkill nf_defrag_ipv6 ip6table_filter cpufreq_ondemand ip6_tables it87 hwmon_vid coretemp snd_hda_codec_hdmi snd_hda_codec_via snd_hda_codec_generic snd_hda_intel snd_hda_controller snd_hda_codec snd_hwdep r8169 mii iTCO_wdt iTCO_vendor_support snd_seq snd_seq_device snd_pcm snd_timer xhci_pci xhci_hcd wmi i2c_i801 serio_raw lpc_ich mfd_core snd microcode pcspkr soundcore acpi_cpufreq ipv6 i915 drm_kms_helper drm video i2c_algo_bit i2c_core [ 9545.948204] Preemption disabled at:[] svc_xprt_received+0x54/0x61 [sunrpc] [ 9545.948205] [ 9545.948207] CPU: 0 PID: 1358 Comm: nfsd Tainted: G W 3.18.7-rt2-nodebug #32 [ 9545.948208] Hardware name: System manufacturer System Product Name/P8H61-I, BIOS 0403 02/11/2011 [ 9545.948210] ffff880137de5fa0 ffff8800aca1bc48 ffffffff814c6c96 0000000000000000 [ 9545.948211] ffff88013b08aa00 ffff8800aca1bc58 ffffffff814c3e55 ffff8800aca1bcd8 [ 9545.948213] ffffffff814c8427 ffff8800aca1bc88 ffffffff814ca486 ffff8800aca18000 [ 9545.948213] Call Trace: [ 9545.948217] [] dump_stack+0x4f/0x7c [ 9545.948219] [] __schedule_bug+0x9a/0xad [ 9545.948220] [] __schedule+0x8f/0x55a [ 9545.948222] [] ? _raw_spin_lock_irqsave+0x1d/0x44 [ 9545.948224] [] ? _raw_spin_unlock_irqrestore+0x19/0x2c [ 9545.948226] [] schedule+0x7a/0x8d [ 9545.948228] [] rt_spin_lock_slowlock+0x150/0x1df [ 9545.948234] [] ? svc_recvfrom+0x5b/0x6e [sunrpc] [ 9545.948237] [] rt_spin_lock_fastlock.constprop.12+0x1f/0x21 [ 9545.948239] [] rt_spin_lock+0xe/0x10 [ 9545.948244] [] svc_xprt_do_enqueue+0x7d/0x14c [sunrpc] [ 9545.948250] [] svc_xprt_received+0x54/0x61 [sunrpc] [ 9545.948255] [] svc_recv+0x6a7/0x727 [sunrpc] [ 9545.948260] [] nfsd+0xe6/0x14f [nfsd] [ 9545.948263] [] ? nfsd_destroy+0x64/0x64 [nfsd] [ 9545.948265] [] kthread+0xc4/0xcc [ 9545.948267] [] ? __init_kthread_worker+0x50/0x50 [ 9545.948270] [] ret_from_fork+0x7c/0xb0 [ 9545.948271] [] ? __init_kthread_worker+0x50/0x50 [ 9545.948273] --------------------------- [ 9545.948273] | preempt count: 00000002 ] [ 9545.948274] | 2-level deep critical section nesting: [ 9545.948274] ---------------------------------------- [ 9545.948280] .. [] .... svc_xprt_do_enqueue+0x53/0x14c [sunrpc] [ 9545.948285] .....[] .. ( <= svc_xprt_received+0x54/0x61 [sunrpc]) [ 9545.948286] .. [] .... __schedule+0x49/0x55a [ 9545.948288] .....[] .. ( <= schedule+0x7a/0x8d) [ 9545.948288]