RaceHound は、Effective Data-Race Detection for the Kernel (OSDI'10) に着想を得た、 Linux カーネルのロックのバグを見つけるツールです。以下は、RaceHound のチュートリアル https://github.com/euspectre/kedr/wiki/RaceHound_Tutorial の、２０１７年７月時点の、kanda.motohiro@gmail.com による抄訳です。
KernelStrider と RaceHound を使って、 e1000 ネットワークドライバ (Intel), それは例えば、仮想マシン環境で一般的です、を解析しましょう。
KernelStrider の基本的操作や、前提は、他のチュートリアルでカバーされていますので、読者はそれをご存知であることを前提とします。
RaceHound をビルドし、インストールする
まず、 GitHub にあるリポジトリをクローンして、ソースを得ます。
$ git clone https://github.com/winnukem/racehound
ビルド用のディレクトリを作って、そこに行きます。
$ mkdir build
$ cd build
プロジェクトを cmake で設定して、ビルドします。
$ cmake path-to-racehound-sources
訳注。Fedora では、gcc-c++, elfutils-devel, libdwarf-devel などが必要です。cmake が警告します。ma_lines をビルドしないなら、GCC plugin は不要です。よくわからんから、入れなかった。
$ make
ツールを、デフォルトの場所にインストールします (root にて)。
# make install
e1000 を解析する
訳注。この節は、KernelStrider の使い方なので、省略。気が向いたら、訳します。
以下の競合があやしいとわかったとします。
競合は以下のコード断片の間にあります (include/linux/dynamic_queue_limits.h)。
/*
* Record number of objects queued. Assumes that caller has already checked
* availability in the queue with dql_avail.
*/
static inline void dql_queued(struct dql *dql, unsigned int count)
{
BUG_ON(count > DQL_MAX_OBJECT);
dql->num_queued += count;
dql->last_obj_cnt = count;
}
/* Returns how many objects can be queued, < 0 indicates over limit. */
static inline int dql_avail(const struct dql *dql)
{
return dql->adj_limit - dql->num_queued;
}
dql->num_queued へのアクセスは同期されません。この競合が深刻なものかは、 e1000 開発者に聞かないとわかりません。問題ないかもしれませんし、そうでないかも。
さてここで、RaceHound を使って、特定の使用シナリオでこの競合が実際に起こるかをチェックしましょう。
前記の報告の最後のところの、"Race verifier data" を見て下さい。.text+0x1ef6 と .text+0x3598 は、競合する命令を特定する助けになります。最初のは、正確に指定されます。２つめのは、競合する命令であるか、その少し前の命令です（ThreadSanitizer はこのようにはたらくためです）。
RaceHound を最初の、正確に指定された命令をモニタするようにポイントする方が簡単です。
まず、私達は、.text+0x1ef6 を、RaceHound がサポートする形式に変換しなくてはいけません。カーネル内の ELF セクションを直接扱うのは難しいのです。ロードされたコードの領域（モジュールの初期化の間、使われるものは、"init" で、他の全てのコードは、"core"）の方が、使いやすいです。RaceHound が提供する、lines2insns ツールは、そのような変換の助けとなります。なお他のことにも使えます。
$ echo 'e1000:.text+0x1ef6' | lines2insns --section-to-area <path_to_e1000.ko>
e1000:core+0x1ef6
アドレスが、 .text セクションにあるなら、通常は .text を .core に置換するだけで十分です。ただ、lines2insns を使うほうが、安全です。
さて、RaceHound をロードします。
# insmod /usr/local/lib/modules/$(uname -r)/misc/racehound.ko
モニタする命令を指定します。
# echo 'e1000:core+0x1ef6' > /sys/kernel/debug/racehound/breakpoints
e1000 を再びロードします。
# modprobe e1000
RaceHound はこれで、 e1000 の指定された命令にソフトウェアブレークポイントを設定しました。もしそれが発火したら、RaceHound はその命令がアクセスしようとしているメモリアドレスを調べます。このツールは次に、ハードウェアブレークポイントを短い時間だけ（デフォルトで、５ジフィーズ）使って、そのメモリアドレスへのアクセスをモニタします。その後、元の命令が通常通り、実行されます。
なので、どれか他のスレッドがそのメモリをそれまでにアクセスしたら、ハードウェアブレークポイントが発火し、RaceHound はシステムログに競合を報告します。
訳注。ようするに、これが全て。強調は、訳者による。
さて、KernelStrider で行なったと同様に、e1000 に仕事をさせましょう。ブラウザで、speedof.me テストを走らせるなど。その間、システムログ('dmesg')に出力されるメッセージを見ましょう。
以下のようなメッセージが出るかもしれません（読みやすいように、改行を入れています）。
[22031.185652] [rh] Detected a data race on the memory block at f0fa4180
between the instruction at e1000:core+0x1ef6 (comm: "DNS Resolver #1")
and the instruction right before e1000_clean+0x13e/0x860 [e1000] (comm: "swapper/0").
[22046.985031] [rh] Detected a data race on the memory block at f0fa4180
between the instruction at e1000:core+0x1ef6 (comm: "DNS Resolver #1")
and the instruction right before dql_completed+0xb/0x180 (comm: "swapper/0").
ご覧のとおり、RaceHound が e1000 をモニタしている間に、同じデータへの少なくても二つの競合が起きました。なお、２つめの競合(e1000_xmit_frame VS dql_completed) は、実際には、 e1000 とカーネル自身の間のもので、e1000 の二つのコード断片の間のものではありません。
e1000 のディスアセンブリから、 e1000_clean+0x13e の前にある命令は、 e1000_clean+0x138 (.text+0x3598)であることがわかります。
ここで、binutils の addr2line、elfutils の eu-addr2line あるいは、GDB などのツールを使って、対応するソースコードを見つけることができます。
$ addr2line -e e1000.ko.debug -i -f -s -j .text 0x3598
netdev_tx_completed_queue
netdevice.h:2031
netdev_completed_queue
netdevice.h:2042
e1000_clean_tx_irq
e1000_main.c:3881
e1000_clean
e1000_main.c:3812
これは、以前、ThreadSanitizer が報告したのと同じ位置です。なので、この競合は本当に起きるのです。
２つめの競合で、競合する命令に対応するソースコードを見つけましょう。カーネルの dql_completed() ソースコードから既に明らかかもしれませんが、きちんとやってみましょう。このカーネルの、デバッグ情報を持った vmlinux は、/boot/vmlinux だと仮定します。
dql_completed の先頭アドレスは、 /proc/kallsyms (root にて)でわかります。
# cat /proc/kallsyms | grep dql_completed
c0427750 T dql_completed
c088fd4c r __ksymtab_dql_completed
c089b07c r __kcrctab_dql_completed
c08ad647 r __kstrtab_dql_completed
アドレスは、0xc0427750 です。
dql_completed+0xb の前にある命令は、バイトを dql_completed+0xa (0xc042775a) に持ちます。addr2line を使ってソースコードを得ましょう。
$ addr2line -e /boot/vmlinux-3.10.29-nrj-desktop-84rosa -i -f 0xc042775a
dql_completed
<...path on build system...>/lib/dynamic_queue_limits.c:23
コードを見ましょう。
17 void dql_completed(struct dql *dql, unsigned int count)
18 {
19 unsigned int inprogress, prev_inprogress, limit;
20 unsigned int ovlimit, completed, num_queued;
21 bool all_prev_completed;
22
23 num_queued = ACCESS_ONCE(dql->num_queued);
<...>
その通り。ここでの、dql->num_queued のリードは、前記、dql_queued() でのそれの加算と競合します。
最後に、 RaceHound をアンロードできます。e1000 をアンロードする必要はありません。
# rmmod race_hound
以上