サマリ
gist.github.com
はじめに
うちのICカードリーダ*1とルネサス製と思しきUSB3.0コントローラ
*2
の相性が悪く、使っていると以下のようなメッセージが2秒おきに出続ける。
xhci_hcd 0000:03:00.0: WARN Successful completion on short TX: needs XHCI_TRUST_TX_LENGTH quirk?
xhci_hcd 0000:03:00.0: WARN Event TRB for slot 1 ep 8 with no TDs queued?
前者は、ソースコードをみた感じだと、前者はデータ転送に成功しているけど、
期待したよりも転送長が長くないときに出るもののようだ。
2300 static int handle_tx_event(struct xhci_hcd *xhci,
2301 struct xhci_transfer_event *event)
<snipped...>
2373 switch (trb_comp_code) {
2374
2377 case COMP_SUCCESS:
2378 if (EVENT_TRB_LEN(le32_to_cpu(event->transfer_len)) == 0)
2379 break;
2380 if (xhci->quirks & XHCI_TRUST_TX_LENGTH)
2381 trb_comp_code = COMP_SHORT_TX;
2382 else
2383 xhci_warn_ratelimited(xhci,
2384 "WARN Successful completion on short TX: needs XHCI_TRUST_TX_LENGTH quirk?\n"); ★これ
後者はというと、2483行目と2484行目にひっかかっているらしい。
リストが空っぽなのにSTOPじゃないのがダメとか、そういう感じなんだろうか。
2477 if (list_empty(&ep_ring->td_list)) {
2478
2483 if (!(trb_comp_code == COMP_STOP ||
2484 trb_comp_code == COMP_STOP_INVAL)) {
2485 xhci_warn(xhci, "WARN Event TRB for slot %d ep %d with no TDs queued?\n",
2486 TRB_TO_SLOT_ID(le32_to_cpu(event->flags)),
2487 ep_index);
2488 xhci_dbg(xhci, "Event TRB with TRB type ID %u\n",
2489 (le32_to_cpu(event->flags) &
2490 TRB_TYPE_BITMASK)>>10);
2491 xhci_print_trb_offsets(xhci, (union xhci_trb *) event);
2492 }
出続けたから何だというわけでもないが、dmesgが埋め尽くされるのはなんとなく嫌なので*3、
これをKernelを改変せずに抑止したい。どうすればよいか？今回は、Systemtapを使ってみる。
実行環境
MOCHI /home/bisco% uname -r
4.4.0-78-generic
MOCHI /home/bisco% cat /etc/lsb-release
DISTRIB_ID=Ubuntu
DISTRIB_RELEASE=16.04
DISTRIB_CODENAME=xenial
DISTRIB_DESCRIPTION="Ubuntu 16.04.2 LTS"
具体的にはここ。
ざっくり言うと、動作中のKernelやユーザプロセスに対し、動的に情報を取ったりメモリを書き換えたりできるツール*4。
今回はKernelをいじるので、Systemtapバイナリに加えてKernelのデバッグ情報をインストールする。
全部まとめてここに書いてあることに従えばよい。
Systemtapで変数を書き換える行を特定するためにソースコードを取得する必要がある。
ソースコードもaptで取得できる。
$ sudo vim /etc/apt/sources.list
$ sudo apt update
$ sudo apt source linux-image-$(uname -r)
書き換え箇所の特定
needs XHCI_TRUST_TX_LENGTH quirk?に関しては、以下の2ステップ。
- 2380行目で
xhci->quirksにXHCI_TRUST_TX_LENGTH bitを立てる
- 2477行目でtrb_comp_codeをCOMP_SUCCESSに戻す
Systemtapは、tapした行が実行される前に効果を発揮するようなので、
2381行目で変数を書き換えても期待した結果が得られない。
2300 static int handle_tx_event(struct xhci_hcd *xhci,
2301 struct xhci_transfer_event *event)
<snipped...>
2373 switch (trb_comp_code) {
2374
2377 case COMP_SUCCESS:
2378 if (EVENT_TRB_LEN(le32_to_cpu(event->transfer_len)) == 0)
2379 break;
2380 if (xhci->quirks & XHCI_TRUST_TX_LENGTH) ★ここ
2381 trb_comp_code = COMP_SHORT_TX;
2382 else
2383 xhci_warn_ratelimited(xhci,
2384 "WARN Successful completion on short TX: needs XHCI_TRUST_TX_LENGTH quirk?\n");
<snipped...>
2463 default:
2464 if (xhci_is_vendor_info_code(xhci, trb_comp_code)) {
2465 status = 0;
2466 break;
2467 }
2468 xhci_warn(xhci, "ERROR Unknown event condition %u, HC probably busted\n",
2469 trb_comp_code);
2470 goto cleanup;
2471 }
2472
2473 do {
2474
2477 if (list_empty(&ep_ring->td_list)) { ★ここ
with no TDs queued?に関しては、以下の2ステップ。
- 2477行目の条件がTRUEなら、trb_comp_codeをCOMP_STOPに書き換える
- 2493行目でtrb_comp_codeを戻す
ここでは2483行目でtrb_comp_codeを書き換えたいんだけど、
2483行目からはtrb_comp_codeにアクセスできないので、しょうがなくこうする。
2473 do {
2474
2477 if (list_empty(&ep_ring->td_list)) {
2478
2483 if (!(trb_comp_code == COMP_STOP ||
2484 trb_comp_code == COMP_STOP_INVAL)) {
2485 xhci_warn(xhci, "WARN Event TRB for slot %d ep %d with no TDs queued?\n",
2486 TRB_TO_SLOT_ID(le32_to_cpu(event->flags)),
2487 ep_index);
2488 xhci_dbg(xhci, "Event TRB with TRB type ID %u\n",
2489 (le32_to_cpu(event->flags) &
2490 TRB_TYPE_BITMASK)>>10);
2491 xhci_print_trb_offsets(xhci, (union xhci_trb *) event);
2492 }
2493 if (ep->skip) {
2494 ep->skip = false;
2495 xhci_dbg(xhci, "td_list is empty while skip "
2496 "flag set. Clear skip flag.\n");
2497 }
ちなみに、アクセスできる/できない変数は、-Lオプションで調べることができる。
アクセスできる変数は$xxxxと表示されるんだけど、2483行目にはtrb_comp_codeがない。
$ stap -L 'kernel.statement("handle_tx_event@drivers/usb/host/xhci-ring.c:*")' | grep 248
kernel.statement("handle_tx_event@/build/linux-0XAgc4/linux-4.4.0/drivers/usb/host/xhci-ring.c:2483") $xhci:struct xhci_hcd* $event:struct xhci_transfer_event* $xdev:struct xhci_virt_device* $ep_ring:struct xhci_ring* $event_trb:union xhci_trb* $status:int $td_num:int $__func__:char const[] const
kernel.statement("handle_tx_event@/build/linux-0XAgc4/linux-4.4.0/drivers/usb/host/xhci-ring.c:2485") $xhci:struct xhci_hcd* $event:struct xhci_transfer_event* $xdev:struct xhci_virt_device* $ep_ring:struct xhci_ring* $event_trb:union xhci_trb* $status:int $trb_comp_code:u32 $td_num:int $__func__:char const[] const
kernel.statement("handle_tx_event@/build/linux-0XAgc4/linux-4.4.0/drivers/usb/host/xhci-ring.c:2488") $descriptor:struct _ddebug $xhci:struct xhci_hcd* $event:struct xhci_transfer_event* $xdev:struct xhci_virt_device* $ep_ring:struct xhci_ring* $status:int $__func__:char const[] const
上記の変更をSystemtapスクリプトにすると、こうなる。
kernel.statement(<PATH>) で、ソースコードの位置を指定する。<PATH>のフォーマットは関数名@ファイルへのパス(ビルドしたときのルートディレクトリからの相対パスでよい)。- $xxxxでKernel内の変数アクセス。構造体メンバへのアクセスは
->を使う。
- グローバル変数は
globalをつけて宣言すると使える
gist.github.com
このスクリプトを-gオプションを付けて実行する。
-gオプションを渡すと、guruモードと呼ばれている変数を書き換えられるモードにしてくれる。
$ sudo stap -gv usb.stp
結果
quirks?のほうは抑止できたけど、with no TDs queued?はなぜか抑止できなかった。うーん、原因がわからん。
その他
Systemtapスクリプトの実行をCtrl-C止めても、quirks?のメッセージが出なくなった。何か残ってるのか・・・？
[2017/05/22 23:11追記]
このコードに対して
2473 do {
2474
2477 if (list_empty(&ep_ring->td_list)) {
2478
2483 if (!(trb_comp_code == COMP_STOP ||
2484 trb_comp_code == COMP_STOP_INVAL)) {
2485 xhci_warn(xhci, "WARN Event TRB for slot %d ep %d with no TDs queued?\n",
2486 TRB_TO_SLOT_ID(le32_to_cpu(event->flags)),
2487 ep_index);
2488 xhci_dbg(xhci, "Event TRB with TRB type ID %u\n",
2489 (le32_to_cpu(event->flags) &
2490 TRB_TYPE_BITMASK)>>10);
2491 xhci_print_trb_offsets(xhci, (union xhci_trb *) event);
2492 }
このtap
probe begin {
printf("force stop warning short TX\n")
}
probe end {
printf("stop probe\n")
}
probe kernel.statement("handle_tx_event@drivers/usb/host/xhci-ring.c:2477") {
next_addr = @cast(&$ep_ring->td_list, "list_head", "kernel")->next
list_addr = &$ep_ring->td_list
if(next_addr == list_addr) {
$trb_comp_code = 26
printf(">> trb_comp_code = %d\n", $trb_comp_code)
}
}
probe kernel.statement("handle_tx_event@drivers/usb/host/xhci-ring.c:2485") {
printf("trb_comp_code = %d\n", $trb_comp_code)
}
結果がこれ
Pass 1: parsed user script and 110 library script(s) using 109624virt/43860res/6236shr/37692data kb, in 320usr/40sys/359real ms.
Pass 2: analyzed script: 4 probe(s), 4 function(s), 0 embed(s), 0 global(s) using 302812virt/236012res/7292shr/230880data kb, in 3640usr/130sys/3774real ms.
Pass 3: translated to C into "/tmp/stapdRn9iB/stap_072980ba0aa3ed0cb26e4f8ce5aa1922_3963_src.c" using 302812virt/236140res/7420shr/230880data kb, in 10usr/10sys/12real ms.
Pass 4: compiled C into "stap_072980ba0aa3ed0cb26e4f8ce5aa1922_3963.ko" in 3850usr/440sys/4690real ms.
Pass 5: starting run.
force stop warning short TX
>> trb_comp_code = 26
trb_comp_code = 26
>> trb_comp_code = 26
trb_comp_code = 26
>> trb_comp_code = 26
trb_comp_code = 26
>> trb_comp_code = 26
trb_comp_code = 26
COMP_STOP = 26という事実からすると、systemtapがおかしいようにも思うし、
自分の理解が間違っているのではという感もあり、よくわからなくなった。