Other Parts Discussed in Thread: WL1271
Tool/software: Linux
I have Wi-Fi AP with WL1807 module. I found issue with missing TX interrupt
after broadcast of packet. Correct execution looks like this (from kernel log,
lines with "FIXME" are added by me for better understanding of program flow
and for getting more information):
7,593724,2466895290,-;wlcore: queue skb hlid 2 q 0 len 118 count 1
7,593725,2466895326,-;FIXME: wlcore_select_ac() - q=0, min_pkts=0
7,593726,2466895337,-;FIXME: wl1271_skb_dequeue() - START, ac=0, wlvif=df380c20, num_links=16
7,593727,2466895346,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=0, ac=0
7,593728,2466895360,-;FIXME: wl18xx_lnk_high_prio() - hlid=0, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0000, ap_fw_ps_map=0x0014
7,593729,2466895367,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,593730,2466895378,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=999
7,593731,2466895388,-;FIXME: wlcore_vif_dequeue_high_prio() - START, ac=0, last_tx_hlid=2, start_hlid=3
7,593732,2466895395,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=3, ac=0
7,593733,2466895405,-;FIXME: wl18xx_lnk_high_prio() - hlid=3, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0000, ap_fw_ps_map=0x0014
7,593734,2466895411,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,593735,2466895418,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=1
7,593736,2466895425,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=4, ac=0
7,593737,2466895434,-;FIXME: wl18xx_lnk_high_prio() - hlid=4, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0000, ap_fw_ps_map=0x0014
7,593738,2466895440,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,593739,2466895448,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=1
7,593740,2466895455,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=1, ac=0
7,593741,2466895464,-;FIXME: wl18xx_lnk_high_prio() - hlid=1, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0000, ap_fw_ps_map=0x0014
7,593742,2466895471,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,593743,2466895478,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=1
7,593744,2466895484,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=2, ac=0
7,593745,2466895493,-;FIXME: wl18xx_lnk_high_prio() - hlid=2, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0000, ap_fw_ps_map=0x0014
7,593746,2466895499,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,593747,2466895507,-;FIXME: wlcore_lnk_dequeue() - skb=df588d80, tx_queue_count[0]=0
7,593748,2466895515,-;FIXME: wlcore_vif_dequeue_high_prio() - END, skb=df588d80, *hlid=2, last_tx_hlid=2
7,593749,2466895524,-;FIXME: wl1271_skb_dequeue() - END, skb=df588d80, *hlid=2, last_wlvif=df380c20
7,593750,2466895537,-;FIXME: wl1271_alloc_tx_id() - id=0, skb=df588d80, tx_frames_cnt=1, tx_frames_map=0x0001
7,593751,2466895555,-;wlcore: tx_allocate: size: 134, blocks: 2, id: 0
7,593752,2466895570,-;wlcore: tx_fill_hdr: hlid: 2 len: 134 life: 8000 mem: 2
7,593753,2466895581,-;FIXME: wl1271_tx_regulate_link() - hlid=2, tx_pkts=1, fw_ps=1, active_link_count=4, ap_count=1
7,593754,2466895592,-;FIXME: wlcore_tx_work_locked() - hlid=2, skb=df588d80, wlvif=df380c20, has_data=1, ret=136
7,593755,2466895600,-;FIXME: wlcore_tx_work_locked() - desc->hlid=2, wl->tx_packets_count=2372
7,593756,2466895608,-;FIXME: wlcore_select_ac() - q=-1, min_pkts=4294967295
7,593757,2466895616,-;FIXME: wl1271_skb_dequeue() - END, skb= (null), *hlid=2, last_wlvif=df380c20
7,593758,2466895715,-;FIXME: wlcore_tx_work_locked() - END, buf_offset=256, sent_packets=1, active_hlids=0x0004, bus_ret=0
7,593759,2466918846,-;wlcore: elp work
7,593760,2466918864,-;wlcore: chip to elp
7,593761,2466966364,-;wlcore: IRQ work
7,593762,2466966385,-;wlcore: waking up chip from elp
7,593763,2466966468,-;wlcore: wakeup time: 0 ms
7,593764,2466966583,-;wlcore: intr: 0x24 (fw_rx_counter = 200, drv_rx_counter = 7, tx_results_counter = 0)
7,593765,2466966604,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,593766,2466966615,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,593767,2466966630,-;FIXME: wlcore_fw_status() - fw_localtime=2433907619, time_offset=1458360385304202
7,593768,2466966637,-;wlcore: WL1271_ACX_INTR_EVENT_A
7,593769,2466966643,-;wlcore: EVENT on mbox 0
7,593770,2466966751,-;wlcore: MBOX vector: 0x2000000
7,593771,2466967160,-;wlcore: WL1271_ACX_INTR_HW_AVAILABLE
7,593772,2466967229,-;wlcore: intr: 0x0 (fw_rx_counter = 200, drv_rx_counter = 7, tx_results_counter = 0)
7,593773,2466967241,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,593774,2466967250,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,593775,2466967262,-;FIXME: wlcore_fw_status() - fw_localtime=2433907619, time_offset=1458360385304821
7,593776,2466967280,-;FIXME: wlcore_irq_locked() - END, ret=0
7,593777,2466988914,-;wlcore: elp work
7,593778,2466988931,-;wlcore: chip to elp
7,593779,2467039309,-;wlcore: IRQ work
7,593780,2467039330,-;wlcore: waking up chip from elp
7,593781,2467039413,-;wlcore: wakeup time: 0 ms
7,593782,2467039531,-;wlcore: intr: 0x60 (fw_rx_counter = 200, drv_rx_counter = 7, tx_results_counter = 0)
7,593783,2467039547,-;FIXME: wlcore_fw_status() - freed=2, alloc=0
7,593784,2467039563,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,593785,2467039573,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,593786,2467039587,-;FIXME: wlcore_fw_status() - fw_localtime=2433980559, time_offset=1458360385302509
7,593787,2467039596,-;wlcore: last released desc = 28, current idx = 29
7,593788,2467039610,-;wlcore: tx status id 0 skb 0xdf588d80 success 1
7,593789,2467039636,-;FIXME: wl1271_free_tx_id() - id=0, skb=df588d80, tx_frames_cnt=0, tx_frames_map=0x0000
7,593790,2467039642,-;wlcore: WL1271_ACX_INTR_DATA
7,593791,2467039651,-;FIXME: wlcore_rx() - hlid=0, drv_rx_counter=8, fw_rx_counter=8
7,593792,2467039659,-;FIXME: wlcore_rx() - END, ret=0
7,593793,2467039665,-;wlcore: WL1271_ACX_INTR_HW_AVAILABLE
7,593794,2467039733,-;wlcore: intr: 0x0 (fw_rx_counter = 200, drv_rx_counter = 7, tx_results_counter = 0)
7,593795,2467039745,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,593796,2467039754,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,593797,2467039763,-;FIXME: wlcore_fw_status() - fw_localtime=2433980559, time_offset=1458360385302685
7,593798,2467039780,-;FIXME: wlcore_irq_locked() - END, ret=0
7,593799,2467066477,-;wlcore: IRQ work
7,593800,2467066646,-;wlcore: intr: 0x8 (fw_rx_counter = 200, drv_rx_counter = 7, tx_results_counter = 0)
7,593801,2467066668,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,593802,2467066678,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,593803,2467066694,-;FIXME: wlcore_fw_status() - fw_localtime=2434007472, time_offset=1458360385302067
7,593804,2467066702,-;wlcore: WL1271_ACX_INTR_EVENT_B
7,593805,2467066709,-;wlcore: EVENT on mbox 1
7,593806,2467066775,-;wlcore: MBOX vector: 0x2000000
7,593807,2467067356,-;wlcore: intr: 0x0 (fw_rx_counter = 200, drv_rx_counter = 7, tx_results_counter = 0)
7,593808,2467067374,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,593809,2467067383,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,593810,2467067394,-;FIXME: wlcore_fw_status() - fw_localtime=2434007472, time_offset=1458360385302754
7,593811,2467067411,-;FIXME: wlcore_irq_locked() - END, ret=0
7,593812,2467088922,-;wlcore: elp work
7,593813,2467088940,-;wlcore: chip to elp
If TX interrupt is missing, kernel log looks differently:
7,686469,2859456615,-;wlcore: queue skb hlid 2 q 0 len 118 count 1
7,686470,2859456653,-;wlcore: IRQ work
7,686471,2859456743,-;wlcore: intr: 0x40 (fw_rx_counter = 221, drv_rx_counter = 28, tx_results_counter = 0)
7,686472,2859456757,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686473,2859456767,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686474,2859456777,-;FIXME: wlcore_fw_status() - fw_localtime=2826377307, time_offset=1458360376125676
7,686475,2859456783,-;wlcore: WL1271_ACX_INTR_DATA
7,686476,2859456791,-;FIXME: wlcore_rx() - hlid=0, drv_rx_counter=28, fw_rx_counter=29
7,686477,2859456798,-;FIXME: wlcore_rx() - buf_size=256, rx_counter=29
7,686478,2859456874,-;FIXME: wlcore_rx() - END, ret=0
7,686479,2859456885,-;FIXME: wlcore_select_ac() - q=0, min_pkts=0
7,686480,2859456896,-;FIXME: wl1271_skb_dequeue() - START, ac=0, wlvif=df380c20, num_links=16
7,686481,2859456905,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=0, ac=0
7,686482,2859456919,-;FIXME: wl18xx_lnk_high_prio() - hlid=0, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0002, ap_fw_ps_map=0x0014
7,686483,2859456926,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,686484,2859456936,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=999
7,686485,2859456947,-;FIXME: wlcore_vif_dequeue_high_prio() - START, ac=0, last_tx_hlid=3, start_hlid=4
7,686486,2859456953,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=4, ac=0
7,686487,2859456963,-;FIXME: wl18xx_lnk_high_prio() - hlid=4, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0002, ap_fw_ps_map=0x0014
7,686488,2859456969,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,686489,2859456977,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=1
7,686490,2859456984,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=1, ac=0
7,686491,2859456993,-;FIXME: wl18xx_lnk_high_prio() - hlid=1, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0002, ap_fw_ps_map=0x0014
7,686492,2859457000,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=10
7,686493,2859457007,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=1
7,686494,2859457013,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=2, ac=0
7,686495,2859457022,-;FIXME: wl18xx_lnk_high_prio() - hlid=2, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0002, ap_fw_ps_map=0x0014
7,686496,2859457029,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,686497,2859457037,-;FIXME: wlcore_lnk_dequeue() - skb=df593b00, tx_queue_count[0]=0
7,686498,2859457044,-;FIXME: wlcore_vif_dequeue_high_prio() - END, skb=df593b00, *hlid=2, last_tx_hlid=2
7,686499,2859457053,-;FIXME: wl1271_skb_dequeue() - END, skb=df593b00, *hlid=2, last_wlvif=df380c20
7,686500,2859457066,-;FIXME: wl1271_alloc_tx_id() - id=0, skb=df593b00, tx_frames_cnt=1, tx_frames_map=0x0001
7,686501,2859457084,-;wlcore: tx_allocate: size: 134, blocks: 2, id: 0
7,686502,2859457099,-;wlcore: tx_fill_hdr: hlid: 2 len: 134 life: 8000 mem: 2
7,686503,2859457110,-;FIXME: wl1271_tx_regulate_link() - hlid=2, tx_pkts=1, fw_ps=1, active_link_count=4, ap_count=1
7,686504,2859457122,-;FIXME: wlcore_tx_work_locked() - hlid=2, skb=df593b00, wlvif=df380c20, has_data=1, ret=136
7,686505,2859457129,-;FIXME: wlcore_tx_work_locked() - desc->hlid=2, wl->tx_packets_count=2663
7,686506,2859457136,-;FIXME: wlcore_select_ac() - q=-1, min_pkts=4294967295
7,686507,2859457145,-;FIXME: wl1271_skb_dequeue() - END, skb= (null), *hlid=2, last_wlvif=df380c20
7,686508,2859457213,-;FIXME: wlcore_tx_work_locked() - END, buf_offset=256, sent_packets=1, active_hlids=0x0004, bus_ret=0
7,686509,2859457283,-;wlcore: intr: 0x0 (fw_rx_counter = 221, drv_rx_counter = 28, tx_results_counter = 0)
7,686510,2859457294,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686511,2859457304,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686512,2859457314,-;FIXME: wlcore_fw_status() - fw_localtime=2826377307, time_offset=1458360376126201
7,686513,2859457323,-;FIXME: wlcore_irq_locked() - END, ret=0
7,686514,2859463626,-;wlcore: IRQ work
7,686515,2859463811,-;wlcore: intr: 0x40 (fw_rx_counter = 222, drv_rx_counter = 29, tx_results_counter = 0)
7,686516,2859463831,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686517,2859463841,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686518,2859463856,-;FIXME: wlcore_fw_status() - fw_localtime=2826384275, time_offset=1458360376125619
7,686519,2859463864,-;wlcore: WL1271_ACX_INTR_DATA
7,686520,2859463873,-;FIXME: wlcore_rx() - hlid=0, drv_rx_counter=29, fw_rx_counter=30
7,686521,2859463882,-;FIXME: wlcore_rx() - buf_size=256, rx_counter=30
7,686522,2859463979,-;FIXME: wlcore_rx() - END, ret=0
7,686523,2859464196,-;wlcore: queue skb hlid 3 q 0 len 70 count 1
7,686524,2859464231,-;wlcore: intr: 0x0 (fw_rx_counter = 222, drv_rx_counter = 29, tx_results_counter = 0)
7,686525,2859464243,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686526,2859464251,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686527,2859464261,-;FIXME: wlcore_fw_status() - fw_localtime=2826384275, time_offset=1458360376126017
7,686528,2859464277,-;FIXME: wlcore_irq_locked() - END, ret=0
7,686529,2859464341,-;wlcore: IRQ work
7,686530,2859464425,-;wlcore: intr: 0x40 (fw_rx_counter = 223, drv_rx_counter = 30, tx_results_counter = 0)
7,686531,2859464438,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686532,2859464447,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686533,2859464457,-;FIXME: wlcore_fw_status() - fw_localtime=2826385052, time_offset=1458360376125432
7,686534,2859464462,-;wlcore: WL1271_ACX_INTR_DATA
7,686535,2859464470,-;FIXME: wlcore_rx() - hlid=0, drv_rx_counter=30, fw_rx_counter=31
7,686536,2859464477,-;FIXME: wlcore_rx() - buf_size=256, rx_counter=31
7,686537,2859464554,-;FIXME: wlcore_rx() - END, ret=0
7,686538,2859464566,-;FIXME: wlcore_select_ac() - q=0, min_pkts=1
7,686539,2859464577,-;FIXME: wl1271_skb_dequeue() - START, ac=0, wlvif=df380c20, num_links=16
7,686540,2859464585,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=0, ac=0
7,686541,2859464598,-;FIXME: wl18xx_lnk_high_prio() - hlid=0, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0002, ap_fw_ps_map=0x0014
7,686542,2859464605,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,686543,2859464615,-;FIXME: wlcore_lnk_dequeue() - skb= (null), tx_queue_count[0]=999
7,686544,2859464625,-;FIXME: wlcore_vif_dequeue_high_prio() - START, ac=0, last_tx_hlid=2, start_hlid=3
7,686545,2859464632,-;FIXME: wlcore_lnk_dequeue_high_prio() - hlid=3, ac=0
7,686546,2859464641,-;FIXME: wl18xx_lnk_high_prio() - hlid=3, suspend_bitmap=0xFFFFFFE0, fw_fast_lnk_map=0x0002, ap_fw_ps_map=0x0014
7,686547,2859464648,-;FIXME: wl18xx_lnk_high_prio() - pkts=0 < thold=4
7,686548,2859464656,-;FIXME: wlcore_lnk_dequeue() - skb=df534f00, tx_queue_count[0]=0
7,686549,2859464664,-;FIXME: wlcore_vif_dequeue_high_prio() - END, skb=df534f00, *hlid=3, last_tx_hlid=3
7,686550,2859464672,-;FIXME: wl1271_skb_dequeue() - END, skb=df534f00, *hlid=3, last_wlvif=df380c20
7,686551,2859464685,-;FIXME: wl1271_alloc_tx_id() - id=1, skb=df534f00, tx_frames_cnt=2, tx_frames_map=0x0003
7,686552,2859464695,-;wlcore: tx_allocate: size: 86, blocks: 2, id: 1
7,686553,2859464708,-;wlcore: tx_fill_hdr: hlid: 3 len: 86 life: 8000 mem: 2
7,686554,2859464719,-;FIXME: wl1271_tx_regulate_link() - hlid=3, tx_pkts=1, fw_ps=0, active_link_count=4, ap_count=1
7,686555,2859464730,-;FIXME: wlcore_tx_work_locked() - hlid=3, skb=df534f00, wlvif=df380c20, has_data=1, ret=88
7,686556,2859464738,-;FIXME: wlcore_tx_work_locked() - desc->hlid=3, wl->tx_packets_count=2664
7,686557,2859464746,-;FIXME: wlcore_select_ac() - q=-1, min_pkts=4294967295
7,686558,2859464754,-;FIXME: wl1271_skb_dequeue() - END, skb= (null), *hlid=3, last_wlvif=df380c20
7,686559,2859464823,-;FIXME: wlcore_tx_work_locked() - END, buf_offset=256, sent_packets=1, active_hlids=0x0008, bus_ret=0
7,686560,2859464896,-;wlcore: intr: 0x0 (fw_rx_counter = 223, drv_rx_counter = 30, tx_results_counter = 0)
7,686561,2859464908,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=1, active_link_count=4, ap_count=1
7,686562,2859464917,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686563,2859464927,-;FIXME: wlcore_fw_status() - fw_localtime=2826385052, time_offset=1458360376125890
7,686564,2859464937,-;FIXME: wlcore_irq_locked() - END, ret=0
7,686565,2859467602,-;wlcore: IRQ work
7,686566,2859467743,-;wlcore: intr: 0x40 (fw_rx_counter = 223, drv_rx_counter = 30, tx_results_counter = 0)
7,686567,2859467758,-;FIXME: wlcore_fw_status() - freed=2, alloc=2
7,686568,2859467781,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686569,2859467791,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686570,2859467805,-;FIXME: wlcore_fw_status() - fw_localtime=2826388226, time_offset=1458360376125523
7,686571,2859467814,-;wlcore: last released desc = 22, current idx = 23
7,686572,2859467827,-;wlcore: tx status id 1 skb 0xdf534f00 success 1
7,686573,2859467849,-;FIXME: wl1271_free_tx_id() - id=1, skb=df534f00, tx_frames_cnt=1, tx_frames_map=0x0001
7,686574,2859467863,-;FIXME: wl18xx_tx_expire() - id=0, now_time=-1468579013, start_time=-1468589678, life_time=8000
7,686575,2859467870,-;wlcore: WL1271_ACX_INTR_DATA
7,686576,2859467878,-;FIXME: wlcore_rx() - hlid=0, drv_rx_counter=31, fw_rx_counter=31
7,686577,2859467885,-;FIXME: wlcore_rx() - END, ret=0
7,686578,2859467953,-;wlcore: intr: 0x0 (fw_rx_counter = 223, drv_rx_counter = 30, tx_results_counter = 0)
7,686579,2859467965,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=3, tx_pkts=0, active_link_count=4, ap_count=1
7,686580,2859467974,-;FIXME: wl12xx_irq_ps_regulate_link() - hlid=4, tx_pkts=0, active_link_count=4, ap_count=1
7,686581,2859467984,-;FIXME: wlcore_fw_status() - fw_localtime=2826388226, time_offset=1458360376125701
7,686582,2859467994,-;FIXME: wlcore_irq_locked() - END, ret=0
7,686583,2859488905,-;wlcore: elp work
7,686584,2859488923,-;wlcore: chip to elp
There is missing line with "tx status id 0 skb ...". Event doesn't occur even
after long time of waiting (see attached whole kernel log). I think this means that
packet processing was broken in Wi-Fi module somehow.
One lost broadcast packet wouldn't be a problem, but there are unpleasant
consequences. Every packet allocates some resources in kernel Wi-Fi driver. In
this case numbers in tx_allocated_blocks, tx_allocated_pkts[] and
tx_queue_count slowly grow as other and other TX interrupts are lost. The
limit is reached after some time and result is "wlcore: ERROR Tx stuck (in FW)
for 5000 ms. Starting recovery". Second problem is that Wi-Fi AP is actually
not working for connected clients during this time - data tranmission drop
and interrupt take few minutes before recovery is reached. It's really bad.
Wi-Fi AP use linux kernel 3.12.10 with wl18xx driver backported from kernel
4.8.5. Wi-Fi module has firmware 8.9.0.1.70. I tested firmware 8.9.0.0.70 too,
but behaviour is same. There are 2 Wi-Fi clients. First is notebook with
Windows 7 (on hlid 3) which communicates over Wi-Fi seldom but regularly.
Second is some router with linux (on hlid 4) which doesn't communicate over
Wi-Fi, it is connected to AP only. More, this router is restarted every 5
minutes. It is here for simulating of connecting/disconnecting of other Wi-Fi
clients. The router is key component in this test. If it is not present and
notebook is connected to AP as the only client, everything is fine!
Whole kernel log, Wi-Fi module log and configuration file are attached.
My questions:
Q1: What should prevent a TX interrupt to occur?
Q2: What is maximum time when TX interrupt should occur?
Q3: Could some change in configuration file help with this problem?
Q4: Could some parameter change in kernel module help with this problem?
Q5: Why power save mode is activated on hlid 2? Cannot be problem here?
Q6: How to disable power save mode in Wi-Fi module completely?