[ath9k-devel] Weird Atheros 9485 http connecting problems

[Arkh4mKn1ght <arkh4mkn1ght@gmail.com>]

Ok new update.
I tested the laptop without using hibernation and the problem happened 
again after 9 hours of having powered on the machine.
Again ASPM disabled on both the root complex and atheros card + 
powersave mode off.
This time i decided to use a script to reload the ath9k modules and 
restart the connection after the problem happened, which it didnt work, 
but i got a nasty module call trace in /var/log/messages when i executed it.
the script is this:

#!/bin/bash

modprobe -r ath9k
ps -ef | grep wpa_supplicant | awk '{print $2}' | xargs kill -9
ps -ef | grep ifplugd | grep wlan | awk '{print $2}' | xargs kill -9
service network stop
sleep 5
service network start

the module call trace is this:

May 22 21:24:42 localhost kernel: Loading modules backported from Linux 
version v3.15-rc1-0-gc9eaa44
May 22 21:24:42 localhost kernel: Backport generated by backports.git 
v3.15-rc1-1-0-g2a25483
May 22 21:24:42 localhost kernel: cfg80211: Calling CRDA to update world 
regulatory domain
May 22 21:24:42 localhost kernel: cfg80211: World regulatory domain updated:
May 22 21:24:42 localhost kernel: cfg80211:  DFS Master region: unset
May 22 21:24:42 localhost kernel: cfg80211:   (start_freq - end_freq @ 
bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
May 22 21:24:42 localhost kernel: cfg80211:   (2402000 KHz - 2472000 KHz 
@ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (2457000 KHz - 2482000 KHz 
@ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (2474000 KHz - 2494000 KHz 
@ 20000 KHz), (N/A, 2000 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (5170000 KHz - 5250000 KHz 
@ 80000 KHz), (N/A, 2000 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (5735000 KHz - 5835000 KHz 
@ 80000 KHz), (N/A, 2000 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (57240000 KHz - 63720000 
KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211: Calling CRDA for country: UY
May 22 21:24:42 localhost kernel: cfg80211: Regulatory domain changed to 
country: UY
May 22 21:24:42 localhost kernel: cfg80211:  DFS Master region: unset
May 22 21:24:42 localhost kernel: cfg80211:   (start_freq - end_freq @ 
bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time)
May 22 21:24:42 localhost kernel: cfg80211:   (2402000 KHz - 2482000 KHz 
@ 40000 KHz), (N/A, 2000 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (5170000 KHz - 5250000 KHz 
@ 80000 KHz), (N/A, 1700 mBm), (N/A)
May 22 21:24:42 localhost kernel: cfg80211:   (5250000 KHz - 5330000 KHz 
@ 80000 KHz), (N/A, 2400 mBm), (0 s)
May 22 21:24:42 localhost kernel: cfg80211:   (5490000 KHz - 5730000 KHz 
@ 80000 KHz), (N/A, 2400 mBm), (0 s)
May 22 21:24:42 localhost kernel: cfg80211:   (5735000 KHz - 5835000 KHz 
@ 80000 KHz), (N/A, 3000 mBm), (N/A)
May 22 21:24:42 localhost kernel: ath: phy0: Disable PLL PowerSave
May 22 21:24:42 localhost kernel: modprobe: page allocation failure: 
order:4, mode:0x1040d0
May 22 21:24:42 localhost kernel: CPU: 3 PID: 30011 Comm: modprobe 
Tainted: G           O 3.12.18-desktop-1.mga4 #1
May 22 21:24:42 localhost kernel: Hardware name: Sony Corporation 
SVE14125CLB/VAIO, BIOS R0150D5 08/30/2012
May 22 21:24:42 localhost kernel:  0000000000000000 ffff88006af35738 
ffffffff816116b9 00000000001040d0
May 22 21:24:42 localhost kernel:  ffff88006af357c0 ffffffff81132430 
000000000000000e ffff88006af35760
May 22 21:24:42 localhost kernel:  ffffffff81134ed6 ffff88006af35790 
0000000000000286 0000000000000003
May 22 21:24:42 localhost kernel: Call Trace:
May 22 21:24:42 localhost kernel:  [<ffffffff816116b9>] dump_stack+0x45/0x56
May 22 21:24:42 localhost kernel:  [<ffffffff81132430>] 
warn_alloc_failed+0xf0/0x140
May 22 21:24:42 localhost kernel:  [<ffffffff81134ed6>] ? 
drain_local_pages+0x16/0x20
May 22 21:24:42 localhost kernel:  [<ffffffff81136a62>] 
__alloc_pages_nodemask+0x862/0xa20
May 22 21:24:42 localhost kernel:  [<ffffffff81173259>] 
alloc_pages_current+0xa9/0x160
May 22 21:24:42 localhost kernel:  [<ffffffff8113151e>] 
__get_free_pages+0xe/0x50
May 22 21:24:42 localhost kernel:  [<ffffffff8114d37e>] 
kmalloc_order_trace+0x2e/0xa0
May 22 21:24:42 localhost kernel:  [<ffffffff8117f8e1>] 
__kmalloc_track_caller+0x171/0x180
May 22 21:24:42 localhost kernel:  [<ffffffffa05545c3>] ? 
ath_descdma_setup+0x113/0x390 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffff8146e705>] 
devm_kzalloc+0x25/0x70
May 22 21:24:42 localhost kernel:  [<ffffffffa05545c3>] 
ath_descdma_setup+0x113/0x390 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffffa055f1b5>] 
ath_tx_init+0x55/0x1f0 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffffa05553be>] 
ath9k_init_device+0xb7e/0xd00 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffff810b4f12>] ? 
request_threaded_irq+0x82/0x170
May 22 21:24:42 localhost kernel:  [<ffffffffa05573f0>] ? 
ath9k_start+0x220/0x220 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffff810b4f5c>] ? 
request_threaded_irq+0xcc/0x170
May 22 21:24:42 localhost kernel:  [<ffffffffa0562db5>] 
ath_pci_probe+0x235/0x330 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffff812038d3>] ? 
sysfs_addrm_finish+0x33/0xc0
May 22 21:24:42 localhost kernel:  [<ffffffff813a322e>] 
local_pci_probe+0x3e/0x70
May 22 21:24:42 localhost kernel:  [<ffffffff813a4601>] 
pci_device_probe+0x111/0x120
May 22 21:24:42 localhost kernel:  [<ffffffff8146ab15>] 
driver_probe_device+0x125/0x3b0
May 22 21:24:42 localhost kernel:  [<ffffffff8146ae73>] 
__driver_attach+0x93/0xa0
May 22 21:24:42 localhost kernel:  [<ffffffff8146ade0>] ? 
__device_attach+0x40/0x40
May 22 21:24:42 localhost kernel:  [<ffffffff81468913>] 
bus_for_each_dev+0x63/0xa0
May 22 21:24:42 localhost kernel:  [<ffffffff8146a4ce>] 
driver_attach+0x1e/0x20
May 22 21:24:42 localhost kernel:  [<ffffffff8146a040>] 
bus_add_driver+0x200/0x2d0
May 22 21:24:42 localhost kernel:  [<ffffffffa078a000>] ? 0xffffffffa0789fff
May 22 21:24:42 localhost kernel:  [<ffffffff8146b4e4>] 
driver_register+0x64/0xf0
May 22 21:24:42 localhost kernel:  [<ffffffffa078a000>] ? 0xffffffffa0789fff
May 22 21:24:42 localhost kernel:  [<ffffffff813a309b>] 
__pci_register_driver+0x4b/0x50
May 22 21:24:42 localhost kernel:  [<ffffffffa0562fe3>] 
ath_pci_init+0x23/0x30 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffffa078a00e>] 
__init_backport+0xe/0x1000 [ath9k]
May 22 21:24:42 localhost kernel:  [<ffffffff810020fa>] 
do_one_initcall+0xfa/0x1b0
May 22 21:24:42 localhost kernel:  [<ffffffff81053733>] ? 
set_memory_nx+0x43/0x50
May 22 21:24:42 localhost kernel:  [<ffffffff810cfeb8>] 
load_module+0x2028/0x2680
May 22 21:24:42 localhost kernel:  [<ffffffff810cb990>] ? 
store_uevent+0x40/0x40
May 22 21:24:42 localhost kernel:  [<ffffffff810d0686>] 
SyS_finit_module+0x86/0xb0
May 22 21:24:42 localhost kernel:  [<ffffffff816208bd>] 
system_call_fastpath+0x1a/0x1f
May 22 21:24:42 localhost kernel: Mem-Info:
May 22 21:24:42 localhost kernel: Node 0 DMA per-cpu:
May 22 21:24:42 localhost kernel: CPU    0: hi:    0, btch:   1 usd:   0
May 22 21:24:42 localhost kernel: CPU    1: hi:    0, btch:   1 usd:   0
May 22 21:24:42 localhost kernel: CPU    2: hi:    0, btch:   1 usd:   0
May 22 21:24:42 localhost kernel: CPU    3: hi:    0, btch:   1 usd:   0
May 22 21:24:42 localhost kernel: Node 0 DMA32 per-cpu:
May 22 21:24:42 localhost kernel: CPU    0: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: CPU    1: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: CPU    2: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: CPU    3: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: Node 0 Normal per-cpu:
May 22 21:24:42 localhost kernel: CPU    0: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: CPU    1: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: CPU    2: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: CPU    3: hi:  186, btch:  31 usd:   0
May 22 21:24:42 localhost kernel: active_anon:408612 inactive_anon:12325 
isolated_anon:0
May 22 21:24:42 localhost kernel:  active_file:146977 
inactive_file:146933 isolated_file:32
May 22 21:24:42 localhost kernel:  unevictable:0 dirty:89 writeback:0 
unstable:0
May 22 21:24:42 localhost kernel:  free:74668 slab_reclaimable:13917 
slab_unreclaimable:8897
May 22 21:24:42 localhost kernel:  mapped:285033 shmem:13469 
pagetables:7573 bounce:0
May 22 21:24:42 localhost kernel:  free_cma:0
May 22 21:24:42 localhost kernel: Node 0 DMA free:15780kB min:268kB 
low:332kB high:400kB active_anon:0kB inactive_anon:0kB active_file:0kB 
inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB 
present:15984kB managed:15900kB mlocked:0kB dirty:0kB writeback:0kB 
mapped:0kB shmem:0kB slab_reclaimable:16kB slab_unreclaimable:16kB 
kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_cma:0kB 
writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
May 22 21:24:42 localhost kernel: lowmem_reserve[]: 0 2687 3886 3886
May 22 21:24:42 localhost kernel: Node 0 DMA32 free:243096kB min:46556kB 
low:58192kB high:69832kB active_anon:1083608kB inactive_anon:31688kB 
active_file:432220kB inactive_file:445304kB unevictable:0kB 
isolated(anon):0kB isolated(file):0kB present:2833152kB 
managed:2756436kB mlocked:0kB dirty:236kB writeback:0kB mapped:745224kB 
shmem:34992kB slab_reclaimable:39528kB slab_unreclaimable:20516kB 
kernel_stack:2408kB pagetables:19812kB unstable:0kB bounce:0kB 
free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
May 22 21:24:42 localhost kernel: lowmem_reserve[]: 0 0 1198 1198
May 22 21:24:42 localhost kernel: Node 0 Normal free:39796kB min:20756kB 
low:25944kB high:31132kB active_anon:550840kB inactive_anon:17612kB 
active_file:155688kB inactive_file:142428kB unevictable:0kB 
isolated(anon):0kB isolated(file):128kB present:1294336kB 
managed:1227128kB mlocked:0kB dirty:120kB writeback:0kB mapped:394908kB 
shmem:18884kB slab_reclaimable:16124kB slab_unreclaimable:15056kB 
kernel_stack:1448kB pagetables:10480kB unstable:0kB bounce:0kB 
free_cma:0kB writeback_tmp:0kB pages_scanned:83 all_unreclaimable? no
May 22 21:24:42 localhost kernel: lowmem_reserve[]: 0 0 0 0
May 22 21:24:42 localhost kernel: Node 0 DMA: 1*4kB (U) 0*8kB 2*16kB 
(UE) 2*32kB (UE) 3*64kB (UE) 1*128kB (E) 2*256kB (UE) 1*512kB (E) 
2*1024kB (UE) 2*2048kB (ER) 2*4096kB (M) = 15780kB
May 22 21:24:42 localhost kernel: Node 0 DMA32: 1000*4kB (UEM) 21105*8kB 
(UEM) 3819*16kB (UEM) 241*32kB (UEM) 15*64kB (UEM) 6*128kB (U) 0*256kB 
0*512kB 0*1024kB 0*2048kB 0*4096kB = 243384kB
May 22 21:24:42 localhost kernel: Node 0 Normal: 7576*4kB (UEM) 782*8kB 
(UEM) 68*16kB (UEM) 18*32kB (UEM) 16*64kB (UEM) 1*128kB (E) 1*256kB (U) 
1*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 40144kB
May 22 21:24:42 localhost kernel: Node 0 hugepages_total=0 
hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
May 22 21:24:42 localhost kernel: 307383 total pagecache pages
May 22 21:24:42 localhost kernel: 0 pages in swap cache
May 22 21:24:42 localhost kernel: Swap cache stats: add 0, delete 0, 
find 0/0
May 22 21:24:42 localhost kernel: Free swap  = 0kB
May 22 21:24:42 localhost kernel: Total swap = 0kB
May 22 21:24:42 localhost kernel: 1035868 pages RAM
May 22 21:24:42 localhost kernel: 0 pages HighMem/MovableOnly
May 22 21:24:42 localhost kernel: 16802 pages reserved
May 22 21:24:42 localhost kernel: ath: phy0: Failed to allocate tx 
descriptors: -12
May 22 21:24:42 localhost kernel: ath9k 0000:07:00.0: Failed to 
initialize device
May 22 21:24:42 localhost kernel: ath9k: probe of 0000:07:00.0 failed 
with error -12

In order to make the connection work again i had to reboot the machine...

So this log seems to imply  three options,
a) there is a bug somewhere in the ath9k driver,
b) my atheros card is a piece of shit
or c) the BIOS of the laptop is a piece of shit....

I dont have any more tests to do besides installing the BIOS update( 
after installing windows 8 somehow ughhhh..)
What do you guys think?

Greetings

Oskar


On 05/21/2014 05:10 PM, Adrian Chadd wrote:
> hi,
>
> Hm. You're hibernating? That may explain why the thing is return
> 0xdeadc0de during register reads. Maybe the MAC isn't fully waking up
> after a resume?
>
>
> -a
>
>
> On 21 May 2014 08:10, Arkh4mKn1ght <arkh4mkn1ght@gmail.com> wrote:
>> Hi rajkumar
>>
>> I dont know if this only happens when resuming from hibernate, it was just a
>> thought that ocurred to me today. I will test again without hibernating to
>> see if this happens again.
>> I dont use any firewall on the laptop, so iptables -F is pointless.
>> Ping latency times are good when the problem is ongoing.
>> I will take a sniffer capture and send it back to you.
>>
>> Thanks for your help
>>
>> Oskar
>>
>>
>> On 05/21/2014 11:59 AM, Rajkumar Manoharan wrote:
>>> On Wed, May 21, 2014 at 11:37:36AM -0300, Arkh4mKn1ght wrote:
>>>> Ok i tried the patch but the issue happened again :(
>>>>
>>>> After resuming my laptop from hibernation i saw in
>>>> /var/log/kernel/errors.log these messages again:
>>>>
>>>> May 21 09:20:10 localhost kernel: mei_me 0000:00:16.0: suspend
>>>> May 21 09:20:10 localhost kernel: ath: phy1: RX failed to go idle in 10
>>>> ms
>>>> RXSM=0xdeadbeef
>>>> May 21 09:20:10 localhost kernel: ath: phy1: DMA failed to stop in 10 ms
>>>> AR_CR=0xdeadbeef AR_DIAG_SW=0xdeadbeef DMADBG_7=0xdeadbeef
>>>> May 21 09:20:11 localhost kernel: dpm_run_callback():
>>>> usb_dev_restore+0x0/0x20 [usbcore] returns -107
>>>> May 21 09:20:11 localhost kernel: PM: Device 1-1 failed to restore async:
>>>> error -107
>>>>
>>>> ASPM was disabled on root complex and atheros card.powersave was off.
>>>> After 1 hour and 10 minutes of those messages that problem arise. I have
>>>> noticed that the problem arises always after some time of resuming the
>>>> laptop from hibernation.
>>>>
>>>> Its really odd, because when it does happen, browsing the web is
>>>> painfully
>>>> slow with the "connecting to domain.com..." message in the browser status
>>>> bar... it does load the website but after some minutes..
>>>> Meanwhile at the same time if i try to download a torrent using a
>>>> bittorrent
>>>> client i can do it without problems at full speed. If i pause the
>>>> torrent,
>>>> browsing websites still behaves slowly until i reboot the laptop.
>>>>
>>>> At first i thought that i have a defective atheros card, but why i can
>>>> download torrents at full speed when this problem arises?
>>>> What options do i have now? i have tested all combinations of ASPM
>>>> enabled/disabled and powersave on/off.
>>>>
>>>> I have seen that there is a BIOS update for my laptop, but im unsure it
>>>> could help for this at all (besides that i would have to install windows
>>>> 8
>>>> to install the friggin bios update)
>>>>
>>> Oskar,
>>>
>>> I am quite confused. Does the issue happen only after resume from
>>> hibernate?
>>> Initially you havn't mentioned hibernate/resume. Are you able to
>>> reproduce the issue without hibernating? Please flush ip table entries
>>> and test.
>>>
>>> sudo iptables -F
>>>
>>> Can you please take a sniffer capture at the problematic time? Are you
>>> seeing huge
>>> latency for ping (icmp)?
>>>
>>> -Rajkumar
>>>