Systemtapを使ってKernelのWarningメッセージを止めた(かったがダメだった)
サマリ
- オンボードのUSB3.0コントローラとUSB ICカードリーダの相性が悪いのか、使っているとWarningが出続けてつらい
- Systemtapを使って抑止しようとしたが、一部止めきれず。何が悪いのかは不明。
- 試したスクリプトは以下。
はじめに
うちの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?
前者は、ソースコードをみた感じだと、前者はデータ転送に成功しているけど、 期待したよりも転送長が長くないときに出るもののようだ。
// drivers/usb/host/xhci-ring.c 2300 static int handle_tx_event(struct xhci_hcd *xhci, 2301 struct xhci_transfer_event *event) <snipped...> 2373 switch (trb_comp_code) { 2374 /* Skip codes that require special handling depending on 2375 * transfer type 2376 */ 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じゃないのがダメとか、そういう感じなんだろうか。
// drivers/usb/host/xhci-ring.c 2477 if (list_empty(&ep_ring->td_list)) { 2478 /* 2479 * A stopped endpoint may generate an extra completion 2480 * event if the device was suspended. Don't print 2481 * warnings. 2482 */ 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"
Systemtapとは何か
具体的にはここ。 ざっくり言うと、動作中のKernelやユーザプロセスに対し、動的に情報を取ったりメモリを書き換えたりできるツール*4。
Systemtapのインストール
今回はKernelをいじるので、Systemtapバイナリに加えてKernelのデバッグ情報をインストールする。 全部まとめてここに書いてあることに従えばよい。
ソースコードの取得
Systemtapで変数を書き換える行を特定するためにソースコードを取得する必要がある。 ソースコードもaptで取得できる。
$ sudo vim /etc/apt/sources.list # deb-srcから始まる行のコメントを外す $ sudo apt update $ sudo apt source linux-image-$(uname -r) # カレントディレクトリにソースコードをダウンロードする
書き換え箇所の特定
needs XHCI_TRUST_TX_LENGTH quirk?に関しては、以下の2ステップ。
- 2380行目で
xhci->quirksにXHCI_TRUST_TX_LENGTHbitを立てる - 2477行目でtrb_comp_codeをCOMP_SUCCESSに戻す
Systemtapは、tapした行が実行される前に効果を発揮するようなので、 2381行目で変数を書き換えても期待した結果が得られない。
// drivers/usb/host/xhci-ring.c(再掲) 2300 static int handle_tx_event(struct xhci_hcd *xhci, 2301 struct xhci_transfer_event *event) <snipped...> 2373 switch (trb_comp_code) { 2374 /* Skip codes that require special handling depending on 2375 * transfer type 2376 */ 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 /* This TRB should be in the TD at the head of this ring's 2475 * TD list. 2476 */ 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 /* This TRB should be in the TD at the head of this ring's 2475 * TD list. 2476 */ 2477 if (list_empty(&ep_ring->td_list)) { 2478 /* 2479 * A stopped endpoint may generate an extra completion 2480 * event if the device was suspended. Don't print 2481 * warnings. 2482 */ 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スクリプト
上記の変更をSystemtapスクリプトにすると、こうなる。
kernel.statement(<PATH>)で、ソースコードの位置を指定する。<PATH>のフォーマットは関数名@ファイルへのパス(ビルドしたときのルートディレクトリからの相対パスでよい)。- $xxxxでKernel内の変数アクセス。構造体メンバへのアクセスは
->を使う。 - グローバル変数は
globalをつけて宣言すると使える
このスクリプトを-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 /* This TRB should be in the TD at the head of this ring's 2475 * TD list. 2476 */ 2477 if (list_empty(&ep_ring->td_list)) { 2478 /* 2479 * A stopped endpoint may generate an extra completion 2480 * event if the device was suspended. Don't print 2481 * warnings. 2482 */ 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がおかしいようにも思うし、
自分の理解が間違っているのではという感もあり、よくわからなくなった。
