前回、ath10k_pci.koドライバロード時にファームのダウンロードに失敗。原因究明中。

【関連記事】
【組込ボードで無線LAN】②(無線LANカードN-6300を組込ボードに接続するには?)
【組込ボードで無線LAN】⑧(iwのビルド:後編-1)【組込ボードで無線LAN】⑰(QCA9377-5を挿してみた)
【組込ボードで無線LAN】㉓(backportをビルドしてみる‐2)
  • なぜファームダウンロードに失敗するのか
まずエラー発生状況を振り返る。まずピンク太字で書いた”failed to receive control response completion, polling..”に着目した。
# insmod compat.ko
Loading modules backported from Linux version v4.4.2-0-g1cb8570
Backport generated by backports.git v4.4.2-1-0-gbec4037
# insmod cfg80211.ko
# insmod mac80211.ko
# insmod ath.ko
# insmod ath10k_core.ko
# insmod ath10k_pci.ko
ath10k_pci 0000:01:00.0: pci irq msi interrupts 1 irq_mode 0 reset_mode 0
root@nitrogen6x:~# ath10k_pci 0000:01:00.0: failed to receive control response completion, polling..
ath10k_pci 0000:01:00.0: ctl_resp never came in (-110)
ath10k_pci 0000:01:00.0: failed to connect to HTC: -110
ath10k_pci 0000:01:00.0: could not init core (-110)
ath10k_pci 0000:01:00.0: could not probe fw (-110)
failed to receive control response completion, polling..”でgrepしてみたらhtc.cがヒットしたのでviで開く。
$ cd /home/pavement1234/backports/backports-4.4.2-1/drivers/net/wireless/ath/ath10k
$ grep "failed to receive control response completion, polling.." *.c
htc.c:          ath10k_warn(ar, "failed to receive control response completion, polling..\n");
$ vi htc.c
該当の文字列が定義されている関数を抜き出した。エラー要因についてworkaroundが書いてある(緑字の箇所)。
int ath10k_htc_wait_target(struct ath10k_htc *htc)
{
        struct ath10k *ar = htc->ar;
        int i, status = 0;
        unsigned long time_left;
        struct ath10k_htc_svc_conn_req conn_req;
        struct ath10k_htc_svc_conn_resp conn_resp;
        struct ath10k_htc_msg *msg;
        u16 message_id;
        u16 credit_count;
        u16 credit_size;

        time_left = wait_for_completion_timeout(&htc->ctl_resp,
                                                ATH10K_HTC_WAIT_TIMEOUT_HZ);
        if (!time_left) {
                /* Workaround: In some cases the PCI HIF doesn't
                 * receive interrupt for the control response message
                 * even if the buffer was completed. It is suspected
                 * iomap writes unmasking PCI CE irqs aren't propagated
                 * properly in KVM PCI-passthrough sometimes.
                 */

                ath10k_warn(ar, "failed to receive control response completion, polling..\n");

                for (i = 0; i < CE_COUNT; i++)
                        ath10k_hif_send_complete_check(htc->ar, i, 1);

                time_left =
                wait_for_completion_timeout(&htc->ctl_resp,
                                            ATH10K_HTC_WAIT_TIMEOUT_HZ);

                if (!time_left)
                        status = -ETIMEDOUT;
        }

        if (status < 0) {
                ath10k_err(ar, "ctl_resp never came in (%d)\n", status);
                return status;
        }

        if (htc->control_resp_len < sizeof(msg->hdr) + sizeof(msg->ready)) {
                ath10k_err(ar, "Invalid HTC ready msg len:%d\n",
                           htc->control_resp_len);
                return -ECOMM;
        }

        msg = (struct ath10k_htc_msg *)htc->control_resp_buffer;
        message_id   = __le16_to_cpu(msg->hdr.message_id);
        credit_count = __le16_to_cpu(msg->ready.credit_count);
        credit_size  = __le16_to_cpu(msg->ready.credit_size);

        if (message_id != ATH10K_HTC_MSG_READY_ID) {
                ath10k_err(ar, "Invalid HTC ready msg: 0x%x\n", message_id);
                return -ECOMM;
        }

        htc->total_transmit_credits = credit_count;
        htc->target_credit_size = credit_size;

        ath10k_dbg(ar, ATH10K_DBG_HTC,
                   "Target ready! transmit resources: %d size:%d\n",
                   htc->total_transmit_credits,
                   htc->target_credit_size);

        if ((htc->total_transmit_credits == 0) ||
            (htc->target_credit_size == 0)) {
                ath10k_err(ar, "Invalid credit size received\n");
                return -ECOMM;
        }

        ath10k_htc_setup_target_buffer_assignments(htc);

        /* setup our pseudo HTC control endpoint connection */
        memset(&conn_req, 0, sizeof(conn_req));
        memset(&conn_resp, 0, sizeof(conn_resp));
        conn_req.ep_ops.ep_tx_complete = ath10k_htc_control_tx_complete;
        conn_req.ep_ops.ep_rx_complete = ath10k_htc_control_rx_complete;
        conn_req.max_send_queue_depth = ATH10K_NUM_CONTROL_TX_BUFFERS;
        conn_req.service_id = ATH10K_HTC_SVC_ID_RSVD_CTRL;

        /* connect fake service */
        status = ath10k_htc_connect_service(htc, &conn_req, &conn_resp);
        if (status) {
                ath10k_err(ar, "could not connect to htc service (%d)\n",
                           status);
                return status;
        }

        return 0;
}
Googleで和訳してみた。KVM PCIパススルーにすると割込みが伝播されないことがある。みたいな話かね。ところでKVM PCIパススルーって何だろう?
Workaround In some cases the PCI HIF doesn't receive interrupt for the control response message even if the buffer was completed. It is suspected iomap writes unmasking PCI CE irqs aren't propagated properly in KVM PCI-passthrough sometimes.

(Google和訳)
【回避策】場合によっては、バッファが完了しても、PCI HIFは制御応答メッセージの割り込みを受信しません。 iomapの書き込みマスク解除PCI CE irqがKVM PCIパススルーで適切に伝播されないことがあると思われます。
KVM PCIパススルーでGoogle検索してみたら、めずらしく日本語サイトがヒット。linux-KVM PCIパススルーを使用すると、ゲストでGTX 1080のドライバーが機能しないを読んだ。

いまいちわからん。KVMって何?Google検索したらKVMとはKernel-based Virtual Machineであることが判明。Kernel-based Virtual Machineを読むと、どうも仮想OS的な話みたいだけど、今回実機で動かしてるから仮想化は関係ない気がする。

ではPCIパススルーとは何か?Google検索したらPCIパススルーとはとかKVM PCIパススルー (PCI PassThrough)がヒット。読むとやはり仮想OSの話の様子。あんまり関係ないね。


次にタイムアウトを発生させているwait_for_completion_timeoutをgrepしてみた。呼び出ししかない...。カーネルAPIか...。
$ grep "wait_for_completion_timeout" *.c
ath10k_core.mod.c:      { 0x7cf9099, __VMLINUX_SYMBOL_STR(wait_for_completion_timeout) },
core.c: time_left = wait_for_completion_timeout(&ar->target_suspend, 1 * HZ);
debug.c:                wait_for_completion_timeout(&ar->debug.fw_stats_complete,
debug.c:        time_left = wait_for_completion_timeout(&ar->debug.tpc_complete,
htc.c:  time_left = wait_for_completion_timeout(&htc->ctl_resp,
htc.c:          wait_for_completion_timeout(&htc->ctl_resp,
htc.c:  time_left = wait_for_completion_timeout(&htc->ctl_resp,
htt.c:  status = wait_for_completion_timeout(&htt->target_version_received,
mac.c:  time_left = wait_for_completion_timeout(&ar->install_key_done, 3 * HZ);
mac.c:  time_left = wait_for_completion_timeout(&ar->vdev_setup_done,
mac.c:          wait_for_completion_timeout(&ar->offchan_tx_completed, 3 * HZ);
mac.c:  ret = wait_for_completion_timeout(&ar->scan.completed, 3*HZ);
mac.c:  ret = wait_for_completion_timeout(&ar->scan.started, 1*HZ);
mac.c:  ret = wait_for_completion_timeout(&ar->scan.on_channel, 3*HZ);
thermal.c:      time_left = wait_for_completion_timeout(&ar->thermal.wmi_sync,
wmi.c:  time_left = wait_for_completion_timeout(&ar->wmi.service_ready,
wmi.c:  time_left = wait_for_completion_timeout(&ar->wmi.unified_ready,
wow.c:  ret = wait_for_completion_timeout(&ar->target_suspend, 3 * HZ);
wow.c:  ret = wait_for_completion_timeout(&ar->wow.wakeup_completed, 3 * HZ);
wait_for_completion_timeoutkernel/sched/completion.cに定義されてる様子。

wait_for_completion_timeoutの中でwait_for_commonが呼ばれてる。
1

wait_for_commonの中で __wait_for_commonが呼ばれてる。

1

__wait_for_commonの中でdo_wait_for_commonが呼ばれてる。

1

do_wait_for_commonはこんな感じ。ウェイト処理ということですね。

1

次にタイムアウトが発生している関数。ath10k_htc_wait_targetを呼び出してる箇所を調べてみる。core.cで呼ばれてるのでviで開いた。
$ grep "ath10k_htc_wait_target" *.c
core.c: status = ath10k_htc_wait_target(&ar->htc);
htc.c:int ath10k_htc_wait_target(struct ath10k_htc *htc)
$ vi core.c
ath10k_htc_wait_targetが呼ばれている関数を抜き出したath10k_htc_wait_targetath10k_hif_startの処理結果を待つ関数のようだ。
int ath10k_core_start(struct ath10k *ar, enum ath10k_firmware_mode mode)
{
        int status;

        lockdep_assert_held(&ar->conf_mutex);

        clear_bit(ATH10K_FLAG_CRASH_FLUSH, &ar->dev_flags);

        ath10k_bmi_start(ar);

        if (ath10k_init_configure_target(ar)) {
                status = -EINVAL;
                goto err;
        }

        status = ath10k_download_cal_data(ar);
        if (status)
                goto err;

        /* Some of of qca988x solutions are having global reset issue
         * during target initialization. Bypassing PLL setting before
         * downloading firmware and letting the SoC run on REF_CLK is
         * fixing the problem. Corresponding firmware change is also needed
         * to set the clock source once the target is initialized.
         */
        if (test_bit(ATH10K_FW_FEATURE_SUPPORTS_SKIP_CLOCK_INIT,
                     ar->fw_features)) {
                status = ath10k_bmi_write32(ar, hi_skip_clock_init, 1);
                if (status) {
                        ath10k_err(ar, "could not write to skip_clock_init: %d\n",
                                   status);
                        goto err;
                }
        }

        status = ath10k_download_fw(ar, mode);
        if (status)
                goto err;

        status = ath10k_init_uart(ar);
        if (status)
                goto err;

        ar->htc.htc_ops.target_send_suspend_complete =
                ath10k_send_suspend_complete;

        status = ath10k_htc_init(ar);
        if (status) {
                ath10k_err(ar, "could not init HTC (%d)\n", status);
                goto err;
        }

        status = ath10k_bmi_done(ar);
        if (status)
                goto err;

        status = ath10k_wmi_attach(ar);
        if (status) {
                ath10k_err(ar, "WMI attach failed: %d\n", status);
                goto err;
        }

        status = ath10k_htt_init(ar);
        if (status) {
                ath10k_err(ar, "failed to init htt: %d\n", status);
                goto err_wmi_detach;
        }

        status = ath10k_htt_tx_alloc(&ar->htt);
        if (status) {
                ath10k_err(ar, "failed to alloc htt tx: %d\n", status);
                goto err_wmi_detach;
        }

        status = ath10k_htt_rx_alloc(&ar->htt);
        if (status) {
                ath10k_err(ar, "failed to alloc htt rx: %d\n", status);
                goto err_htt_tx_detach;
        }

        status = ath10k_hif_start(ar);
        if (status) {
                ath10k_err(ar, "could not start HIF: %d\n", status);
                goto err_htt_rx_detach;
        }

        status = ath10k_htc_wait_target(&ar->htc);
        if (status) {
                ath10k_err(ar, "failed to connect to HTC: %d\n", status);
                goto err_hif_stop;
        }

        if (mode == ATH10K_FIRMWARE_MODE_NORMAL) {
                status = ath10k_htt_connect(&ar->htt);
                if (status) {
                        ath10k_err(ar, "failed to connect htt (%d)\n", status);
                        goto err_hif_stop;
                }
        }

        status = ath10k_wmi_connect(ar);
        if (status) {
                ath10k_err(ar, "could not connect wmi: %d\n", status);
                goto err_hif_stop;
        }

        status = ath10k_htc_start(&ar->htc);
        if (status) {
                ath10k_err(ar, "failed to start htc: %d\n", status);
                goto err_hif_stop;
        }

        if (mode == ATH10K_FIRMWARE_MODE_NORMAL) {
                status = ath10k_wmi_wait_for_service_ready(ar);
                if (status) {
                        ath10k_warn(ar, "wmi service ready event not received");
                        goto err_hif_stop;
                }
        }

        ath10k_dbg(ar, ATH10K_DBG_BOOT, "firmware %s booted\n",
                   ar->hw->wiphy->fw_version);

        status = ath10k_wmi_cmd_init(ar);
        if (status) {
                ath10k_err(ar, "could not send WMI init command (%d)\n",
                           status);
                goto err_hif_stop;
        }

        status = ath10k_wmi_wait_for_unified_ready(ar);
        if (status) {
                ath10k_err(ar, "wmi unified ready event not received\n");
                goto err_hif_stop;
        }

        /* If firmware indicates Full Rx Reorder support it must be used in a
         * slightly different manner. Let HTT code know.
         */
        ar->htt.rx_ring.in_ord_rx = !!(test_bit(WMI_SERVICE_RX_FULL_REORDER,
                                                ar->wmi.svc_map));

        status = ath10k_htt_rx_ring_refill(ar);
        if (status) {
                ath10k_err(ar, "failed to refill htt rx ring: %d\n", status);
                goto err_hif_stop;
        }

        /* we don't care about HTT in UTF mode */
        if (mode == ATH10K_FIRMWARE_MODE_NORMAL) {
                status = ath10k_htt_setup(&ar->htt);
                if (status) {
                        ath10k_err(ar, "failed to setup htt: %d\n", status);
                        goto err_hif_stop;
                }
        }

        status = ath10k_debug_start(ar);
        if (status)
                goto err_hif_stop;

        ar->free_vdev_map = (1LL << ar->max_num_vdevs) - 1;

        INIT_LIST_HEAD(&ar->arvifs);

        return 0;

err_hif_stop:
        ath10k_hif_stop(ar);
err_htt_rx_detach:
        ath10k_htt_rx_free(&ar->htt);
err_htt_tx_detach:
        ath10k_htt_tx_free(&ar->htt);
err_wmi_detach:
        ath10k_wmi_detach(ar);
err:
        return status;
}
EXPORT_SYMBOL(ath10k_core_start);
次にath10k_hif_startをgrepした(最初*.cで検索したらヒットしないので*.hで検索したらヒットした)。hif.hにインライン定義されている様子なのでviで開く。
$ grep "ath10k_hif_start" *.h
hif.h:static inline int ath10k_hif_start(struct ath10k *ar)
$ vi hif.h
ath10k_hif_startの定義箇所を抜き出した。startが呼ばれてる。
static inline int ath10k_hif_start(struct ath10k *ar)
{
        return ar->hif.ops->start(ar);
}
startでgrep。たくさん出てきたがpci.cath10k_pci_hif_startがヒットだろう。
$ grep "start" *.c
(省略)
pci.c:  .start                  = ath10k_pci_hif_start,
(省略)
ath10k_pci_hif_startを抜き出した。ath10k_pci_rx_postが呼ばれてる。
static int ath10k_pci_hif_start(struct ath10k *ar)
{
        struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);

        ath10k_dbg(ar, ATH10K_DBG_BOOT, "boot hif start\n");

        ath10k_pci_irq_enable(ar);
        ath10k_pci_rx_post(ar);

        pcie_capability_write_word(ar_pci->pdev, PCI_EXP_LNKCTL,
                                   ar_pci->link_ctl);

        return 0;
}
ath10k_pci_rx_postからath10k_pci_rx_post_pipeが呼ばれてる。
static void ath10k_pci_rx_post(struct ath10k *ar)
{
        struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);
        int i;

        for (i = 0; i < CE_COUNT; i++)
                ath10k_pci_rx_post_pipe(&ar_pci->pipe_info[i]);
}
ath10k_pci_rx_post_pipeから__ath10k_pci_rx_post_bufが呼ばれてる。
static void ath10k_pci_rx_post_pipe(struct ath10k_pci_pipe *pipe)
{
        struct ath10k *ar = pipe->hif_ce_state;
        struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);
        struct ath10k_ce_pipe *ce_pipe = pipe->ce_hdl;
        int ret, num;

        if (pipe->buf_sz == 0)
                return;

        if (!ce_pipe->dest_ring)
                return;

        spin_lock_bh(&ar_pci->ce_lock);
        num = __ath10k_ce_rx_num_free_bufs(ce_pipe);
        spin_unlock_bh(&ar_pci->ce_lock);
        while (num--) {
                ret = __ath10k_pci_rx_post_buf(pipe);
                if (ret) {
                        if (ret == -ENOSPC)
                                break;
                        ath10k_warn(ar, "failed to post pci rx buf: %d\n", ret);
                        mod_timer(&ar_pci->rx_post_retry, jiffies +
                                  ATH10K_PCI_RX_POST_RETRY_MS);
                        break;
                }
        }
}
__ath10k_pci_rx_post_bufではdev_alloc_skbでskb(ソケットバッファ)を作り、dma_map_singleでDMA領域を獲得(参考:Linuxネットワークドライバの開発)して、__ath10k_ce_rx_post_bufを呼び、dma_unmap_singleでDMA領域を解放してる。
tatic int __ath10k_pci_rx_post_buf(struct ath10k_pci_pipe *pipe)
{
        struct ath10k *ar = pipe->hif_ce_state;
        struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);
        struct ath10k_ce_pipe *ce_pipe = pipe->ce_hdl;
        struct sk_buff *skb;
        dma_addr_t paddr;
        int ret;

        skb = dev_alloc_skb(pipe->buf_sz);
        if (!skb)
                return -ENOMEM;

        WARN_ONCE((unsigned long)skb->data & 3, "unaligned skb");

        paddr = dma_map_single(ar->dev, skb->data,
                               skb->len + skb_tailroom(skb),
                               DMA_FROM_DEVICE);
        if (unlikely(dma_mapping_error(ar->dev, paddr))) {
                ath10k_warn(ar, "failed to dma map pci rx buf\n");
                dev_kfree_skb_any(skb);
                return -EIO;
        }

        ATH10K_SKB_RXCB(skb)->paddr = paddr;

        spin_lock_bh(&ar_pci->ce_lock);
        ret = __ath10k_ce_rx_post_buf(ce_pipe, skb, paddr);
        spin_unlock_bh(&ar_pci->ce_lock);
        if (ret) {
                dma_unmap_single(ar->dev, paddr, skb->len + skb_tailroom(skb),
                                 DMA_FROM_DEVICE);
                dev_kfree_skb_any(skb);
                return ret;
        }

        return 0;
}
__ath10k_ce_rx_post_bufをgrepした。ce.cがヒットしたのでviで開く。
$ grep "__ath10k_ce_rx_post_buf" *.c
ce.c:int __ath10k_ce_rx_post_buf(struct ath10k_ce_pipe *pipe, void *ctx, u32 paddr)
ce.c:   ret = __ath10k_ce_rx_post_buf(pipe, ctx, paddr);
pci.c:  ret = __ath10k_ce_rx_post_buf(ce_pipe, skb, paddr);
pci.c:          ret = __ath10k_ce_rx_post_buf(ce_diag, NULL, ce_data);
pci.c:          ret = __ath10k_ce_rx_post_buf(ce_diag, NULL, address);
$ vi ce.c
__ath10k_ce_rx_post_bufを抜き出す。__ath10k_ce_rx_post_bufからath10k_ce_dest_ring_write_index_setが呼ばれてる。
int __ath10k_ce_rx_post_buf(struct ath10k_ce_pipe *pipe, void *ctx, u32 paddr)
{
        struct ath10k *ar = pipe->ar;
        struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);
        struct ath10k_ce_ring *dest_ring = pipe->dest_ring;
        unsigned int nentries_mask = dest_ring->nentries_mask;
        unsigned int write_index = dest_ring->write_index;
        unsigned int sw_index = dest_ring->sw_index;
        struct ce_desc *base = dest_ring->base_addr_owner_space;
        struct ce_desc *desc = CE_DEST_RING_TO_DESC(base, write_index);
        u32 ctrl_addr = pipe->ctrl_addr;

        lockdep_assert_held(&ar_pci->ce_lock);

        if (CE_RING_DELTA(nentries_mask, write_index, sw_index - 1) == 0)
                return -ENOSPC;

        desc->addr = __cpu_to_le32(paddr);
        desc->nbytes = 0;

        dest_ring->per_transfer_context[write_index] = ctx;
        write_index = CE_RING_IDX_INCR(nentries_mask, write_index);
        ath10k_ce_dest_ring_write_index_set(ar, ctrl_addr, write_index);
        dest_ring->write_index = write_index;

        return 0;
}
ath10k_ce_dest_ring_write_index_setからath10k_pci_write32が呼ばれてる。
static inline void ath10k_ce_dest_ring_write_index_set(struct ath10k *ar,
                                                       u32 ce_ctrl_addr,
                                                       unsigned int n)
{
        ath10k_pci_write32(ar, ce_ctrl_addr + DST_WR_INDEX_ADDRESS, n);
}
ath10k_pci_write32をgrepした。たくさんヒットするがpci.cに定義されてるようだ。pci.cをviで開く。
$ grep "ath10k_pci_write32" *.c
(省略)
pci.c:void ath10k_pci_write32(struct ath10k *ar, u32 offset, u32 value)
(省略)
$ vi pci.c
ath10k_pci_write32ではath10k_pci_wakeでPCI起床しiowrite32を実行しath10k_pci_sleepでPCI休眠させる。ほぼここが末端だろう。
void ath10k_pci_write32(struct ath10k *ar, u32 offset, u32 value)
{
        struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);
        int ret;

        if (unlikely(offset + sizeof(value) > ar_pci->mem_len)) {
                ath10k_warn(ar, "refusing to write mmio out of bounds at 0x%08x - 0x%08zx (max 0x%08zx)\n",
                            offset, offset + sizeof(value), ar_pci->mem_len);
                return;
        }

        ret = ath10k_pci_wake(ar);
        if (ret) {
                ath10k_warn(ar, "failed to wake target for write32 of 0x%08x at 0x%08x: %d\n",
                            value, offset, ret);
                return;
        }

        iowrite32(value, ar_pci->mem + offset);
        ath10k_pci_sleep(ar);
}
さて、いろいろ見てみた結果、PCIe経由で無線チップにデータを書き込みしたが、チップから応答がなくて止まっちゃったみたいな感じ?

ますます迷宮入りした感じだが、次回も継続して調べていこう。

続く
IMG_20180105_125253





スポンサードリンク