Re: [linux-next: May 13] intel/iwlwifi/mvm/mvm.h:1069 suspicious rcu_dereference_protected() usage

2016-05-14 Thread Sergey Senozhatsky
On (05/15/16 01:31), Sergey Senozhatsky wrote:
> [11455.550649] ===
> [11455.550652] [ INFO: suspicious RCU usage. ]
> [11455.550657] 4.6.0-rc7-next-20160513-dbg-4-g8de8b92-dirty #655 Not 
> tainted
> [11455.550660] ---
> [11455.550664] drivers/net/wireless/intel/iwlwifi/mvm/mvm.h:1069 suspicious 
> rcu_dereference_protected() usage!
> [11455.550667] 
>other info that might help us debug this:
> 
> [11455.550671] 
>rcu_scheduler_active = 1, debug_locks = 0
> [11455.550675] 5 locks held by irq/29-iwlwifi/247:
> [11455.550677]  #0:  (sync_cmd_lockdep_map){..}, at: [] 
> iwl_pcie_irq_handler+0x0/0x635 [iwlwifi]
> [11455.550705]  #1:  (&(>lock)->rlock){+.+...}, at: [] 
> iwl_pcie_rx_handle+0x38/0x5d5 [iwlwifi]
> [11455.550725]  #2:  (rcu_read_lock){..}, at: [] 
> ieee80211_rx_napi+0x152/0x8e2 [mac80211]
> [11455.550768]  #3:  (&(>rx_path_lock)->rlock){+.-...}, at: 
> [] ieee80211_rx_handlers+0x2e/0x1fe1 [mac80211]
> [11455.550804]  #4:  (rcu_read_lock){..}, at: [] 
> iwl_mvm_update_tkip_key+0x0/0x162 [iwlmvm]
> [11455.550833] 


[ 5406.034379] iwlwifi :02:00.0: Queue 16 stuck for 1 ms.
[ 5406.034385] iwlwifi :02:00.0: Current SW read_ptr 98 write_ptr 125
[ 5406.034431] iwl data: : 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
00  
[ 5406.034454] iwlwifi :02:00.0: FH TRBs(0) = 0x8000300f
[ 5406.034475] iwlwifi :02:00.0: FH TRBs(1) = 0xc0110071
[ 5406.034491] iwlwifi :02:00.0: FH TRBs(2) = 0x
[ 5406.034505] iwlwifi :02:00.0: FH TRBs(3) = 0x8030001e
[ 5406.034520] iwlwifi :02:00.0: FH TRBs(4) = 0x
[ 5406.034536] iwlwifi :02:00.0: FH TRBs(5) = 0x
[ 5406.034551] iwlwifi :02:00.0: FH TRBs(6) = 0x
[ 5406.034566] iwlwifi :02:00.0: FH TRBs(7) = 0x00709087
[ 5406.034625] iwlwifi :02:00.0: Q 0 is active and mapped to fifo 3 ra_tid 
0x [31,31]
[ 5406.034690] iwlwifi :02:00.0: Q 1 is active and mapped to fifo 2 ra_tid 
0x [0,0]
[ 5406.034756] iwlwifi :02:00.0: Q 2 is active and mapped to fifo 1 ra_tid 
0x [17,17]
[ 5406.034821] iwlwifi :02:00.0: Q 3 is active and mapped to fifo 0 ra_tid 
0x [16,16]
[ 5406.034886] iwlwifi :02:00.0: Q 4 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.034944] iwlwifi :02:00.0: Q 5 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035010] iwlwifi :02:00.0: Q 6 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035068] iwlwifi :02:00.0: Q 7 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035133] iwlwifi :02:00.0: Q 8 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035192] iwlwifi :02:00.0: Q 9 is active and mapped to fifo 7 ra_tid 
0x [136,136]
[ 5406.035257] iwlwifi :02:00.0: Q 10 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035323] iwlwifi :02:00.0: Q 11 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035388] iwlwifi :02:00.0: Q 12 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035446] iwlwifi :02:00.0: Q 13 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035505] iwlwifi :02:00.0: Q 14 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035563] iwlwifi :02:00.0: Q 15 is active and mapped to fifo 5 ra_tid 
0x [0,0]
[ 5406.035622] iwlwifi :02:00.0: Q 16 is active and mapped to fifo 1 ra_tid 
0x [98,125]
[ 5406.035687] iwlwifi :02:00.0: Q 17 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035752] iwlwifi :02:00.0: Q 18 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035817] iwlwifi :02:00.0: Q 19 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.035883] iwlwifi :02:00.0: Q 20 is inactive and mapped to fifo 0 
ra_tid 0xfffc [0,0]
[ 5406.035940] iwlwifi :02:00.0: Q 21 is inactive and mapped to fifo 0 
ra_tid 0x0003 [0,0]
[ 5406.035999] iwlwifi :02:00.0: Q 22 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036064] iwlwifi :02:00.0: Q 23 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036122] iwlwifi :02:00.0: Q 24 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036188] iwlwifi :02:00.0: Q 25 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036246] iwlwifi :02:00.0: Q 26 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036305] iwlwifi :02:00.0: Q 27 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036370] iwlwifi :02:00.0: Q 28 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036428] iwlwifi :02:00.0: Q 29 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036487] iwlwifi :02:00.0: Q 30 is inactive and mapped to fifo 0 
ra_tid 0x [0,0]
[ 5406.036555] iwlwifi :02:00.0: Microcode SW error detected.  Restarting 
0x200.
[ 5406.036558] iwlwifi :02:00.0: CSR values:
[ 5406.036559] 

[linux-next: May 13] intel/iwlwifi/mvm/mvm.h:1069 suspicious rcu_dereference_protected() usage

2016-05-14 Thread Sergey Senozhatsky
Hello,

[11455.550649] ===
[11455.550652] [ INFO: suspicious RCU usage. ]
[11455.550657] 4.6.0-rc7-next-20160513-dbg-4-g8de8b92-dirty #655 Not tainted
[11455.550660] ---
[11455.550664] drivers/net/wireless/intel/iwlwifi/mvm/mvm.h:1069 suspicious 
rcu_dereference_protected() usage!
[11455.550667] 
   other info that might help us debug this:

[11455.550671] 
   rcu_scheduler_active = 1, debug_locks = 0
[11455.550675] 5 locks held by irq/29-iwlwifi/247:
[11455.550677]  #0:  (sync_cmd_lockdep_map){..}, at: [] 
iwl_pcie_irq_handler+0x0/0x635 [iwlwifi]
[11455.550705]  #1:  (&(>lock)->rlock){+.+...}, at: [] 
iwl_pcie_rx_handle+0x38/0x5d5 [iwlwifi]
[11455.550725]  #2:  (rcu_read_lock){..}, at: [] 
ieee80211_rx_napi+0x152/0x8e2 [mac80211]
[11455.550768]  #3:  (&(>rx_path_lock)->rlock){+.-...}, at: 
[] ieee80211_rx_handlers+0x2e/0x1fe1 [mac80211]
[11455.550804]  #4:  (rcu_read_lock){..}, at: [] 
iwl_mvm_update_tkip_key+0x0/0x162 [iwlmvm]
[11455.550833] 
   stack backtrace:
[11455.550840] CPU: 4 PID: 247 Comm: irq/29-iwlwifi Not tainted 
4.6.0-rc7-next-20160513-dbg-4-g8de8b92-dirty #655
[11455.550844]   880037ff78e8 81187f9c 
88041b7ea980
[11455.550854]  0001 880037ff7918 8106b836 
88041bc0e028
[11455.550863]   88041d247878 88041bc0e028 
880037ff7938
[11455.550872] Call Trace:
[11455.550883]  [] dump_stack+0x68/0x92
[11455.550890]  [] lockdep_rcu_suspicious+0xf7/0x100
[11455.550911]  [] iwl_mvm_get_key_sta.part.0+0x5d/0x80 
[iwlmvm]
[11455.550930]  [] iwl_mvm_update_tkip_key+0xd3/0x162 [iwlmvm]
[11455.550945]  [] iwl_mvm_mac_update_tkip_key+0x17/0x19 
[iwlmvm]
[11455.550973]  [] ieee80211_tkip_decrypt_data+0x22c/0x24b 
[mac80211]
[11455.550996]  [] ieee80211_crypto_tkip_decrypt+0xc5/0x110 
[mac80211]
[11455.551026]  [] ieee80211_rx_handlers+0x9bb/0x1fe1 
[mac80211]
[11455.551035]  [] ? __lock_is_held+0x3c/0x57
[11455.551063]  [] 
ieee80211_prepare_and_rx_handle+0xe89/0xf33 [mac80211]
[11455.551071]  [] ? debug_smp_processor_id+0x17/0x19
[11455.551098]  [] ieee80211_rx_napi+0x4bf/0x8e2 [mac80211]
[11455.551119]  [] iwl_mvm_rx_rx_mpdu+0x6af/0x754 [iwlmvm]
[11455.551134]  [] iwl_mvm_rx+0x44/0x6d [iwlmvm]
[11455.551147]  [] iwl_pcie_rx_handle+0x461/0x5d5 [iwlwifi]
[11455.551160]  [] iwl_pcie_irq_handler+0x452/0x635 [iwlwifi]
[11455.551167]  [] ? irq_finalize_oneshot+0xc9/0xc9
[11455.551172]  [] irq_thread_fn+0x18/0x2f
[11455.551176]  [] irq_thread+0x108/0x1b0
[11455.551183]  [] ? __schedule+0x48d/0x58f
[11455.551188]  [] ? wake_threads_waitq+0x28/0x28
[11455.551193]  [] ? irq_thread_dtor+0x93/0x93
[11455.551198]  [] kthread+0xf3/0xfb
[11455.551205]  [] ? _raw_spin_unlock_irq+0x27/0x45
[11455.551212]  [] ret_from_fork+0x1f/0x40
[11455.551217]  [] ? kthread_create_on_node+0x1ca/0x1ca

-ss