* Re: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?
[not found] ` <1e797dea-d2e1-4947-8ef3-d2ac5ea0c156@oss.qualcomm.com>
@ 2025-07-28 7:39 ` Paul Menzel
2025-07-28 8:50 ` Baochen Qiang
2025-07-29 9:41 ` athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`? Baochen Qiang
0 siblings, 2 replies; 7+ messages in thread
From: Paul Menzel @ 2025-07-28 7:39 UTC (permalink / raw)
To: Baochen Qiang
Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood,
Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot, LKML
[CC: +scheduler folks for input on the wait_for_completion_timeout() part]
Dear Baochen,
Thank you for your reply.
Am 28.07.25 um 04:18 schrieb Baochen Qiang:
> On 7/25/2025 8:15 PM, Paul Menzel wrote:
>> Am 22.07.25 um 11:38 schrieb Baochen Qiang:
>>
>>> On 7/22/2025 4:37 PM, Paul Menzel wrote:
>>
>>>> Today, on the Intel Kaby Lake laptop Dell XPS 13 9360 with
>>>>
>>>> $ lspci -nn -s 3a:
>>>> 3a:00.0 Network controller [0280]: Qualcomm Atheros QCA6174 802.11ac Wireless Network Adapter [168c:003e] (rev 32)
>>>>
>>>> resuming from ACPI S3 took longer, as it sometimes does, and looking into this, I see
>>>> `failed to receive service ready completion, polling..` after a delay of five seconds:
>>>>
>>>> ```
>>>> [ 0.000000] Linux version 6.16.0-rc6-00253-g4871b7cb27f4 (build@bohemianrhapsody.molgen.mpg.de) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU Binutils for Debian) 2.44) #90 SMP PREEMPT_DYNAMIC Sat Jul 19 08:53:39 CEST 2025
>>>> […]
>>>> [ 8.588020] abreu kernel: ath10k_pci 0000:3a:00.0: qca6174 hw3.2 target 0x05030000 chip_id 0x00340aff sub 1a56:1535
>>>> [ 8.588372] abreu kernel: ath10k_pci 0000:3a:00.0: kconfig debug 0 debugfs 0 tracing 0 dfs 0 testmode 0
>>>> [ 8.588603] abreu kernel: ath10k_pci 0000:3a:00.0: firmware ver WLAN.RM.4.4.1-00309- api 6 features wowlan,ignore-otp,mfp crc32 0793bcf2
>>>> […]
>>>> [ 9.113550] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome 0x302 build 0x111
>>>> […]
>>>> [41804.953487] PM: suspend entry (deep)
>>>> [41804.988361] Filesystems sync: 0.034 seconds
>>>> [41805.007216] Freezing user space processes
>>>> [41805.009650] Freezing user space processes completed (elapsed 0.002 seconds)
>>>> [41805.009663] OOM killer disabled.
>>>> [41805.009666] Freezing remaining freezable tasks
>>>> [41805.011383] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
>>>> [41805.011502] printk: Suspending console(s) (use no_console_suspend to debug)
>>>> [41805.523883] ACPI: EC: interrupt blocked
>>>> [41805.545779] ACPI: PM: Preparing to enter system sleep state S3
>>>> [41805.556040] ACPI: EC: event blocked
>>>> [41805.556045] ACPI: EC: EC stopped
>>>> [41805.556046] ACPI: PM: Saving platform NVS memory
>>>> [41805.559408] Disabling non-boot CPUs ...
>>>> [41805.562480] smpboot: CPU 3 is now offline
>>>> [41805.567105] smpboot: CPU 2 is now offline
>>>> [41805.572122] smpboot: CPU 1 is now offline
>>>> [41805.582034] ACPI: PM: Low-level resume complete
>>>> [41805.582079] ACPI: EC: EC started
>>>> [41805.582080] ACPI: PM: Restoring platform NVS memory
>>>> [41805.583986] Enabling non-boot CPUs ...
>>>> [41805.584009] smpboot: Booting Node 0 Processor 1 APIC 0x2
>>>> [41805.584734] CPU1 is up
>>>> [41805.584749] smpboot: Booting Node 0 Processor 2 APIC 0x1
>>>> [41805.585514] CPU2 is up
>>>> [41805.585530] smpboot: Booting Node 0 Processor 3 APIC 0x3
>>>> [41805.586216] CPU3 is up
>>>> [41805.589070] ACPI: PM: Waking up from system sleep state S3
>>>> [41805.623652] ACPI: EC: interrupt unblocked
>>>> [41805.640074] ACPI: EC: event unblocked
>>>> [41805.651951] nvme nvme0: 4/0/0 default/read/poll queues
>>>> [41805.865391] atkbd serio0: Failed to deactivate keyboard on isa0060/serio0
>>>> [41810.933639] ath10k_pci 0000:3a:00.0: failed to receive service ready completion, polling..
>>>> [41810.933769] ath10k_pci 0000:3a:00.0: service ready completion received, continuing normally
>>>> [41810.986330] OOM killer enabled.
>>>> [41810.986332] Restarting tasks: Starting
>>>> […]
>>>> ```
>>>>
>>>> Commit e57b7d62a1b2 (wifi: ath10k: poll service ready message before failing) [1][2],
>>>> present since Linux v6.10-rc1, added this to avoid the hardware not being initialized:
>>>>
>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>> if (!time_left) {
>>>> /* Sometimes the PCI HIF doesn't receive interrupt
>>>> * for the service ready message even if the buffer
>>>> * was completed. PCIe sniffer shows that it's
>>>> * because the corresponding CE ring doesn't fires
>>>> * it. Workaround here by polling CE rings once.
>>>> */
>>>> ath10k_warn(ar, "failed to receive service ready completion, polling..\n");
>>>>
>>>> for (i = 0; i < CE_COUNT; i++)
>>>> ath10k_hif_send_complete_check(ar, i, 1);
>>>>
>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>> if (!time_left) {
>>>> ath10k_warn(ar, "polling timed out\n");
>>>> return -ETIMEDOUT;
>>>> }
>>>>
>>>> ath10k_warn(ar, "service ready completion received, continuing normally\n");
>>>> }
>>>>
>>>> The comment says, it’s a hardware issue. I guess from the Qualcomm device and not the
>>>> board design, as it happens with several devices like James’?
>>>>
>>>> Anyway, should polling be used by default then to avoid the delay?
>>>
>>> Adding additional polling before wait seems OK to me
>>
>> With the attached diff, I didn’t notice any issue on the Dell XPS 13 9360 with QCA6174.
>
> In the diff you are moving polling ahead of wait, IMO this might introduce some race: what
> if hardware/firmware send the event right after polling is done?
>
> So how about, instead of moving, just adding a new polling before wait:
>
> 1. polling
> 2. wait
> 3. poling again if wait fail
I do not know the hardware behavior/design and the error, so cannot
judge, if a race would be possible.
Could Qualcomm take over to cook up a patch
I’d appreciated if Qualcomm could take over to cook up a patch, as you
have the datasheets, erratas and a line to the hardware designers.
>> Unrelated: The only thing I noticed is, that during boot (not resume) the function seems
>> to be called twice. It looks like once for Wi-Fi and once for Bluetooth:
>>
>> ```
>> [ 35.507604] ath10k_pci 0000:3a:00.0: board_file api 2 bmi_id N/A crc32 d2863f91
>> [ 35.516010] usb 1-5: New USB device found, idVendor=0c45, idProduct=670c, bcdDevice=56.26
>> [ 35.516022] usb 1-5: New USB device strings: Mfr=2, Product=1, SerialNumber=0
>> [ 35.516026] usb 1-5: Product: Integrated_Webcam_HD
>> [ 35.516029] usb 1-5: Manufacturer: CN09GTFMLOG008C8B7FWA01
>> [ 35.587852] ath10k_pci 0000:3a:00.0: service ready completion received, continuing normally
>> [ 35.606632] ath10k_pci 0000:3a:00.0: htt-ver 3.87 wmi-op 4 htt-op 3 cal otp max-sta 32 raw 0 hwcrypto 1
>> [ 35.628744] mc: Linux media interface: v0.10
>> [ 35.651301] nvme nvme0: using unchecked data buffer
>> [ 35.687466] Bluetooth: Core ver 2.22
>> [ 35.687493] NET: Registered PF_BLUETOOTH protocol family
>> [ 35.687495] Bluetooth: HCI device and connection manager initialized
>> [ 35.687499] Bluetooth: HCI socket layer initialized
>> [ 35.687501] Bluetooth: L2CAP socket layer initialized
>> [ 35.687505] Bluetooth: SCO socket layer initialized
>> [ 35.696050] ath: EEPROM regdomain: 0x6c
>> [ 35.696055] ath: EEPROM indicates we should expect a direct regpair map
>> [ 35.696057] ath: Country alpha2 being used: 00
>> [ 35.696058] ath: Regpair used: 0x6c
>> [ 35.712821] ath10k_pci 0000:3a:00.0 wlp58s0: renamed from wlan0
>> [ 35.716790] input: ELAN Touchscreen as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input40
>> [ 35.718912] videodev: Linux video capture interface: v2.00
>> [ 35.719492] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input41
>> [ 35.719595] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input42
>> [ 35.720899] hid-multitouch 0003:04F3:2234.0002: input,hiddev0,hidraw1: USB HID v1.10 Device [ELAN Touchscreen] on usb-0000:00:14.0-4/input0
>> [ 35.720947] usbcore: registered new interface driver usbhid
>> [ 35.720949] usbhid: USB HID core driver
>> [ 35.812081] usbcore: registered new interface driver btusb
>> [ 35.815263] Bluetooth: hci0: using rampatch file: qca/rampatch_usb_00000302.bin
>> [ 35.815270] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome 0x302 build 0x111
>> [ 36.174345] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
>> [ 36.199643] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is advertised, but not supported.
>> [ 36.398657] ath10k_pci 0000:3a:00.0: service ready completion received, continuing normally
>
> Hmm, I don't think this is for BT as ath10k is not a BT driver. Something must be wrong
> here ...
>
>> ```
Can you reproduce it?
How would I get a call graph for both function calls?
>>>> Additionally I have two questions regarding the code:
>>>>
>>>> 1. Is `WMI_SERVICE_READY_TIMEOUT_HZ` the right value to pass to
>>>> `wait_for_completion_timeout(struct completion *done, unsigned long timeout)`?
>>>>
>>>> The macro is defined as:
>>>>
>>>> drivers/net/wireless/ath/ath10k/wmi.h:#define WMI_SERVICE_READY_TIMEOUT_HZ (5 * HZ)
>>>>
>>>> `timeout` is supposed to be in jiffies, and `CONFIG_HZ_250=y` on my system. I wonder how
>>>> that amounts to five seconds on my system.
>>>
>>> HZ is defined as jiffies per second, so 5 * HZ equals 5 seconds.
Sorry, I missed to comment here in my previous reply. HZ can be defined
differently – like 1000 HZ –, so the timeout would very, and then not
match the actual timeout required by the hardware?
`Documentation/scheduler/completion.rst` contains:
> Timeouts are preferably calculated with msecs_to_jiffies() or usecs_to_jiffies(),
> to make the code largely HZ-invariant.
>>>> The timeout should probably be defined in seconds? Does the WMI specification say
>>>> something about this?
>>>>
>>>> 2. Is the task interruptable and should `wait_for_completion_interruptible_timeout(struct
>>>> completion *done, unsigned long timeout)` be used?
>>>
>>> While I am not sure for now, may I ask why the question?
>>
>> I was just reading up on `wait_for_completion_*()`, and so the different variants.
>
> If there is no obvious benefits I don't think the change is necessary.
Thinking about it, the driver initialization is in the boot path (hot
patch) so would block one thread(?) – or is that a wrong assumption –,
which is unwanted?
Kind regards,
Paul
>>>> [1]: https://web.git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=e57b7d62a1b2f496caf0beba81cec3c90fad80d5
>>>> [2]: https://lore.kernel.org/all/20240227030409.89702-1-quic_bqiang@quicinc.com/
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?
2025-07-28 7:39 ` athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`? Paul Menzel
@ 2025-07-28 8:50 ` Baochen Qiang
2025-07-28 12:48 ` Paul Menzel
2025-07-29 9:41 ` athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`? Baochen Qiang
1 sibling, 1 reply; 7+ messages in thread
From: Baochen Qiang @ 2025-07-28 8:50 UTC (permalink / raw)
To: Paul Menzel
Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood,
Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot, LKML
On 7/28/2025 3:39 PM, Paul Menzel wrote:
> [CC: +scheduler folks for input on the wait_for_completion_timeout() part]
>
> Dear Baochen,
>
>
> Thank you for your reply.
>
> Am 28.07.25 um 04:18 schrieb Baochen Qiang:
>> On 7/25/2025 8:15 PM, Paul Menzel wrote:
>
>>> Am 22.07.25 um 11:38 schrieb Baochen Qiang:
>>>
>>>> On 7/22/2025 4:37 PM, Paul Menzel wrote:
>>>
>>>>> Today, on the Intel Kaby Lake laptop Dell XPS 13 9360 with
>>>>>
>>>>> $ lspci -nn -s 3a:
>>>>> 3a:00.0 Network controller [0280]: Qualcomm Atheros QCA6174 802.11ac Wireless
>>>>> Network Adapter [168c:003e] (rev 32)
>>>>>
>>>>> resuming from ACPI S3 took longer, as it sometimes does, and looking into this, I see
>>>>> `failed to receive service ready completion, polling..` after a delay of five seconds:
>>>>>
>>>>> ```
>>>>> [ 0.000000] Linux version 6.16.0-rc6-00253-g4871b7cb27f4
>>>>> (build@bohemianrhapsody.molgen.mpg.de) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU
>>>>> Binutils for Debian) 2.44) #90 SMP PREEMPT_DYNAMIC Sat Jul 19 08:53:39 CEST 2025
>>>>> […]
>>>>> [ 8.588020] abreu kernel: ath10k_pci 0000:3a:00.0: qca6174 hw3.2 target 0x05030000
>>>>> chip_id 0x00340aff sub 1a56:1535
>>>>> [ 8.588372] abreu kernel: ath10k_pci 0000:3a:00.0: kconfig debug 0 debugfs 0
>>>>> tracing 0 dfs 0 testmode 0
>>>>> [ 8.588603] abreu kernel: ath10k_pci 0000:3a:00.0: firmware ver
>>>>> WLAN.RM.4.4.1-00309- api 6 features wowlan,ignore-otp,mfp crc32 0793bcf2
>>>>> […]
>>>>> [ 9.113550] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome
>>>>> 0x302 build 0x111
>>>>> […]
>>>>> [41804.953487] PM: suspend entry (deep)
>>>>> [41804.988361] Filesystems sync: 0.034 seconds
>>>>> [41805.007216] Freezing user space processes
>>>>> [41805.009650] Freezing user space processes completed (elapsed 0.002 seconds)
>>>>> [41805.009663] OOM killer disabled.
>>>>> [41805.009666] Freezing remaining freezable tasks
>>>>> [41805.011383] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
>>>>> [41805.011502] printk: Suspending console(s) (use no_console_suspend to debug)
>>>>> [41805.523883] ACPI: EC: interrupt blocked
>>>>> [41805.545779] ACPI: PM: Preparing to enter system sleep state S3
>>>>> [41805.556040] ACPI: EC: event blocked
>>>>> [41805.556045] ACPI: EC: EC stopped
>>>>> [41805.556046] ACPI: PM: Saving platform NVS memory
>>>>> [41805.559408] Disabling non-boot CPUs ...
>>>>> [41805.562480] smpboot: CPU 3 is now offline
>>>>> [41805.567105] smpboot: CPU 2 is now offline
>>>>> [41805.572122] smpboot: CPU 1 is now offline
>>>>> [41805.582034] ACPI: PM: Low-level resume complete
>>>>> [41805.582079] ACPI: EC: EC started
>>>>> [41805.582080] ACPI: PM: Restoring platform NVS memory
>>>>> [41805.583986] Enabling non-boot CPUs ...
>>>>> [41805.584009] smpboot: Booting Node 0 Processor 1 APIC 0x2
>>>>> [41805.584734] CPU1 is up
>>>>> [41805.584749] smpboot: Booting Node 0 Processor 2 APIC 0x1
>>>>> [41805.585514] CPU2 is up
>>>>> [41805.585530] smpboot: Booting Node 0 Processor 3 APIC 0x3
>>>>> [41805.586216] CPU3 is up
>>>>> [41805.589070] ACPI: PM: Waking up from system sleep state S3
>>>>> [41805.623652] ACPI: EC: interrupt unblocked
>>>>> [41805.640074] ACPI: EC: event unblocked
>>>>> [41805.651951] nvme nvme0: 4/0/0 default/read/poll queues
>>>>> [41805.865391] atkbd serio0: Failed to deactivate keyboard on isa0060/serio0
>>>>> [41810.933639] ath10k_pci 0000:3a:00.0: failed to receive service ready completion,
>>>>> polling..
>>>>> [41810.933769] ath10k_pci 0000:3a:00.0: service ready completion received, continuing
>>>>> normally
>>>>> [41810.986330] OOM killer enabled.
>>>>> [41810.986332] Restarting tasks: Starting
>>>>> […]
>>>>> ```
>>>>>
>>>>> Commit e57b7d62a1b2 (wifi: ath10k: poll service ready message before failing) [1][2],
>>>>> present since Linux v6.10-rc1, added this to avoid the hardware not being initialized:
>>>>>
>>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>>> if (!time_left) {
>>>>> /* Sometimes the PCI HIF doesn't receive interrupt
>>>>> * for the service ready message even if the buffer
>>>>> * was completed. PCIe sniffer shows that it's
>>>>> * because the corresponding CE ring doesn't fires
>>>>> * it. Workaround here by polling CE rings once.
>>>>> */
>>>>> ath10k_warn(ar, "failed to receive service ready completion,
>>>>> polling..\n");
>>>>>
>>>>> for (i = 0; i < CE_COUNT; i++)
>>>>> ath10k_hif_send_complete_check(ar, i, 1);
>>>>>
>>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>>> if (!time_left) {
>>>>> ath10k_warn(ar, "polling timed out\n");
>>>>> return -ETIMEDOUT;
>>>>> }
>>>>>
>>>>> ath10k_warn(ar, "service ready completion received, continuing
>>>>> normally\n");
>>>>> }
>>>>>
>>>>> The comment says, it’s a hardware issue. I guess from the Qualcomm device and not the
>>>>> board design, as it happens with several devices like James’?
>>>>>
>>>>> Anyway, should polling be used by default then to avoid the delay?
>>>>
>>>> Adding additional polling before wait seems OK to me
>>>
>>> With the attached diff, I didn’t notice any issue on the Dell XPS 13 9360 with QCA6174.
>>
>> In the diff you are moving polling ahead of wait, IMO this might introduce some race: what
>> if hardware/firmware send the event right after polling is done?
>>
>> So how about, instead of moving, just adding a new polling before wait:
>>
>> 1. polling
>> 2. wait
>> 3. poling again if wait fail
>
> I do not know the hardware behavior/design and the error, so cannot judge, if a race would
> be possible.
>
> Could Qualcomm take over to cook up a patch
> I’d appreciated if Qualcomm could take over to cook up a patch, as you have the
> datasheets, erratas and a line to the hardware designers.
sure, I will see what I can do here
>
>>> Unrelated: The only thing I noticed is, that during boot (not resume) the function seems
>>> to be called twice. It looks like once for Wi-Fi and once for Bluetooth:
>>>
>>> ```
>>> [ 35.507604] ath10k_pci 0000:3a:00.0: board_file api 2 bmi_id N/A crc32 d2863f91
>>> [ 35.516010] usb 1-5: New USB device found, idVendor=0c45, idProduct=670c,
>>> bcdDevice=56.26
>>> [ 35.516022] usb 1-5: New USB device strings: Mfr=2, Product=1, SerialNumber=0
>>> [ 35.516026] usb 1-5: Product: Integrated_Webcam_HD
>>> [ 35.516029] usb 1-5: Manufacturer: CN09GTFMLOG008C8B7FWA01
>>> [ 35.587852] ath10k_pci 0000:3a:00.0: service ready completion received, continuing
>>> normally
>>> [ 35.606632] ath10k_pci 0000:3a:00.0: htt-ver 3.87 wmi-op 4 htt-op 3 cal otp max-sta
>>> 32 raw 0 hwcrypto 1
>>> [ 35.628744] mc: Linux media interface: v0.10
>>> [ 35.651301] nvme nvme0: using unchecked data buffer
>>> [ 35.687466] Bluetooth: Core ver 2.22
>>> [ 35.687493] NET: Registered PF_BLUETOOTH protocol family
>>> [ 35.687495] Bluetooth: HCI device and connection manager initialized
>>> [ 35.687499] Bluetooth: HCI socket layer initialized
>>> [ 35.687501] Bluetooth: L2CAP socket layer initialized
>>> [ 35.687505] Bluetooth: SCO socket layer initialized
>>> [ 35.696050] ath: EEPROM regdomain: 0x6c
>>> [ 35.696055] ath: EEPROM indicates we should expect a direct regpair map
>>> [ 35.696057] ath: Country alpha2 being used: 00
>>> [ 35.696058] ath: Regpair used: 0x6c
>>> [ 35.712821] ath10k_pci 0000:3a:00.0 wlp58s0: renamed from wlan0
>>> [ 35.716790] input: ELAN Touchscreen as /devices/pci0000:00/0000:00:14.0/
>>> usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input40
>>> [ 35.718912] videodev: Linux video capture interface: v2.00
>>> [ 35.719492] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/
>>> usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input41
>>> [ 35.719595] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/
>>> usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input42
>>> [ 35.720899] hid-multitouch 0003:04F3:2234.0002: input,hiddev0,hidraw1: USB HID v1.10
>>> Device [ELAN Touchscreen] on usb-0000:00:14.0-4/input0
>>> [ 35.720947] usbcore: registered new interface driver usbhid
>>> [ 35.720949] usbhid: USB HID core driver
>>> [ 35.812081] usbcore: registered new interface driver btusb
>>> [ 35.815263] Bluetooth: hci0: using rampatch file: qca/rampatch_usb_00000302.bin
>>> [ 35.815270] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome 0x302
>>> build 0x111
>>> [ 36.174345] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
>>> [ 36.199643] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is
>>> advertised, but not supported.
>>> [ 36.398657] ath10k_pci 0000:3a:00.0: service ready completion received, continuing
>>> normally
>>
>> Hmm, I don't think this is for BT as ath10k is not a BT driver. Something must be wrong
>> here ...
>>
>>> ```
>
> Can you reproduce it?
>
> How would I get a call graph for both function calls?
# cd /sys/kernel/debug/tracing/
# echo 0 > ./tracing_on
# echo function >./current_tracer
/* replace function with what you want to trace, e.g. ath10k_wmi_wait_for_service_ready */
# echo <function> > ./set_ftrace_filter
# echo 1 > ./options/func_stack_trace
# echo 1 > ./tracing_on
# cat trace_pipe
/* reload ath10k driver */
>
>>>>> Additionally I have two questions regarding the code:
>>>>>
>>>>> 1. Is `WMI_SERVICE_READY_TIMEOUT_HZ` the right value to pass to
>>>>> `wait_for_completion_timeout(struct completion *done, unsigned long timeout)`?
>>>>>
>>>>> The macro is defined as:
>>>>>
>>>>> drivers/net/wireless/ath/ath10k/wmi.h:#define WMI_SERVICE_READY_TIMEOUT_HZ (5 *
>>>>> HZ)
>>>>>
>>>>> `timeout` is supposed to be in jiffies, and `CONFIG_HZ_250=y` on my system. I wonder how
>>>>> that amounts to five seconds on my system.
>>>>
>>>> HZ is defined as jiffies per second, so 5 * HZ equals 5 seconds.
>
> Sorry, I missed to comment here in my previous reply. HZ can be defined differently – like
> 1000 HZ –, so the timeout would very, and then not match the actual timeout required by
> the hardware? `Documentation/scheduler/completion.rst` contains:
>
>> Timeouts are preferably calculated with msecs_to_jiffies() or usecs_to_jiffies(),
>> to make the code largely HZ-invariant.
Hmm, new knowledge to me. Will check and update.
>
>
>>>>> The timeout should probably be defined in seconds? Does the WMI specification say
>>>>> something about this?
>>>>>
>>>>> 2. Is the task interruptable and should
>>>>> `wait_for_completion_interruptible_timeout(struct
>>>>> completion *done, unsigned long timeout)` be used?
>>>>
>>>> While I am not sure for now, may I ask why the question?
>>>
>>> I was just reading up on `wait_for_completion_*()`, and so the different variants.
>>
>> If there is no obvious benefits I don't think the change is necessary.
>
> Thinking about it, the driver initialization is in the boot path (hot patch) so would
> block one thread(?) – or is that a wrong assumption –, which is unwanted?
Indeed a thread would block there ... So you want to make the thread responsible to
signals? such as killing it when ath10k goes wrong?
>
>
> Kind regards,
>
> Paul
>
>
>>>>> [1]: https://web.git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?
>>>>> id=e57b7d62a1b2f496caf0beba81cec3c90fad80d5
>>>>> [2]: https://lore.kernel.org/all/20240227030409.89702-1-quic_bqiang@quicinc.com/
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?
2025-07-28 8:50 ` Baochen Qiang
@ 2025-07-28 12:48 ` Paul Menzel
2025-07-29 2:27 ` Baochen Qiang
0 siblings, 1 reply; 7+ messages in thread
From: Paul Menzel @ 2025-07-28 12:48 UTC (permalink / raw)
To: Baochen Qiang
Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood,
Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot, LKML
Dear Baochen,
Am 28.07.25 um 10:50 schrieb Baochen Qiang:
> On 7/28/2025 3:39 PM, Paul Menzel wrote:
>> [CC: +scheduler folks for input on the wait_for_completion_timeout() part]
>> Am 28.07.25 um 04:18 schrieb Baochen Qiang:
>>> On 7/25/2025 8:15 PM, Paul Menzel wrote:
>>
>>>> Am 22.07.25 um 11:38 schrieb Baochen Qiang:
>>>>
>>>>> On 7/22/2025 4:37 PM, Paul Menzel wrote:
>>>>
>>>>>> Today, on the Intel Kaby Lake laptop Dell XPS 13 9360 with
>>>>>>
>>>>>> $ lspci -nn -s 3a:
>>>>>> 3a:00.0 Network controller [0280]: Qualcomm Atheros QCA6174 802.11ac Wireless
>>>>>> Network Adapter [168c:003e] (rev 32)
>>>>>>
>>>>>> resuming from ACPI S3 took longer, as it sometimes does, and looking into this, I see
>>>>>> `failed to receive service ready completion, polling..` after a delay of five seconds:
>>>>>>
>>>>>> ```
>>>>>> [ 0.000000] Linux version 6.16.0-rc6-00253-g4871b7cb27f4 (build@bohemianrhapsody.molgen.mpg.de) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU Binutils for Debian) 2.44) #90 SMP PREEMPT_DYNAMIC Sat Jul 19 08:53:39 CEST 2025
>>>>>> […]
>>>>>> [ 8.588020] abreu kernel: ath10k_pci 0000:3a:00.0: qca6174 hw3.2 target 0x05030000 chip_id 0x00340aff sub 1a56:1535
>>>>>> [ 8.588372] abreu kernel: ath10k_pci 0000:3a:00.0: kconfig debug 0 debugfs 0 tracing 0 dfs 0 testmode 0
>>>>>> [ 8.588603] abreu kernel: ath10k_pci 0000:3a:00.0: firmware ver WLAN.RM.4.4.1-00309- api 6 features wowlan,ignore-otp,mfp crc32 0793bcf2
>>>>>> […]
>>>>>> [ 9.113550] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome 0x302 build 0x111
>>>>>> […]
>>>>>> [41804.953487] PM: suspend entry (deep)
>>>>>> [41804.988361] Filesystems sync: 0.034 seconds
>>>>>> [41805.007216] Freezing user space processes
>>>>>> [41805.009650] Freezing user space processes completed (elapsed 0.002 seconds)
>>>>>> [41805.009663] OOM killer disabled.
>>>>>> [41805.009666] Freezing remaining freezable tasks
>>>>>> [41805.011383] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
>>>>>> [41805.011502] printk: Suspending console(s) (use no_console_suspend to debug)
>>>>>> [41805.523883] ACPI: EC: interrupt blocked
>>>>>> [41805.545779] ACPI: PM: Preparing to enter system sleep state S3
>>>>>> [41805.556040] ACPI: EC: event blocked
>>>>>> [41805.556045] ACPI: EC: EC stopped
>>>>>> [41805.556046] ACPI: PM: Saving platform NVS memory
>>>>>> [41805.559408] Disabling non-boot CPUs ...
>>>>>> [41805.562480] smpboot: CPU 3 is now offline
>>>>>> [41805.567105] smpboot: CPU 2 is now offline
>>>>>> [41805.572122] smpboot: CPU 1 is now offline
>>>>>> [41805.582034] ACPI: PM: Low-level resume complete
>>>>>> [41805.582079] ACPI: EC: EC started
>>>>>> [41805.582080] ACPI: PM: Restoring platform NVS memory
>>>>>> [41805.583986] Enabling non-boot CPUs ...
>>>>>> [41805.584009] smpboot: Booting Node 0 Processor 1 APIC 0x2
>>>>>> [41805.584734] CPU1 is up
>>>>>> [41805.584749] smpboot: Booting Node 0 Processor 2 APIC 0x1
>>>>>> [41805.585514] CPU2 is up
>>>>>> [41805.585530] smpboot: Booting Node 0 Processor 3 APIC 0x3
>>>>>> [41805.586216] CPU3 is up
>>>>>> [41805.589070] ACPI: PM: Waking up from system sleep state S3
>>>>>> [41805.623652] ACPI: EC: interrupt unblocked
>>>>>> [41805.640074] ACPI: EC: event unblocked
>>>>>> [41805.651951] nvme nvme0: 4/0/0 default/read/poll queues
>>>>>> [41805.865391] atkbd serio0: Failed to deactivate keyboard on isa0060/serio0
>>>>>> [41810.933639] ath10k_pci 0000:3a:00.0: failed to receive service ready completion, polling..
>>>>>> [41810.933769] ath10k_pci 0000:3a:00.0: service ready completion received, continuing normally
>>>>>> [41810.986330] OOM killer enabled.
>>>>>> [41810.986332] Restarting tasks: Starting
>>>>>> […]
>>>>>> ```
>>>>>>
>>>>>> Commit e57b7d62a1b2 (wifi: ath10k: poll service ready message before failing) [1][2],
>>>>>> present since Linux v6.10-rc1, added this to avoid the hardware not being initialized:
>>>>>>
>>>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>>>> if (!time_left) {
>>>>>> /* Sometimes the PCI HIF doesn't receive interrupt
>>>>>> * for the service ready message even if the buffer
>>>>>> * was completed. PCIe sniffer shows that it's
>>>>>> * because the corresponding CE ring doesn't fires
>>>>>> * it. Workaround here by polling CE rings once.
>>>>>> */
>>>>>> ath10k_warn(ar, "failed to receive service ready completion, polling..\n");
>>>>>>
>>>>>> for (i = 0; i < CE_COUNT; i++)
>>>>>> ath10k_hif_send_complete_check(ar, i, 1);
>>>>>>
>>>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>>>> if (!time_left) {
>>>>>> ath10k_warn(ar, "polling timed out\n");
>>>>>> return -ETIMEDOUT;
>>>>>> }
>>>>>>
>>>>>> ath10k_warn(ar, "service ready completion received, continuing normally\n");
>>>>>> }
>>>>>>
>>>>>> The comment says, it’s a hardware issue. I guess from the Qualcomm device and not the
>>>>>> board design, as it happens with several devices like James’?
>>>>>>
>>>>>> Anyway, should polling be used by default then to avoid the delay?
>>>>>
>>>>> Adding additional polling before wait seems OK to me
>>>>
>>>> With the attached diff, I didn’t notice any issue on the Dell XPS 13 9360 with QCA6174.
>>>
>>> In the diff you are moving polling ahead of wait, IMO this might introduce some race: what
>>> if hardware/firmware send the event right after polling is done?
>>>
>>> So how about, instead of moving, just adding a new polling before wait:
>>>
>>> 1. polling
>>> 2. wait
>>> 3. poling again if wait fail
>>
>> I do not know the hardware behavior/design and the error, so cannot judge, if a race would
>> be possible.
>>
>> Could Qualcomm take over to cook up a patch
>> I’d appreciated if Qualcomm could take over to cook up a patch, as you have the
>> datasheets, erratas and a line to the hardware designers.
>
> sure, I will see what I can do here
Awesome. Thank you!
>>>> Unrelated: The only thing I noticed is, that during boot (not resume) the function seems
>>>> to be called twice. It looks like once for Wi-Fi and once for Bluetooth:
>>>>
>>>> ```
>>>> [ 35.507604] ath10k_pci 0000:3a:00.0: board_file api 2 bmi_id N/A crc32 d2863f91
>>>> [ 35.516010] usb 1-5: New USB device found, idVendor=0c45, idProduct=670c, bcdDevice=56.26
>>>> [ 35.516022] usb 1-5: New USB device strings: Mfr=2, Product=1, SerialNumber=0
>>>> [ 35.516026] usb 1-5: Product: Integrated_Webcam_HD
>>>> [ 35.516029] usb 1-5: Manufacturer: CN09GTFMLOG008C8B7FWA01
>>>> [ 35.587852] ath10k_pci 0000:3a:00.0: service ready completion received, continuing normally
>>>> [ 35.606632] ath10k_pci 0000:3a:00.0: htt-ver 3.87 wmi-op 4 htt-op 3 cal otp max-sta 32 raw 0 hwcrypto 1
>>>> [ 35.628744] mc: Linux media interface: v0.10
>>>> [ 35.651301] nvme nvme0: using unchecked data buffer
>>>> [ 35.687466] Bluetooth: Core ver 2.22
>>>> [ 35.687493] NET: Registered PF_BLUETOOTH protocol family
>>>> [ 35.687495] Bluetooth: HCI device and connection manager initialized
>>>> [ 35.687499] Bluetooth: HCI socket layer initialized
>>>> [ 35.687501] Bluetooth: L2CAP socket layer initialized
>>>> [ 35.687505] Bluetooth: SCO socket layer initialized
>>>> [ 35.696050] ath: EEPROM regdomain: 0x6c
>>>> [ 35.696055] ath: EEPROM indicates we should expect a direct regpair map
>>>> [ 35.696057] ath: Country alpha2 being used: 00
>>>> [ 35.696058] ath: Regpair used: 0x6c
>>>> [ 35.712821] ath10k_pci 0000:3a:00.0 wlp58s0: renamed from wlan0
>>>> [ 35.716790] input: ELAN Touchscreen as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input40
>>>> [ 35.718912] videodev: Linux video capture interface: v2.00
>>>> [ 35.719492] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input41
>>>> [ 35.719595] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input42
>>>> [ 35.720899] hid-multitouch 0003:04F3:2234.0002: input,hiddev0,hidraw1: USB HID v1.10 Device [ELAN Touchscreen] on usb-0000:00:14.0-4/input0
>>>> [ 35.720947] usbcore: registered new interface driver usbhid
>>>> [ 35.720949] usbhid: USB HID core driver
>>>> [ 35.812081] usbcore: registered new interface driver btusb
>>>> [ 35.815263] Bluetooth: hci0: using rampatch file: qca/rampatch_usb_00000302.bin
>>>> [ 35.815270] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome 0x302 build 0x111
>>>> [ 36.174345] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
>>>> [ 36.199643] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is advertised, but not supported.
>>>> [ 36.398657] ath10k_pci 0000:3a:00.0: service ready completion received, continuing normally
>>>
>>> Hmm, I don't think this is for BT as ath10k is not a BT driver. Something must be wrong
>>> here ...
>>>
>>>> ```
>>
>> Can you reproduce it?
>>
>> How would I get a call graph for both function calls?
>
> # cd /sys/kernel/debug/tracing/
> # echo 0 > ./tracing_on
> # echo function >./current_tracer
> /* replace function with what you want to trace, e.g. ath10k_wmi_wait_for_service_ready */
> # echo <function> > ./set_ftrace_filter
> # echo 1 > ./options/func_stack_trace
> # echo 1 > ./tracing_on
> # cat trace_pipe
> /* reload ath10k driver */
Somehow it did not work for me. I think, reloading the module seems to
make it forget the function `ath10k_wmi_wait_for_service_ready()`.
$ sudo cat /sys/kernel/debug/tracing/set_ftrace_filter
ath10k_wmi_wait_for_service_ready [ath10k_core]
Unload the module with `sudo modprobe -r ath10k_pci`.
$ sudo cat /sys/kernel/debug/tracing/set_ftrace_filter
$
Load the module, and it’s still empty:
$ sudo cat /sys/kernel/debug/tracing/set_ftrace_filter
$
>>>>>> Additionally I have two questions regarding the code:
>>>>>>
>>>>>> 1. Is `WMI_SERVICE_READY_TIMEOUT_HZ` the right value to pass to
>>>>>> `wait_for_completion_timeout(struct completion *done, unsigned long timeout)`?
>>>>>>
>>>>>> The macro is defined as:
>>>>>>
>>>>>> drivers/net/wireless/ath/ath10k/wmi.h:#define WMI_SERVICE_READY_TIMEOUT_HZ (5 * HZ)
>>>>>>
>>>>>> `timeout` is supposed to be in jiffies, and `CONFIG_HZ_250=y` on my system. I wonder how
>>>>>> that amounts to five seconds on my system.
>>>>>
>>>>> HZ is defined as jiffies per second, so 5 * HZ equals 5 seconds.
>>
>> Sorry, I missed to comment here in my previous reply. HZ can be defined differently – like
>> 1000 HZ –, so the timeout would very, and then not match the actual timeout required by
>> the hardware? `Documentation/scheduler/completion.rst` contains:
>>
>>> Timeouts are preferably calculated with msecs_to_jiffies() or usecs_to_jiffies(),
>>> to make the code largely HZ-invariant.
>
> Hmm, new knowledge to me. Will check and update.
Awesome!
>>>>>> The timeout should probably be defined in seconds? Does the WMI specification say
>>>>>> something about this?
>>>>>>
>>>>>> 2. Is the task interruptible and should
>>>>>> `wait_for_completion_interruptible_timeout(struct completion *done, unsigned long timeout)` be used?
>>>>>
>>>>> While I am not sure for now, may I ask why the question?
>>>>
>>>> I was just reading up on `wait_for_completion_*()`, and so the different variants.
>>>
>>> If there is no obvious benefits I don't think the change is necessary.
>>
>> Thinking about it, the driver initialization is in the boot path (hot patch) so would
>> block one thread(?) – or is that a wrong assumption –, which is unwanted?
>
> Indeed a thread would block there ... So you want to make the thread responsible to
> signals? such as killing it when ath10k goes wrong?
You got me, that I actually do not know, what the downsides are, and
what signal/interrupt could be fired, and how it should be handled. As a
side note: Other drivers use
`wait_for_completion_interruptible_timeout()` also without checking the
return value. If nobody else sheds light into this, please ignore my
comment.
Kind regards,
Paul
>>>>>> [1]: https://web.git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=e57b7d62a1b2f496caf0beba81cec3c90fad80d5
>>>>>> [2]: https://lore.kernel.org/all/20240227030409.89702-1-quic_bqiang@quicinc.com/
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?
2025-07-28 12:48 ` Paul Menzel
@ 2025-07-29 2:27 ` Baochen Qiang
2025-07-30 10:40 ` ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot (was: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?) Paul Menzel
0 siblings, 1 reply; 7+ messages in thread
From: Baochen Qiang @ 2025-07-29 2:27 UTC (permalink / raw)
To: Paul Menzel
Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood,
Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot, LKML
On 7/28/2025 8:48 PM, Paul Menzel wrote:
> Dear Baochen,
>
>
> Am 28.07.25 um 10:50 schrieb Baochen Qiang:
>
>> On 7/28/2025 3:39 PM, Paul Menzel wrote:
>>> [CC: +scheduler folks for input on the wait_for_completion_timeout() part]
>
>>> Am 28.07.25 um 04:18 schrieb Baochen Qiang:
>>>> On 7/25/2025 8:15 PM, Paul Menzel wrote:
>>>
>>>>> Am 22.07.25 um 11:38 schrieb Baochen Qiang:
>>>>>
>>>>>> On 7/22/2025 4:37 PM, Paul Menzel wrote:
>>>>>
>>>>>>> Today, on the Intel Kaby Lake laptop Dell XPS 13 9360 with
>>>>>>>
>>>>>>> $ lspci -nn -s 3a:
>>>>>>> 3a:00.0 Network controller [0280]: Qualcomm Atheros QCA6174 802.11ac Wireless
>>>>>>> Network Adapter [168c:003e] (rev 32)
>>>>>>>
>>>>>>> resuming from ACPI S3 took longer, as it sometimes does, and looking into this, I see
>>>>>>> `failed to receive service ready completion, polling..` after a delay of five seconds:
>>>>>>>
>>>>>>> ```
>>>>>>> [ 0.000000] Linux version 6.16.0-rc6-00253-g4871b7cb27f4
>>>>>>> (build@bohemianrhapsody.molgen.mpg.de) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU
>>>>>>> Binutils for Debian) 2.44) #90 SMP PREEMPT_DYNAMIC Sat Jul 19 08:53:39 CEST 2025
>>>>>>> […]
>>>>>>> [ 8.588020] abreu kernel: ath10k_pci 0000:3a:00.0: qca6174 hw3.2 target
>>>>>>> 0x05030000 chip_id 0x00340aff sub 1a56:1535
>>>>>>> [ 8.588372] abreu kernel: ath10k_pci 0000:3a:00.0: kconfig debug 0 debugfs 0
>>>>>>> tracing 0 dfs 0 testmode 0
>>>>>>> [ 8.588603] abreu kernel: ath10k_pci 0000:3a:00.0: firmware ver
>>>>>>> WLAN.RM.4.4.1-00309- api 6 features wowlan,ignore-otp,mfp crc32 0793bcf2
>>>>>>> […]
>>>>>>> [ 9.113550] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome
>>>>>>> 0x302 build 0x111
>>>>>>> […]
>>>>>>> [41804.953487] PM: suspend entry (deep)
>>>>>>> [41804.988361] Filesystems sync: 0.034 seconds
>>>>>>> [41805.007216] Freezing user space processes
>>>>>>> [41805.009650] Freezing user space processes completed (elapsed 0.002 seconds)
>>>>>>> [41805.009663] OOM killer disabled.
>>>>>>> [41805.009666] Freezing remaining freezable tasks
>>>>>>> [41805.011383] Freezing remaining freezable tasks completed (elapsed 0.001 seconds)
>>>>>>> [41805.011502] printk: Suspending console(s) (use no_console_suspend to debug)
>>>>>>> [41805.523883] ACPI: EC: interrupt blocked
>>>>>>> [41805.545779] ACPI: PM: Preparing to enter system sleep state S3
>>>>>>> [41805.556040] ACPI: EC: event blocked
>>>>>>> [41805.556045] ACPI: EC: EC stopped
>>>>>>> [41805.556046] ACPI: PM: Saving platform NVS memory
>>>>>>> [41805.559408] Disabling non-boot CPUs ...
>>>>>>> [41805.562480] smpboot: CPU 3 is now offline
>>>>>>> [41805.567105] smpboot: CPU 2 is now offline
>>>>>>> [41805.572122] smpboot: CPU 1 is now offline
>>>>>>> [41805.582034] ACPI: PM: Low-level resume complete
>>>>>>> [41805.582079] ACPI: EC: EC started
>>>>>>> [41805.582080] ACPI: PM: Restoring platform NVS memory
>>>>>>> [41805.583986] Enabling non-boot CPUs ...
>>>>>>> [41805.584009] smpboot: Booting Node 0 Processor 1 APIC 0x2
>>>>>>> [41805.584734] CPU1 is up
>>>>>>> [41805.584749] smpboot: Booting Node 0 Processor 2 APIC 0x1
>>>>>>> [41805.585514] CPU2 is up
>>>>>>> [41805.585530] smpboot: Booting Node 0 Processor 3 APIC 0x3
>>>>>>> [41805.586216] CPU3 is up
>>>>>>> [41805.589070] ACPI: PM: Waking up from system sleep state S3
>>>>>>> [41805.623652] ACPI: EC: interrupt unblocked
>>>>>>> [41805.640074] ACPI: EC: event unblocked
>>>>>>> [41805.651951] nvme nvme0: 4/0/0 default/read/poll queues
>>>>>>> [41805.865391] atkbd serio0: Failed to deactivate keyboard on isa0060/serio0
>>>>>>> [41810.933639] ath10k_pci 0000:3a:00.0: failed to receive service ready completion,
>>>>>>> polling..
>>>>>>> [41810.933769] ath10k_pci 0000:3a:00.0: service ready completion received,
>>>>>>> continuing normally
>>>>>>> [41810.986330] OOM killer enabled.
>>>>>>> [41810.986332] Restarting tasks: Starting
>>>>>>> […]
>>>>>>> ```
>>>>>>>
>>>>>>> Commit e57b7d62a1b2 (wifi: ath10k: poll service ready message before failing) [1][2],
>>>>>>> present since Linux v6.10-rc1, added this to avoid the hardware not being initialized:
>>>>>>>
>>>>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>>>>> if (!time_left) {
>>>>>>> /* Sometimes the PCI HIF doesn't receive interrupt
>>>>>>> * for the service ready message even if the buffer
>>>>>>> * was completed. PCIe sniffer shows that it's
>>>>>>> * because the corresponding CE ring doesn't fires
>>>>>>> * it. Workaround here by polling CE rings once.
>>>>>>> */
>>>>>>> ath10k_warn(ar, "failed to receive service ready completion,
>>>>>>> polling..\n");
>>>>>>>
>>>>>>> for (i = 0; i < CE_COUNT; i++)
>>>>>>> ath10k_hif_send_complete_check(ar, i, 1);
>>>>>>>
>>>>>>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>>>>>>>
>>>>>>> WMI_SERVICE_READY_TIMEOUT_HZ);
>>>>>>> if (!time_left) {
>>>>>>> ath10k_warn(ar, "polling timed out\n");
>>>>>>> return -ETIMEDOUT;
>>>>>>> }
>>>>>>>
>>>>>>> ath10k_warn(ar, "service ready completion received, continuing
>>>>>>> normally\n");
>>>>>>> }
>>>>>>>
>>>>>>> The comment says, it’s a hardware issue. I guess from the Qualcomm device and not the
>>>>>>> board design, as it happens with several devices like James’?
>>>>>>>
>>>>>>> Anyway, should polling be used by default then to avoid the delay?
>>>>>>
>>>>>> Adding additional polling before wait seems OK to me
>>>>>
>>>>> With the attached diff, I didn’t notice any issue on the Dell XPS 13 9360 with QCA6174.
>>>>
>>>> In the diff you are moving polling ahead of wait, IMO this might introduce some race:
>>>> what
>>>> if hardware/firmware send the event right after polling is done?
>>>>
>>>> So how about, instead of moving, just adding a new polling before wait:
>>>>
>>>> 1. polling
>>>> 2. wait
>>>> 3. poling again if wait fail
>>>
>>> I do not know the hardware behavior/design and the error, so cannot judge, if a race would
>>> be possible.
>>>
>>> Could Qualcomm take over to cook up a patch
>>> I’d appreciated if Qualcomm could take over to cook up a patch, as you have the
>>> datasheets, erratas and a line to the hardware designers.
>>
>> sure, I will see what I can do here
>
> Awesome. Thank you!
>
>>>>> Unrelated: The only thing I noticed is, that during boot (not resume) the function seems
>>>>> to be called twice. It looks like once for Wi-Fi and once for Bluetooth:
>>>>>
>>>>> ```
>>>>> [ 35.507604] ath10k_pci 0000:3a:00.0: board_file api 2 bmi_id N/A crc32 d2863f91
>>>>> [ 35.516010] usb 1-5: New USB device found, idVendor=0c45, idProduct=670c,
>>>>> bcdDevice=56.26
>>>>> [ 35.516022] usb 1-5: New USB device strings: Mfr=2, Product=1, SerialNumber=0
>>>>> [ 35.516026] usb 1-5: Product: Integrated_Webcam_HD
>>>>> [ 35.516029] usb 1-5: Manufacturer: CN09GTFMLOG008C8B7FWA01
>>>>> [ 35.587852] ath10k_pci 0000:3a:00.0: service ready completion received, continuing
>>>>> normally
>>>>> [ 35.606632] ath10k_pci 0000:3a:00.0: htt-ver 3.87 wmi-op 4 htt-op 3 cal otp max-
>>>>> sta 32 raw 0 hwcrypto 1
>>>>> [ 35.628744] mc: Linux media interface: v0.10
>>>>> [ 35.651301] nvme nvme0: using unchecked data buffer
>>>>> [ 35.687466] Bluetooth: Core ver 2.22
>>>>> [ 35.687493] NET: Registered PF_BLUETOOTH protocol family
>>>>> [ 35.687495] Bluetooth: HCI device and connection manager initialized
>>>>> [ 35.687499] Bluetooth: HCI socket layer initialized
>>>>> [ 35.687501] Bluetooth: L2CAP socket layer initialized
>>>>> [ 35.687505] Bluetooth: SCO socket layer initialized
>>>>> [ 35.696050] ath: EEPROM regdomain: 0x6c
>>>>> [ 35.696055] ath: EEPROM indicates we should expect a direct regpair map
>>>>> [ 35.696057] ath: Country alpha2 being used: 00
>>>>> [ 35.696058] ath: Regpair used: 0x6c
>>>>> [ 35.712821] ath10k_pci 0000:3a:00.0 wlp58s0: renamed from wlan0
>>>>> [ 35.716790] input: ELAN Touchscreen as /devices/pci0000:00/0000:00:14.0/
>>>>> usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input40
>>>>> [ 35.718912] videodev: Linux video capture interface: v2.00
>>>>> [ 35.719492] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/
>>>>> usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input41
>>>>> [ 35.719595] input: ELAN Touchscreen UNKNOWN as /devices/pci0000:00/0000:00:14.0/
>>>>> usb1/1-4/1-4:1.0/0003:04F3:2234.0002/input/input42
>>>>> [ 35.720899] hid-multitouch 0003:04F3:2234.0002: input,hiddev0,hidraw1: USB HID
>>>>> v1.10 Device [ELAN Touchscreen] on usb-0000:00:14.0-4/input0
>>>>> [ 35.720947] usbcore: registered new interface driver usbhid
>>>>> [ 35.720949] usbhid: USB HID core driver
>>>>> [ 35.812081] usbcore: registered new interface driver btusb
>>>>> [ 35.815263] Bluetooth: hci0: using rampatch file: qca/rampatch_usb_00000302.bin
>>>>> [ 35.815270] Bluetooth: hci0: QCA: patch rome 0x302 build 0x3e8, firmware rome
>>>>> 0x302 build 0x111
>>>>> [ 36.174345] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
>>>>> [ 36.199643] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is
>>>>> advertised, but not supported.
>>>>> [ 36.398657] ath10k_pci 0000:3a:00.0: service ready completion received, continuing
>>>>> normally
>>>>
>>>> Hmm, I don't think this is for BT as ath10k is not a BT driver. Something must be wrong
>>>> here ...
>>>>
>>>>> ```
>>>
>>> Can you reproduce it?
>>>
>>> How would I get a call graph for both function calls?
>>
>> # cd /sys/kernel/debug/tracing/
>> # echo 0 > ./tracing_on
>> # echo function >./current_tracer
>> /* replace function with what you want to trace, e.g. ath10k_wmi_wait_for_service_ready */
>> # echo <function> > ./set_ftrace_filter
>> # echo 1 > ./options/func_stack_trace
>> # echo 1 > ./tracing_on
>> # cat trace_pipe
>> /* reload ath10k driver */
>
> Somehow it did not work for me. I think, reloading the module seems to make it forget the
> function `ath10k_wmi_wait_for_service_ready()`.
>
> $ sudo cat /sys/kernel/debug/tracing/set_ftrace_filter
> ath10k_wmi_wait_for_service_ready [ath10k_core]
>
> Unload the module with `sudo modprobe -r ath10k_pci`.
>
> $ sudo cat /sys/kernel/debug/tracing/set_ftrace_filter
> $
>
> Load the module, and it’s still empty:
>
> $ sudo cat /sys/kernel/debug/tracing/set_ftrace_filter
> $
>
Yeah, my bad, I missed the side effect of reaload.
Never mind, since you can modify the source code, you can simply get call stack with:
$ git diff
diff --git a/drivers/net/wireless/ath/ath10k/wmi.c b/drivers/net/wireless/ath/ath10k/wmi.c
index cb8ae751eb31..eb591e059103 100644
--- a/drivers/net/wireless/ath/ath10k/wmi.c
+++ b/drivers/net/wireless/ath/ath10k/wmi.c
@@ -1766,6 +1766,8 @@ int ath10k_wmi_wait_for_service_ready(struct ath10k *ar)
{
unsigned long time_left, i;
+ dump_stack();
+
time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
WMI_SERVICE_READY_TIMEOUT_HZ);
if (!time_left) {
>>>>>>> Additionally I have two questions regarding the code:
>>>>>>>
>>>>>>> 1. Is `WMI_SERVICE_READY_TIMEOUT_HZ` the right value to pass to
>>>>>>> `wait_for_completion_timeout(struct completion *done, unsigned long timeout)`?
>>>>>>>
>>>>>>> The macro is defined as:
>>>>>>>
>>>>>>> drivers/net/wireless/ath/ath10k/wmi.h:#define WMI_SERVICE_READY_TIMEOUT_HZ
>>>>>>> (5 * HZ)
>>>>>>>
>>>>>>> `timeout` is supposed to be in jiffies, and `CONFIG_HZ_250=y` on my system. I
>>>>>>> wonder how
>>>>>>> that amounts to five seconds on my system.
>>>>>>
>>>>>> HZ is defined as jiffies per second, so 5 * HZ equals 5 seconds.
>>>
>>> Sorry, I missed to comment here in my previous reply. HZ can be defined differently – like
>>> 1000 HZ –, so the timeout would very, and then not match the actual timeout required by
>>> the hardware? `Documentation/scheduler/completion.rst` contains:
>>>
>>>> Timeouts are preferably calculated with msecs_to_jiffies() or usecs_to_jiffies(),
>>>> to make the code largely HZ-invariant.
>>
>> Hmm, new knowledge to me. Will check and update.
>
> Awesome!
>
>>>>>>> The timeout should probably be defined in seconds? Does the WMI specification say
>>>>>>> something about this?
>>>>>>>
>>>>>>> 2. Is the task interruptible and should
>>>>>>> `wait_for_completion_interruptible_timeout(struct completion *done, unsigned long
>>>>>>> timeout)` be used?
>>>>>>
>>>>>> While I am not sure for now, may I ask why the question?
>>>>>
>>>>> I was just reading up on `wait_for_completion_*()`, and so the different variants.
>>>>
>>>> If there is no obvious benefits I don't think the change is necessary.
>>>
>>> Thinking about it, the driver initialization is in the boot path (hot patch) so would
>>> block one thread(?) – or is that a wrong assumption –, which is unwanted?
>>
>> Indeed a thread would block there ... So you want to make the thread responsible to
>> signals? such as killing it when ath10k goes wrong?
>
> You got me, that I actually do not know, what the downsides are, and what signal/interrupt
> could be fired, and how it should be handled. As a side note: Other drivers use
> `wait_for_completion_interruptible_timeout()` also without checking the return value. If
> nobody else sheds light into this, please ignore my comment.
>
>
> Kind regards,
>
> Paul
>
>
>>>>>>> [1]: https://web.git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/
>>>>>>> commit/?id=e57b7d62a1b2f496caf0beba81cec3c90fad80d5
>>>>>>> [2]: https://lore.kernel.org/all/20240227030409.89702-1-quic_bqiang@quicinc.com/
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?
2025-07-28 7:39 ` athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`? Paul Menzel
2025-07-28 8:50 ` Baochen Qiang
@ 2025-07-29 9:41 ` Baochen Qiang
1 sibling, 0 replies; 7+ messages in thread
From: Baochen Qiang @ 2025-07-29 9:41 UTC (permalink / raw)
To: Paul Menzel
Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood,
Ingo Molnar, Peter Zijlstra, Juri Lelli, Vincent Guittot, LKML
On 7/28/2025 3:39 PM, Paul Menzel wrote:
>>>>> Additionally I have two questions regarding the code:
>>>>>
>>>>> 1. Is `WMI_SERVICE_READY_TIMEOUT_HZ` the right value to pass to
>>>>> `wait_for_completion_timeout(struct completion *done, unsigned long timeout)`?
>>>>>
>>>>> The macro is defined as:
>>>>>
>>>>> drivers/net/wireless/ath/ath10k/wmi.h:#define WMI_SERVICE_READY_TIMEOUT_HZ (5 *
>>>>> HZ)
>>>>>
>>>>> `timeout` is supposed to be in jiffies, and `CONFIG_HZ_250=y` on my system. I wonder how
>>>>> that amounts to five seconds on my system.
>>>>
>>>> HZ is defined as jiffies per second, so 5 * HZ equals 5 seconds.
>
> Sorry, I missed to comment here in my previous reply. HZ can be defined differently – like
Sorry for misleading - I was trying to say the HZ has a direct relationship with jiffies,
it equals jiffies-per-second in its value.
> 1000 HZ –, so the timeout would very, and then not match the actual timeout required by
> the hardware? `Documentation/scheduler/completion.rst` contains:
Not quite sure about what the 'timeout' actually mean here
- If you are referring it as the argument passed to wait_for_completion_timeout(): yes, of
course if could vary based on HZ value.
- But if you are talking about the actual max time wait_for_completion_timeout() will
block: the answer is NO.
>
>> Timeouts are preferably calculated with msecs_to_jiffies() or usecs_to_jiffies(),
>> to make the code largely HZ-invariant.
I am not quite understanding the 'HZ-invariant' here:
- Does it mean the actual max time blocked will vary if timeout argument is defined based
on HZ?
- Or it is saying the value of timeout argument itself could vary? But note the result of
msecs_to_jiffies() even varies on HZ as well.
^ permalink raw reply [flat|nested] 7+ messages in thread
* ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot (was: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?)
2025-07-29 2:27 ` Baochen Qiang
@ 2025-07-30 10:40 ` Paul Menzel
2025-07-31 0:12 ` ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot Baochen Qiang
0 siblings, 1 reply; 7+ messages in thread
From: Paul Menzel @ 2025-07-30 10:40 UTC (permalink / raw)
To: Baochen Qiang; +Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood, LKML
[Cc: remove scheduler folks]
Dear Baochen,
Thank you for your reply, and let’s fork this thread.
Am 29.07.25 um 04:27 schrieb Baochen Qiang:
[…]
> Never mind, since you can modify the source code, you can simply get
> call stack with:
>
> $ git diff
> diff --git a/drivers/net/wireless/ath/ath10k/wmi.c b/drivers/net/wireless/ath/ath10k/wmi.c
> index cb8ae751eb31..eb591e059103 100644
> --- a/drivers/net/wireless/ath/ath10k/wmi.c
> +++ b/drivers/net/wireless/ath/ath10k/wmi.c
> @@ -1766,6 +1766,8 @@ int ath10k_wmi_wait_for_service_ready(struct ath10k *ar)
> {
> unsigned long time_left, i;
>
> + dump_stack();
> +
> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
> WMI_SERVICE_READY_TIMEOUT_HZ);
> if (!time_left) {
Thanks, yes, I wanted to avoid it, but now added it to the end, and
started the Linux kernel.
With that, I got:
```
[ 0.000000] Linux version 6.16.0-04406-g154cace907b6
(build@bohemianrhapsody.molgen.mpg.de) (gcc (Debian 14.2.0-19) 14.2.0,
GNU ld (GNU Binutils for Debian) 2.44) #98 SMP PREEMPT_DYNAMIC Wed Jul
30 11:59:36 CEST 2025
[ 0.000000] Command line:
BOOT_IMAGE=/vmlinuz-6.16.0-04406-g154cace907b6
root=UUID=32e29882-d94d-4a92-9ee4-4d03002bfa29 ro quiet pci=noaer
mem_sleep_default=deep log_buf_len=16M cryptomgr.notests
usbcore.quirks=0cf3:e300:e,04f3:2234:e,0c45:670c:e
[…]
[ 0.000000] DMI: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0 06/02/2022
[…]
[ 14.624206] ath10k_pci 0000:3a:00.0: enabling device (0000 -> 0002)
[ 14.633316] ath10k_pci 0000:3a:00.0: pci irq msi oper_irq_mode 2
irq_mode 0 reset_mode 0
[ 14.662181] audit: type=1400 audit(1753869969.819:2):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name=4D6F6E676F444220436F6D70617373 pid=516 comm="apparmor_parser"
[ 14.662313] audit: type=1400 audit(1753869969.819:3):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="QtWebEngineProcess" pid=518 comm="apparmor_parser"
[ 14.663112] audit: type=1400 audit(1753869969.819:4):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="1password" pid=514 comm="apparmor_parser"
[ 14.664059] audit: type=1400 audit(1753869969.819:5):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="Discord" pid=515 comm="apparmor_parser"
[ 14.664963] audit: type=1400 audit(1753869969.819:6):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="balena-etcher" pid=523 comm="apparmor_parser"
[ 14.665357] audit: type=1400 audit(1753869969.819:7):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="buildah" pid=525 comm="apparmor_parser"
[ 14.665479] audit: type=1400 audit(1753869969.819:8):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="brave" pid=524 comm="apparmor_parser"
[ 14.666813] audit: type=1400 audit(1753869969.823:9):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="cam" pid=527 comm="apparmor_parser"
[ 14.666817] audit: type=1400 audit(1753869969.823:10):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="busybox" pid=526 comm="apparmor_parser"
[ 14.667174] audit: type=1400 audit(1753869969.823:11):
apparmor="STATUS" operation="profile_load" profile="unconfined"
name="ch-checkns" pid=528 comm="apparmor_parser"
[ 14.719843] usbcore: registered new interface driver uvcvideo
[ 14.792965] snd_hda_intel 0000:00:1f.3: enabling device (0000 -> 0002)
[ 14.793498] snd_hda_intel 0000:00:1f.3: bound 0000:00:02.0 (ops
intel_audio_component_bind_ops [i915])
[ 14.837438] snd_hda_codec_generic hdaudioC0D0: autoconfig for
Generic: line_outs=1 (0x14/0x0/0x0/0x0/0x0) type:speaker
[ 14.837458] snd_hda_codec_generic hdaudioC0D0: speaker_outs=0
(0x0/0x0/0x0/0x0/0x0)
[ 14.837467] snd_hda_codec_generic hdaudioC0D0: hp_outs=1
(0x21/0x0/0x0/0x0/0x0)
[ 14.837475] snd_hda_codec_generic hdaudioC0D0: mono: mono_out=0x0
[ 14.837480] snd_hda_codec_generic hdaudioC0D0: inputs:
[ 14.837485] snd_hda_codec_generic hdaudioC0D0: Mic=0x12
[ 14.870772] ath10k_pci 0000:3a:00.0: qca6174 hw3.2 target 0x05030000
chip_id 0x00340aff sub 1a56:1535
[ 14.870778] ath10k_pci 0000:3a:00.0: kconfig debug 0 debugfs 0
tracing 0 dfs 0 testmode 0
[ 14.870853] ath10k_pci 0000:3a:00.0: firmware ver
WLAN.RM.4.4.1-00309- api 6 features wowlan,ignore-otp,mfp crc32 0793bcf2
[ 14.877651] input: HDA Intel PCH Front Headphone as
/devices/pci0000:00/0000:00:1f.3/sound/card0/input24
[ 14.877724] input: HDA Intel PCH HDMI/DP,pcm=3 as
/devices/pci0000:00/0000:00:1f.3/sound/card0/input25
[ 14.877788] input: HDA Intel PCH HDMI/DP,pcm=7 as
/devices/pci0000:00/0000:00:1f.3/sound/card0/input26
[ 14.877872] input: HDA Intel PCH HDMI/DP,pcm=8 as
/devices/pci0000:00/0000:00:1f.3/sound/card0/input27
[ 14.944938] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
[ 14.946658] ath10k_pci 0000:3a:00.0: board_file api 2 bmi_id N/A
crc32 d2863f91
[ 14.967545] Bluetooth: hci0: HCI Enhanced Setup Synchronous
Connection command is advertised, but not supported.
[ 15.027036] CPU: 1 UID: 0 PID: 41 Comm: kworker/u16:2 Not tainted
6.16.0-04406-g154cace907b6 #98 PREEMPT(voluntary)
[ 15.027044] Hardware name: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0
06/02/2022
[ 15.027046] Workqueue: ath10k_wq ath10k_core_register_work [ath10k_core]
[ 15.027084] Call Trace:
[ 15.027088] <TASK>
[ 15.027091] dump_stack_lvl+0x5d/0x80
[ 15.027100] ath10k_wmi_wait_for_service_ready.cold+0x5/0xc [ath10k_core]
[ 15.027136] ath10k_core_start+0xaec/0x1090 [ath10k_core]
[ 15.027169] ath10k_core_register_work+0x5c4/0x930 [ath10k_core]
[ 15.027198] process_one_work+0x185/0x340
[ 15.027205] worker_thread+0x252/0x3a0
[ 15.027210] ? rescuer_thread+0x4b0/0x4b0
[ 15.027215] kthread+0xf9/0x240
[ 15.027219] ? kthreads_online_cpu+0x120/0x120
[ 15.027223] ? kthreads_online_cpu+0x120/0x120
[ 15.027227] ret_from_fork+0x198/0x1d0
[ 15.027232] ? kthreads_online_cpu+0x120/0x120
[ 15.027235] ret_from_fork_asm+0x11/0x20
[ 15.027243] </TASK>
[ 15.046899] ath10k_pci 0000:3a:00.0: htt-ver 3.87 wmi-op 4 htt-op 3
cal otp max-sta 32 raw 0 hwcrypto 1
[ 15.053439] nvme nvme0: using unchecked data buffer
[ 15.120478] ath: EEPROM regdomain: 0x6c
[ 15.120483] ath: EEPROM indicates we should expect a direct regpair map
[ 15.120485] ath: Country alpha2 being used: 00
[ 15.120486] ath: Regpair used: 0x6c
[ 15.153053] ath10k_pci 0000:3a:00.0 wlp58s0: renamed from wlan0
[ 15.644071] CPU: 0 UID: 0 PID: 675 Comm: NetworkManager Not tainted
6.16.0-04406-g154cace907b6 #98 PREEMPT(voluntary)
[ 15.644075] Hardware name: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0
06/02/2022
[ 15.644077] Call Trace:
[ 15.644079] <TASK>
[ 15.644082] dump_stack_lvl+0x5d/0x80
[ 15.644089] ath10k_wmi_wait_for_service_ready.cold+0x5/0xc [ath10k_core]
[ 15.644104] ath10k_core_start+0xaec/0x1090 [ath10k_core]
[ 15.644115] ath10k_start+0xb8/0x840 [ath10k_core]
[ 15.644125] drv_start+0x3c/0xf0 [mac80211]
[ 15.644165] ieee80211_do_open+0x2c2/0x7f0 [mac80211]
[ 15.644197] ieee80211_open+0x84/0x90 [mac80211]
[ 15.644230] __dev_open+0xee/0x200
[ 15.644233] __dev_change_flags+0x1ef/0x230
[ 15.644234] ? prep_new_page+0xcc/0x1d0
[ 15.644237] netif_change_flags+0x26/0x60
[ 15.644238] do_setlink.isra.0+0x348/0x1150
[ 15.644241] ? __nla_validate_parse+0x5e/0xc70
[ 15.644243] ? security_capable+0x66/0xa0
[ 15.644245] rtnl_newlink+0x892/0xc20
[ 15.644247] ? update_load_avg+0x80/0x760
[ 15.644249] ? update_curr+0x90/0x170
[ 15.644250] ? mod_memcg_lruvec_state+0x191/0x1d0
[ 15.644253] ? do_setlink.isra.0+0x1150/0x1150
[ 15.644254] rtnetlink_rcv_msg+0x348/0x3e0
[ 15.644257] ? rtnl_calcit.isra.0+0x120/0x120
[ 15.644260] netlink_rcv_skb+0x4f/0x100
[ 15.644263] netlink_unicast+0x273/0x3d0
[ 15.644265] netlink_sendmsg+0x228/0x470
[ 15.644267] __sock_sendmsg+0x38/0x70
[ 15.644270] ? __import_iovec+0x139/0x180
[ 15.644272] ____sys_sendmsg+0x1c0/0x260
[ 15.644275] ? import_iovec+0xb/0x10
[ 15.644277] ___sys_sendmsg+0x95/0xd0
[ 15.644279] __sys_sendmsg+0x7b/0xd0
[ 15.644282] do_syscall_64+0x84/0xae0
[ 15.644284] ? pollwake+0x77/0x90
[ 15.644287] ? wake_up_state+0x10/0x10
[ 15.644288] ? __wake_up_common+0x72/0x90
[ 15.644290] ? eventfd_write+0xe1/0x210
[ 15.644292] ? security_file_permission+0x35/0x70
[ 15.644294] ? vfs_write+0xcc/0x460
[ 15.644296] ? ___sys_sendmsg+0xa1/0xd0
[ 15.644297] ? ksys_write+0xc7/0xe0
[ 15.644298] ? do_syscall_64+0xbc/0xae0
[ 15.644301] ? __sys_sendmsg+0xb6/0xd0
[ 15.644303] ? do_syscall_64+0xbc/0xae0
[ 15.644304] ? do_syscall_64+0xbc/0xae0
[ 15.644306] ? do_syscall_64+0xbc/0xae0
[ 15.644308] entry_SYSCALL_64_after_hwframe+0x4b/0x53
[ 15.644310] RIP: 0033:0x7fa5c3ca49ee
[ 15.644334] Code: 08 0f 85 f5 4b ff ff 49 89 fb 48 89 f0 48 89 d7 48
89 ce 4c 89 c2 4d 89 ca 4c 8b 44 24 08 4c 8b 4c 24 10 4c 89 5c 24 08 0f
05 <c3> 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 80 00 00 00 00 48 83 ec 08
[ 15.644335] RSP: 002b:00007ffc2e929548 EFLAGS: 00000246 ORIG_RAX:
000000000000002e
[ 15.644338] RAX: ffffffffffffffda RBX: 00007fa5c3094580 RCX:
00007fa5c3ca49ee
[ 15.644339] RDX: 0000000000000000 RSI: 00007ffc2e9295d0 RDI:
000000000000000d
[ 15.644340] RBP: 00007ffc2e9295d0 R08: 0000000000000000 R09:
0000000000000000
[ 15.644340] R10: 0000000000000000 R11: 0000000000000246 R12:
000000000000001c
[ 15.644341] R13: 00007ffc2e9297c8 R14: 00007ffc2e9297bc R15:
0000000000000000
[ 15.644343] </TASK>
[ 18.369625] pci 0000:01:00.0: [8086:1576] type 01 class 0x060400 PCIe
Switch Upstream Port
[ 18.369702] pci 0000:01:00.0: PCI bridge to [bus 02-39]
[…]
```
Kind regards,
Paul
^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot
2025-07-30 10:40 ` ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot (was: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?) Paul Menzel
@ 2025-07-31 0:12 ` Baochen Qiang
0 siblings, 0 replies; 7+ messages in thread
From: Baochen Qiang @ 2025-07-31 0:12 UTC (permalink / raw)
To: Paul Menzel; +Cc: Baochen Qiang, Jeff Johnson, ath10k, James Prestwood, LKML
On 7/30/2025 6:40 PM, Paul Menzel wrote:
> [Cc: remove scheduler folks]
>
> Dear Baochen,
>
>
> Thank you for your reply, and let’s fork this thread.
>
>
> Am 29.07.25 um 04:27 schrieb Baochen Qiang:
>
> […]
>
>> Never mind, since you can modify the source code, you can simply get
>> call stack with:
>>
>> $ git diff
>> diff --git a/drivers/net/wireless/ath/ath10k/wmi.c b/drivers/net/wireless/ath/ath10k/wmi.c
>> index cb8ae751eb31..eb591e059103 100644
>> --- a/drivers/net/wireless/ath/ath10k/wmi.c
>> +++ b/drivers/net/wireless/ath/ath10k/wmi.c
>> @@ -1766,6 +1766,8 @@ int ath10k_wmi_wait_for_service_ready(struct ath10k *ar)
>> {
>> unsigned long time_left, i;
>>
>> + dump_stack();
>> +
>> time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
>> WMI_SERVICE_READY_TIMEOUT_HZ);
>> if (!time_left) {
>
> Thanks, yes, I wanted to avoid it, but now added it to the end, and started the Linux kernel.
>
> With that, I got:
>
> ```
> [ 0.000000] Linux version 6.16.0-04406-g154cace907b6
> (build@bohemianrhapsody.molgen.mpg.de) (gcc (Debian 14.2.0-19) 14.2.0, GNU ld (GNU
> Binutils for Debian) 2.44) #98 SMP PREEMPT_DYNAMIC Wed Jul 30 11:59:36 CEST 2025
> [ 0.000000] Command line: BOOT_IMAGE=/vmlinuz-6.16.0-04406-g154cace907b6
> root=UUID=32e29882-d94d-4a92-9ee4-4d03002bfa29 ro quiet pci=noaer mem_sleep_default=deep
> log_buf_len=16M cryptomgr.notests usbcore.quirks=0cf3:e300:e,04f3:2234:e,0c45:670c:e
> […]
> [ 0.000000] DMI: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0 06/02/2022
> […]
> [ 14.624206] ath10k_pci 0000:3a:00.0: enabling device (0000 -> 0002)
> [ 14.633316] ath10k_pci 0000:3a:00.0: pci irq msi oper_irq_mode 2 irq_mode 0 reset_mode 0
> [ 14.662181] audit: type=1400 audit(1753869969.819:2): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name=4D6F6E676F444220436F6D70617373 pid=516
> comm="apparmor_parser"
> [ 14.662313] audit: type=1400 audit(1753869969.819:3): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="QtWebEngineProcess" pid=518
> comm="apparmor_parser"
> [ 14.663112] audit: type=1400 audit(1753869969.819:4): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="1password" pid=514 comm="apparmor_parser"
> [ 14.664059] audit: type=1400 audit(1753869969.819:5): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="Discord" pid=515 comm="apparmor_parser"
> [ 14.664963] audit: type=1400 audit(1753869969.819:6): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="balena-etcher" pid=523
> comm="apparmor_parser"
> [ 14.665357] audit: type=1400 audit(1753869969.819:7): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="buildah" pid=525 comm="apparmor_parser"
> [ 14.665479] audit: type=1400 audit(1753869969.819:8): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="brave" pid=524 comm="apparmor_parser"
> [ 14.666813] audit: type=1400 audit(1753869969.823:9): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="cam" pid=527 comm="apparmor_parser"
> [ 14.666817] audit: type=1400 audit(1753869969.823:10): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="busybox" pid=526 comm="apparmor_parser"
> [ 14.667174] audit: type=1400 audit(1753869969.823:11): apparmor="STATUS"
> operation="profile_load" profile="unconfined" name="ch-checkns" pid=528
> comm="apparmor_parser"
> [ 14.719843] usbcore: registered new interface driver uvcvideo
> [ 14.792965] snd_hda_intel 0000:00:1f.3: enabling device (0000 -> 0002)
> [ 14.793498] snd_hda_intel 0000:00:1f.3: bound 0000:00:02.0 (ops
> intel_audio_component_bind_ops [i915])
> [ 14.837438] snd_hda_codec_generic hdaudioC0D0: autoconfig for Generic: line_outs=1
> (0x14/0x0/0x0/0x0/0x0) type:speaker
> [ 14.837458] snd_hda_codec_generic hdaudioC0D0: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
> [ 14.837467] snd_hda_codec_generic hdaudioC0D0: hp_outs=1 (0x21/0x0/0x0/0x0/0x0)
> [ 14.837475] snd_hda_codec_generic hdaudioC0D0: mono: mono_out=0x0
> [ 14.837480] snd_hda_codec_generic hdaudioC0D0: inputs:
> [ 14.837485] snd_hda_codec_generic hdaudioC0D0: Mic=0x12
> [ 14.870772] ath10k_pci 0000:3a:00.0: qca6174 hw3.2 target 0x05030000 chip_id 0x00340aff
> sub 1a56:1535
> [ 14.870778] ath10k_pci 0000:3a:00.0: kconfig debug 0 debugfs 0 tracing 0 dfs 0 testmode 0
> [ 14.870853] ath10k_pci 0000:3a:00.0: firmware ver WLAN.RM.4.4.1-00309- api 6 features
> wowlan,ignore-otp,mfp crc32 0793bcf2
> [ 14.877651] input: HDA Intel PCH Front Headphone as /devices/pci0000:00/0000:00:1f.3/
> sound/card0/input24
> [ 14.877724] input: HDA Intel PCH HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:1f.3/
> sound/card0/input25
> [ 14.877788] input: HDA Intel PCH HDMI/DP,pcm=7 as /devices/pci0000:00/0000:00:1f.3/
> sound/card0/input26
> [ 14.877872] input: HDA Intel PCH HDMI/DP,pcm=8 as /devices/pci0000:00/0000:00:1f.3/
> sound/card0/input27
> [ 14.944938] Bluetooth: hci0: using NVM file: qca/nvm_usb_00000302.bin
> [ 14.946658] ath10k_pci 0000:3a:00.0: board_file api 2 bmi_id N/A crc32 d2863f91
> [ 14.967545] Bluetooth: hci0: HCI Enhanced Setup Synchronous Connection command is
> advertised, but not supported.
> [ 15.027036] CPU: 1 UID: 0 PID: 41 Comm: kworker/u16:2 Not tainted 6.16.0-04406-
> g154cace907b6 #98 PREEMPT(voluntary)
> [ 15.027044] Hardware name: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0 06/02/2022
> [ 15.027046] Workqueue: ath10k_wq ath10k_core_register_work [ath10k_core]
> [ 15.027084] Call Trace:
> [ 15.027088] <TASK>
> [ 15.027091] dump_stack_lvl+0x5d/0x80
> [ 15.027100] ath10k_wmi_wait_for_service_ready.cold+0x5/0xc [ath10k_core]
> [ 15.027136] ath10k_core_start+0xaec/0x1090 [ath10k_core]
> [ 15.027169] ath10k_core_register_work+0x5c4/0x930 [ath10k_core]
> [ 15.027198] process_one_work+0x185/0x340
> [ 15.027205] worker_thread+0x252/0x3a0
> [ 15.027210] ? rescuer_thread+0x4b0/0x4b0
> [ 15.027215] kthread+0xf9/0x240
> [ 15.027219] ? kthreads_online_cpu+0x120/0x120
> [ 15.027223] ? kthreads_online_cpu+0x120/0x120
> [ 15.027227] ret_from_fork+0x198/0x1d0
> [ 15.027232] ? kthreads_online_cpu+0x120/0x120
> [ 15.027235] ret_from_fork_asm+0x11/0x20
> [ 15.027243] </TASK>
OK, so this is from driver load.
> [ 15.046899] ath10k_pci 0000:3a:00.0: htt-ver 3.87 wmi-op 4 htt-op 3 cal otp max-sta 32
> raw 0 hwcrypto 1
> [ 15.053439] nvme nvme0: using unchecked data buffer
> [ 15.120478] ath: EEPROM regdomain: 0x6c
> [ 15.120483] ath: EEPROM indicates we should expect a direct regpair map
> [ 15.120485] ath: Country alpha2 being used: 00
> [ 15.120486] ath: Regpair used: 0x6c
> [ 15.153053] ath10k_pci 0000:3a:00.0 wlp58s0: renamed from wlan0
> [ 15.644071] CPU: 0 UID: 0 PID: 675 Comm: NetworkManager Not tainted 6.16.0-04406-
> g154cace907b6 #98 PREEMPT(voluntary)
> [ 15.644075] Hardware name: Dell Inc. XPS 13 9360/0596KF, BIOS 2.21.0 06/02/2022
> [ 15.644077] Call Trace:
> [ 15.644079] <TASK>
> [ 15.644082] dump_stack_lvl+0x5d/0x80
> [ 15.644089] ath10k_wmi_wait_for_service_ready.cold+0x5/0xc [ath10k_core]
> [ 15.644104] ath10k_core_start+0xaec/0x1090 [ath10k_core]
> [ 15.644115] ath10k_start+0xb8/0x840 [ath10k_core]
> [ 15.644125] drv_start+0x3c/0xf0 [mac80211]
> [ 15.644165] ieee80211_do_open+0x2c2/0x7f0 [mac80211]
> [ 15.644197] ieee80211_open+0x84/0x90 [mac80211]
> [ 15.644230] __dev_open+0xee/0x200
> [ 15.644233] __dev_change_flags+0x1ef/0x230
> [ 15.644234] ? prep_new_page+0xcc/0x1d0
> [ 15.644237] netif_change_flags+0x26/0x60
> [ 15.644238] do_setlink.isra.0+0x348/0x1150
> [ 15.644241] ? __nla_validate_parse+0x5e/0xc70
> [ 15.644243] ? security_capable+0x66/0xa0
> [ 15.644245] rtnl_newlink+0x892/0xc20
> [ 15.644247] ? update_load_avg+0x80/0x760
> [ 15.644249] ? update_curr+0x90/0x170
> [ 15.644250] ? mod_memcg_lruvec_state+0x191/0x1d0
> [ 15.644253] ? do_setlink.isra.0+0x1150/0x1150
> [ 15.644254] rtnetlink_rcv_msg+0x348/0x3e0
> [ 15.644257] ? rtnl_calcit.isra.0+0x120/0x120
> [ 15.644260] netlink_rcv_skb+0x4f/0x100
> [ 15.644263] netlink_unicast+0x273/0x3d0
> [ 15.644265] netlink_sendmsg+0x228/0x470
> [ 15.644267] __sock_sendmsg+0x38/0x70
> [ 15.644270] ? __import_iovec+0x139/0x180
> [ 15.644272] ____sys_sendmsg+0x1c0/0x260
> [ 15.644275] ? import_iovec+0xb/0x10
> [ 15.644277] ___sys_sendmsg+0x95/0xd0
> [ 15.644279] __sys_sendmsg+0x7b/0xd0
> [ 15.644282] do_syscall_64+0x84/0xae0
> [ 15.644284] ? pollwake+0x77/0x90
> [ 15.644287] ? wake_up_state+0x10/0x10
> [ 15.644288] ? __wake_up_common+0x72/0x90
> [ 15.644290] ? eventfd_write+0xe1/0x210
> [ 15.644292] ? security_file_permission+0x35/0x70
> [ 15.644294] ? vfs_write+0xcc/0x460
> [ 15.644296] ? ___sys_sendmsg+0xa1/0xd0
> [ 15.644297] ? ksys_write+0xc7/0xe0
> [ 15.644298] ? do_syscall_64+0xbc/0xae0
> [ 15.644301] ? __sys_sendmsg+0xb6/0xd0
> [ 15.644303] ? do_syscall_64+0xbc/0xae0
> [ 15.644304] ? do_syscall_64+0xbc/0xae0
> [ 15.644306] ? do_syscall_64+0xbc/0xae0
> [ 15.644308] entry_SYSCALL_64_after_hwframe+0x4b/0x53
> [ 15.644310] RIP: 0033:0x7fa5c3ca49ee
> [ 15.644334] Code: 08 0f 85 f5 4b ff ff 49 89 fb 48 89 f0 48 89 d7 48 89 ce 4c 89 c2 4d
> 89 ca 4c 8b 44 24 08 4c 8b 4c 24 10 4c 89 5c 24 08 0f 05 <c3> 66 2e 0f 1f 84 00 00 00 00
> 00 0f 1f 80 00 00 00 00 48 83 ec 08
> [ 15.644335] RSP: 002b:00007ffc2e929548 EFLAGS: 00000246 ORIG_RAX: 000000000000002e
> [ 15.644338] RAX: ffffffffffffffda RBX: 00007fa5c3094580 RCX: 00007fa5c3ca49ee
> [ 15.644339] RDX: 0000000000000000 RSI: 00007ffc2e9295d0 RDI: 000000000000000d
> [ 15.644340] RBP: 00007ffc2e9295d0 R08: 0000000000000000 R09: 0000000000000000
> [ 15.644340] R10: 0000000000000000 R11: 0000000000000246 R12: 000000000000001c
> [ 15.644341] R13: 00007ffc2e9297c8 R14: 00007ffc2e9297bc R15: 0000000000000000
> [ 15.644343] </TASK>
> [ 18.369625] pci 0000:01:00.0: [8086:1576] type 01 class 0x060400 PCIe Switch Upstream Port
> [ 18.369702] pci 0000:01:00.0: PCI bridge to [bus 02-39]
and this is from userspace starting to bringup the WLAN interface: calling the _start() ops.
In summary, the two instances of 'wait for service ready' are expected behavior.
> […]
> ```
>
>
> Kind regards,
>
> Paul
^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2025-07-31 0:12 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
[not found] <97a15967-5518-4731-a8ff-d43ff7f437b0@molgen.mpg.de>
[not found] ` <3cbe13e1-a820-4804-a28c-a57e2ee7a020@oss.qualcomm.com>
[not found] ` <8716a67c-6e33-4a35-8d96-33f81c07c8e0@molgen.mpg.de>
[not found] ` <1e797dea-d2e1-4947-8ef3-d2ac5ea0c156@oss.qualcomm.com>
2025-07-28 7:39 ` athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`? Paul Menzel
2025-07-28 8:50 ` Baochen Qiang
2025-07-28 12:48 ` Paul Menzel
2025-07-29 2:27 ` Baochen Qiang
2025-07-30 10:40 ` ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot (was: athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`?) Paul Menzel
2025-07-31 0:12 ` ath10k: ath10k_wmi_wait_for_service_ready() called twice during boot Baochen Qiang
2025-07-29 9:41 ` athk10: Poll service ready completion by default to avoid warning `failed to receive service ready completion, polling..`? Baochen Qiang
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox
all inboxes | Powered by JetHome®