* 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
* 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
* 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
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®