Return-path: Received: from mail-ee0-f46.google.com ([74.125.83.46]:55153 "EHLO mail-ee0-f46.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751926Ab1LAKd5 (ORCPT ); Thu, 1 Dec 2011 05:33:57 -0500 MIME-Version: 1.0 Date: Thu, 1 Dec 2011 11:33:55 +0100 Message-ID: (sfid-20111201_113417_190120_78967B4A) Subject: Busy looping iwl3945 driver From: Zdenek Kabelac To: Linux Kernel Mailing List Cc: linux-wireless@vger.kernel.org Content-Type: text/plain; charset=ISO-8859-1 Sender: linux-wireless-owner@vger.kernel.org List-ID: Hi Today I've noticed 100% CPU occupied by kworker thread - which appeared to be the result of some iwl3945 driver interaction. Here are some trace of some tasks from that moment. It looked like when I've then even tried to run 'mc' of 'ifconfig' - they could not start since some device lock was kept busy. The problem was most probably caused by doing suspend when attached to the wireless network and resuming in wired docking station, without having the previous wireless AP available. My hw - T61, 4G, C2D, iwl3945 wifi, X86_64 kernel 3.2.0-rc3 Only reboot fixed this problem. NetworkManager D 0000000000000000 0 648 1 0x00000004 ffff8801301157e8 0000000000000046 ffffffff814d9fe4 0000000000000000 ffff8801301157f8 ffff88012c968000 0000000000000000 ffff880130115fd8 ffff880130115fd8 ffff880130115fd8 ffffffff81a0d020 ffff88012c968000 Call Trace: [] ? __schedule+0x994/0xb50 [] schedule+0x3f/0x60 [] mutex_lock_nested+0x1b2/0x3f0 [] ? ieee80211_ifa_changed+0x9f/0x150 [mac80211] [] ? ieee80211_ifa_changed+0x9f/0x150 [mac80211] [] ieee80211_ifa_changed+0x9f/0x150 [mac80211] [] notifier_call_chain+0x93/0x100 [] __blocking_notifier_call_chain+0x78/0xb0 [] blocking_notifier_call_chain+0x16/0x20 [] __inet_del_ifa+0xb6/0x290 [] inet_rtm_deladdr+0x10e/0x160 [] rtnetlink_rcv_msg+0x124/0x2e0 [] ? __rtnl_unlock+0x20/0x20 [] netlink_rcv_skb+0xa9/0xd0 [] rtnetlink_rcv+0x25/0x40 [] netlink_unicast+0x2c0/0x310 [] netlink_sendmsg+0x2b6/0x310 [] ? sock_update_classid+0xb8/0x1f0 [] sock_sendmsg+0x10e/0x1e0 [] ? sock_recvmsg+0x18d/0x210 [] ? might_fault+0x53/0xb0 [] ? might_fault+0x9c/0xb0 [] ? might_fault+0x53/0xb0 [] ? verify_iovec+0x56/0xd0 [] __sys_sendmsg+0x376/0x380 [] ? fget_light+0x48/0x3b0 [] ? fget_light+0xe1/0x3b0 [] ? fget_light+0x48/0x3b0 [] ? mntput+0x1f/0x30 [] sys_sendmsg+0x49/0x90 [] system_call_fastpath+0x16/0x1b avahi-daemon D 0000000000000246 0 667 1 0x00000000 ffff880127df5ba8 0000000000000046 0000000000000000 0000000000000000 ffff880127df5bb8 ffff880128be4600 0000000000000000 ffff880127df5fd8 ffff880127df5fd8 ffff880127df5fd8 ffff88012ca72300 ffff880128be4600 Call Trace: [] schedule+0x3f/0x60 [] mutex_lock_nested+0x1b2/0x3f0 [] ? rtnl_lock+0x17/0x20 [] ? rtnl_lock+0x17/0x20 [] rtnl_lock+0x17/0x20 [] ip_mc_leave_group+0x2f/0x180 [] do_ip_setsockopt+0x6d4/0xdb0 [] ? sock_sendmsg+0x10e/0x1e0 [] ? pipe_write+0x2ec/0x5b0 [] ? fsnotify+0x93/0x600 [] ? sys_sendto+0x101/0x130 [] ip_setsockopt+0x36/0xb0 [] udp_setsockopt+0x1b/0x40 [] sock_common_setsockopt+0x14/0x20 [] sys_setsockopt+0x7f/0xe0 [] system_call_fastpath+0x16/0x1b wpa_supplicant D 0000000000000246 0 770 1 0x00000000 ffff880127c17908 0000000000000046 0000000000000000 0000000000000000 ffff880127c17918 ffff880127e02300 0000000000000000 ffff880127c17fd8 ffff880127c17fd8 ffff880127c17fd8 ffff88012ca72300 ffff880127e02300 Call Trace: [] schedule+0x3f/0x60 [] mutex_lock_nested+0x1b2/0x3f0 [] ? rtnl_lock+0x17/0x20 [] ? rtnl_lock+0x17/0x20 [] rtnl_lock+0x17/0x20 [] nl80211_pre_doit+0xf5/0x190 [cfg80211] [] genl_rcv_msg+0x1c3/0x250 [] ? genl_rcv+0x40/0x40 [] netlink_rcv_skb+0xa9/0xd0 [] genl_rcv+0x25/0x40 [] netlink_unicast+0x2c0/0x310 [] netlink_sendmsg+0x2b6/0x310 [] ? sock_update_classid+0xb8/0x1f0 [] sock_sendmsg+0x10e/0x1e0 [] ? sock_recvmsg+0x18d/0x210 [] ? might_fault+0x53/0xb0 [] ? might_fault+0x9c/0xb0 [] ? might_fault+0x53/0xb0 [] ? verify_iovec+0x56/0xd0 [] __sys_sendmsg+0x376/0x380 [] ? set_current_blocked+0x34/0x60 [] ? fpu_finit+0x21/0x40 [] ? init_fpu+0x4a/0x180 [] ? restore_i387_xstate+0xc8/0x1d0 [] ? fget_light+0x1af/0x3b0 [] ? _raw_spin_unlock_irq+0x3b/0x60 [] sys_sendmsg+0x49/0x90 [] system_call_fastpath+0x16/0x1b ntpd D 0000000000000246 0 21324 1 0x00000000 ffff880127adfca8 0000000000000046 0000000000000000 0000000000000000 ffff880127adfcb8 ffff880127f5c600 0000000000000000 ffff880127adffd8 ffff880127adffd8 ffff880127adffd8 ffff8800379e4600 ffff880127f5c600 Call Trace: [] schedule+0x3f/0x60 [] mutex_lock_nested+0x1b2/0x3f0 [] ? rtnl_lock+0x17/0x20 [] ? rtnl_lock+0x17/0x20 [] rtnl_lock+0x17/0x20 [] dev_ioctl+0x3c5/0x660 [] ? lockdep_init_map+0xf0/0x590 [] sock_do_ioctl+0x5d/0x70 [] sock_ioctl+0x79/0x2f0 [] do_vfs_ioctl+0x98/0x570 [] ? _raw_spin_unlock+0x35/0x60 [] ? fd_install+0x7d/0x100 [] ? fget_light+0x1af/0x3b0 [] sys_ioctl+0x91/0xa0 [] system_call_fastpath+0x16/0x1b Here I've tried 'mc' and rmmod of iwl3945 (which had in fact open count == 0) mc D 0000000000000000 0 12325 12174 0x00000000 ffff880007a77ca8 0000000000000046 ffffffff814d9fe4 0000000000000000 ffff880007a77cb8 ffff880037918000 0000000000000000 ffff880007a77fd8 ffff880007a77fd8 ffff880007a77fd8 ffffffff81a0d020 ffff880037918000 Call Trace: [] ? __schedule+0x994/0xb50 [] schedule+0x3f/0x60 [] mutex_lock_nested+0x1b2/0x3f0 [] ? rtnl_lock+0x17/0x20 [] ? rtnl_lock+0x17/0x20 [] rtnl_lock+0x17/0x20 [] dev_ioctl+0x3c5/0x660 [] ? lockdep_init_map+0xf0/0x590 [] sock_do_ioctl+0x5d/0x70 [] sock_ioctl+0x79/0x2f0 [] do_vfs_ioctl+0x98/0x570 [] ? _raw_spin_unlock+0x35/0x60 [] ? fd_install+0x7d/0x100 [] ? fget_light+0x1af/0x3b0 [] sys_ioctl+0x91/0xa0 [] system_call_fastpath+0x16/0x1b rmmod D 0000000000000000 0 12340 22112 0x00000000 ffff880051811bf8 0000000000000046 ffffffff814d9fe4 ffffffff814d5fd1 0000000000000001 ffff8800b0cd8000 0000000000000046 ffff880051811fd8 ffff880051811fd8 ffff880051811fd8 ffff880136d44600 ffff8800b0cd8000 Call Trace: [] ? __schedule+0x994/0xb50 [] ? __slab_free+0x233/0x3aa [] schedule+0x3f/0x60 [] rwsem_down_failed_common+0xc5/0x160 [] rwsem_down_write_failed+0x13/0x20 [] call_rwsem_down_write_failed+0x13/0x20 [] ? blocking_notifier_chain_unregister+0x27/0xe0 [] ? down_write+0x89/0xb0 [] ? blocking_notifier_chain_unregister+0x27/0xe0 [] blocking_notifier_chain_unregister+0x27/0xe0 [] unregister_inetaddr_notifier+0x18/0x20 [] ieee80211_unregister_hw+0x46/0x120 [mac80211] [] iwl3945_pci_remove+0x57/0x300 [iwl3945] [] ? _raw_spin_unlock_irqrestore+0x42/0x80 [] pci_device_remove+0x46/0x110 [] __device_release_driver+0x7c/0xe0 [] driver_detach+0xd8/0xe0 [] bus_remove_driver+0x91/0x110 [] driver_unregister+0x62/0xa0 [] pci_unregister_driver+0x44/0xc0 [] iwl3945_exit+0x10/0x17 [iwl3945] [] sys_delete_module+0x16e/0x250 [] ? trace_hardirqs_on_caller+0x1f/0x1b0 [] system_call_fastpath+0x16/0x1b Here is 'pert record -a -g' # Overhead Command Shared Object Symbol # ........ ............... .......................... ........................................... # 97.57% kworker/u:3 [kernel.kallsyms] [k] lock_timer_base | --- lock_timer_base try_to_del_timer_sync del_timer_sync iwl3945_send_tx_power ieee80211_bss_info_change_notify ieee80211_sta_eosp_irqsafe ieee80211_sta_eosp_irqsafe ieee80211_stop_tx_ba_cb ieee80211_stop_tx_ba_cb ieee80211_stop_tx_ba_cb ieee80211_stop_tx_ba_cb process_one_work worker_thread kthread kernel_thread_helper 0.38% kworker/u:3 [kernel.kallsyms] [k] ioread32 | --- ioread32 | |--37.76%-- iwl_legacy_send_bt_config | iwl3945_rx_queue_restock | iwl3945_irq_tasklet | tasklet_action | __do_softirq | call_softirq | do_softirq | irq_exit | __irqentry_text_start | ret_from_intr | try_to_del_timer_sync | del_timer_sync | iwl3945_send_tx_power | ieee80211_bss_info_change_notify | ieee80211_sta_eosp_irqsafe | ieee80211_sta_eosp_irqsafe | ieee80211_stop_tx_ba_cb | ieee80211_stop_tx_ba_cb | ieee80211_stop_tx_ba_cb | ieee80211_stop_tx_ba_cb | process_one_work | worker_thread | kthread | kernel_thread_helper | |--31.13%-- iwl3945_irq_tasklet | tasklet_action | __do_softirq | call_softirq | do_softirq | irq_exit | | | |--92.86%-- __irqentry_text_start | | ret_from_intr | | try_to_del_timer_sync | | del_timer_sync | | iwl3945_send_tx_power | | ieee80211_bss_info_change_notify | | ieee80211_sta_eosp_irqsafe | | ieee80211_sta_eosp_irqsafe | | ieee80211_stop_tx_ba_cb | | ieee80211_stop_tx_ba_cb | | ieee80211_stop_tx_ba_cb | | ieee80211_stop_tx_ba_cb | | process_one_work | | worker_thread | | kthread | | kernel_thread_helper | | | --7.14%-- smp_apic_timer_interrupt | apic_timer_interrupt | try_to_del_timer_sync | del_timer_sync | iwl3945_send_tx_power | ieee80211_bss_info_change_notify | ieee80211_sta_eosp_irqsafe | ieee80211_sta_eosp_irqsafe | ieee80211_stop_tx_ba_cb | ieee80211_stop_tx_ba_cb | ieee80211_stop_tx_ba_cb | ieee80211_stop_tx_ba_cb | process_one_work | worker_thread | kthread | kernel_thread_helper | --31.12%-- iwl_legacy_add_beacon_time handle_irq_event_percpu handle_irq_event handle_edge_irq handle_irq __irqentry_text_start ret_from_intr try_to_del_timer_sync del_timer_sync iwl3945_send_tx_power ieee80211_bss_info_change_notify ieee80211_sta_eosp_irqsafe ieee80211_sta_eosp_irqsafe ieee80211_stop_tx_ba_cb ieee80211_stop_tx_ba_cb ieee80211_stop_tx_ba_cb ieee80211_stop_tx_ba_cb process_one_work worker_thread kthread kernel_thread_helper 0.27% kworker/u:3 [kernel.kallsyms] [k] read_hpet .... Zdenek