ハードウェアのタイムスタンプを使用してネットワークの待ち時間を測定する方法

2023年10月30日月曜日

【この記事を書いた人】
Pierre Louis Aublin

I'm a researcher at IIJ Research Laboratory, working on security and fault-tolerance of distributed systems to making the Internet a safe place for everyone.

「ハードウェアのタイムスタンプを使用してネットワークの待ち時間を測定する方法」のイメージ

CONTENTS

今回は、IIJの技術研究所にインターンシップとしてドイツから来日していたフォーゲルアーネさんの研究を紹介します。彼は博士号候補者で一緒に働いていました。研究内容は、ネットワークカードのハードウェアタイムスタンプについてです。それではご覧ください。
（以下フォーゲルさんの記事）

この投稿では、ハードウェアのタイムスタンプを使用して、単純なpingコマンドよりもきめ細かくネットワークの待ち時間を測定する方法を探ります。

動機

2つのノード間のネットワークレイテンシを調べたい場合どうすればよいでしょうか？

シンプルな方法はpingを使うことでしょう：

$ ping node0
PING node0-link-1 (10.10.1.1) 56(84) bytes of data.
64 bytes from node0-link-1 (10.10.1.1): icmp_seq=1 ttl=64 time=0.326 ms
64 bytes from node0-link-1 (10.10.1.1): icmp_seq=2 ttl=64 time=0.315 ms
64 bytes from node0-link-1 (10.10.1.1): icmp_seq=3 ttl=64 time=0.318 ms
64 bytes from node0-link-1 (10.10.1.1): icmp_seq=4 ttl=64 time=0.316 ms

概念的には、pingから出力される数字について考えると、このようなイメージになります：

2台のマシンでping pongメッセージを交換することで、パケットが2台のマシン間のネットワークを通過するのにかかる時間を測定します。

しかし、この単純な概念モデルでは捉えられないようなことが、2台のマシン間で送信されるパケットにはたくさん起こっています。

TNICはパケットを受信し、ダイレクトメモリアクセス（DMA）を介してメインメモリにコピーし、カーネルがそれを処理した上で初めてユーザ空間のアプリケーションに届けられる。

しかし、これらの追加レイテンシの内訳はどうなっているでしょうか？パケットはカーネル、ネットワークインターフェース（NIC）、実際のネットワークでどれだけの時間を費やしているでしょうか？

問題：pingによって測定されたネットワークレイテンシには、NICとカーネルで費やされた時間も含まれています。
ですが、例えばパフォーマンスが重要なデータセンター・サービス等について最適化や性能の調査を行う時に、これらのレイテンシ特性、つまり、パケットがネットワーク内でどれだけの時間を費やし、NICとカーネルの間でどれだけの時間を費やすのかをより明確に把握したい場合があります。

2つのホスト間のレイテンシを最適化するために、どこにエネルギーを使うべきか？例えば、カーネルのオプションを調べるべきか、NICが遅いのか、それともこのレイテンシはネットワークによるものなのか等のヒントが得られるかもしれません。

pingだけではこれらについての十分な情報を得ることができません。
なので、今回は、別のツールであるハードウェア・タイムスタンプを使って、これらの情報を得る方法を模索します。

ハードウェアタイムスタンプ

NICのハードウェアタイムスタンプ機能を使うと、NICがパケットを受信したときに、そのパケットにタイムスタンプを付与するようにすることができます。
このタイムスタンプを使って、パケットがネットワーク上にいた時間や、ユーザアプリケーションがそれを受信するまでにマシン上で処理された時間を知ることができます。

また、カーネルもパケットのタイムスタンプ機能を実装しており、この機能を使うと、カーネルも、NICからパケットを受け取ったタイミングで、そのパケットに対してタイムスタンプを付与します。

これらの数字を使って、パケットがNICからカーネルに、そしてカーネルからユーザ空間にかかった時間を得ることができます。

この記事の残りの部分では、使用するインターフェイスをeth0と仮定する。

手元のNICがハードウェアタイムスタンプをサポートしているか確認する

すべてのNICがハードウェアタイムスタンプをサポートしているわけではありません。

NICがハードウェアタイムスタンプをサポートしているかどうかは、ethtoolを使って確認できます：

$ ethtool -T eth0
Time stamping parameters for eth0:
Capabilities:
	hardware-transmit
	hardware-receive
	hardware-raw-clock
PTP Hardware Clock: 2
Hardware Transmit Timestamp Modes:
	off
	on
Hardware Receive Filter Modes:
	none
	all

ethtool の出力で、上のようにhardware-receiveが含まれていれば、対象のNICはハードウェアタイムスタンプ機能をサポートしています。

Mellanox ConnectX-5 25Gb NICでハードウェアタイムスタンプを使用することに成功しました。

NICとカーネルの間で時間を同期する

NICとカーネルは異なるタイムオフセットを使用します。
そのため、NICから受信したタイムスタンプはアプリケーションにとっては役に立たない。
このため、結果を解釈する前に、NICとカーネル間の時刻を同期させる必要があるのです。

同期には、Precision Time Protocol (PTP)があります。

これは、ネットワーク内の時刻を同期させるための標準化されたプロトコルで、今回はこのPTPプロトコルを使ってNICとカーネル間の時刻を同期させてみます。

Phc2sys を使った時刻同期

時刻同期にはphc2sysというツールが利用できます。

phc2sysはLinux PTP Projectが配布しているツールで、Ubuntu16.04等を利用している場合は以下のようにして apt レポジトリからインストールし、実行できます。

$ sudo apt install linuxptp
$ sudo phc2sys -s eth0 -O 0 -m

上記のコマンドを実行すると、NICとカーネルの間で時刻が同期されます。

出力例：

phc2sys[259.181]: CLOCK_REALTIME phc offset 368000329 s0 freq     -37 delay    761
phc2sys[260.182]: CLOCK_REALTIME phc offset 368004374 s1 freq   +4007 delay    761
phc2sys[261.182]: CLOCK_REALTIME phc offset      -990 s2 freq   +3017 delay    761
phc2sys[262.182]: CLOCK_REALTIME phc offset      -995 s2 freq   +2715 delay    762
phc2sys[263.182]: CLOCK_REALTIME phc offset      -706 s2 freq   +2705 delay    761
phc2sys[264.182]: CLOCK_REALTIME phc offset      -383 s2 freq   +2817 delay    761
phc2sys[265.183]: CLOCK_REALTIME phc offset       -83 s2 freq   +2702 delay    761
phc2sys[266.183]: CLOCK_REALTIME phc offset        10 s2 freq   +2623 delay    761

注意：phc2sysは、時刻同期のために、このタイムスタンプの実験を行っている間は常に実行されている必要があります。

ハードウェア・タイムスタンプをhwstamp_ctlで有効にする

ハードウェア・タイムスタンプはハードウェアで可能かもしれないが、カーネルで有効にする必要がある。

ハードウェア・タイムスタンプをシステム上で有効にするには、先ほどのlinuxptpに含まれるhwstamp_ctlというツールを使います。

apt get でlinuxptpをインストールした場合は以下のコマンドで行えます。

$ sudo hwstamp_ctl -i eth0 -t 1 -r 1

出力例：

$ sudo hwstamp_ctl -i eth0 -t 1 -r 1
current settings:
tx_type 0
rx_filter 0
new settings:
tx_type 1
rx_filter 1

アプリケーションでタイムスタンプを取得する

先ほど有効にしたハードウェアとカーネルによるパケットのタイムスタンプを、アプリケーションから取得する方法をみていきます。

アプリケーションが特定のソケットファイルデスクリプタに対してタイムスタンプの付与するように設定するためには、以下のようにsetsockoptシステムコールを利用します：

int enable = SOF_TIMESTAMPING_RX_HARDWARE | SOF_TIMESTAMPING_RAW_HARDWARE |
             SOF_TIMESTAMPING_SYS_HARDWARE | SOF_TIMESTAMPING_SOFTWARE;
int res = setsockopt(sock, SOL_SOCKET, SO_TIMESTAMPING, &enable, sizeof(int));

パケットの受信に併せてタイムスタンプ情報をカーネルから受け取るためには、以下のプログラムのように、データの受信にrecvmsgシステムコールを利用します。
ポイントは、msghdr 構造体のmsg_control フィールドに、「制御メッセージ」を保存可能なように、ユーザ空間のバッファへのポインタ（プログラム中 control）と、msg_controllen フィールドにそのバッファのサイズを指定することです。

struct msghdr msg;
struct iovec iov;
struct sockaddr_in host_address;
char buffer[2048];
char control[1024];
int got;

/* recvmsg header structure */
make_address(0, &host_address);
iov.iov_base = buffer;
iov.iov_len = 2048;
msg.msg_iov = &iov;
msg.msg_iovlen = 1;
msg.msg_name = &host_address;
msg.msg_namelen = sizeof(struct sockaddr_in);
msg.msg_control = control;
msg.msg_controllen = 1024;

/* block for message */
got = recvmsg(sock, &msg, 0);
if( !got && errno == EAGAIN )
    return 0;

handle_time(&msg, cfg);

上記のプログラムで、recvmsgシステムコールを実行すると、受信データが（あれば） msghdr 構造体に紐づけられた iov を通して指定されたバッファに書き込まれます。また、その受信データについてのタイムスタンプ情報が、同じく msghdr 構造体に紐づけられた制御メッセージ用のバッファに書き込まれます。
以下のようにすると、この制御メッセージからタイムスタンプ情報を取り出すことができます（上記プログラムにおける handle_time の実装）。CMSG_FIRSTHDRで最初の制御メッセージへのポインタを取得し、CMSG_NXTHDRを利用することで、以降の制御メッセージを取得して処理できます。また、制御メッセージにはタイムスタンプ以外の情報が含まれる場合もあるので、メッセージのタイプ（cmsg_type）がSO_TIMESTAMPING のものだけについてタイムスタンプの取り出し処理を行っています。

// Extract the timestamp from the message
static void handle_time(struct msghdr* msg, struct configuration* cfg)
{
  struct timespec* ts = NULL;
  struct cmsghdr* cmsg;

  /*
   * The kernel stores control messages for each packet. E.g., on which interface
   * the packet was received on. Or, if as we configured it with the timestamps
   * from the NIC and the kernel.
  */
  for( cmsg = CMSG_FIRSTHDR(msg); cmsg; cmsg = CMSG_NXTHDR(msg,cmsg) ) {
    if( cmsg->cmsg_level != SOL_SOCKET )
      continue;

    switch( cmsg->cmsg_type ) {
    // We are looking for the SO_TIMESTAMPING control message.
    case SO_TIMESTAMPING:
      ts = (struct timespec*) CMSG_DATA(cmsg);
      break;
    default:
      /* Ignore other cmsg options */
      break;
    }
  }

  print_time(ts);
}

最後に、アプリケーション内部の現在時刻を取得することで（gettimeofdayを利用）、それをNICとカーネルのタイムスタンプと並べて比較することができます：

struct timeval time_user;
gettimeofday(&time_user, NULL);

// The timespec we extracted has three fields.
// ts[0] contains the kernels timestamp
// ts[1] unclear, was 0 in all our testing
// ts[2] contains the NIC timestamp
uint64_t nanoseconds_nic = ts[2].tv_sec * 1000000000 + ts[2].tv_nsec;
uint64_t nanoseconds_kernel = ts[0].tv_sec * 1000000000 + ts[0].tv_nsec;
uint64_t nanoseconds_user = time_user.tv_sec * 1000000000 + time_user.tv_usec * 1000;

詳細は以下のソースコードを参照ください：
https://github.com/ArneVogel/hw-timestamping

測定結果の例

以下のプロットは、上のプログラムを利用して測定を行った、パケットが NIC からユーザ空間アプリケーションに到達するまでのレイテンシの内訳を示しています：

NICとカーネルを経由してユーザ空間アプリケーションに到達するパケットのレイテンシの内訳を示すプロット

エンド・ツー・エンドのレイテンシを追加したプロット。

エンド・ツー・エンドの待ち時間を追加した、NICとカーネルを経由してユーザ空間アプリケーションに到達するパケットの待ち時間の内訳を示すプロット

エンド・ツー・エンドの内訳を見ると、パケットがカーネル/NICで多くの時間を費やしていることがわかります：

NICとカーネルを経由してユーザ空間アプリケーションに到達するパケットのレイテンシの内訳を示すプロット

(このプロットは、パケットの送信に、カーネルとNICでパケットを受信するのと同じ時間がかかると仮定しています)

実験の再現方法

以下に、https://github.com/ArneVogel/hw-timestampingに配置したサンプルプログラムを使用して、上記の実験を再現する方法を示します。

この実験ではnode0とnode1が同じスイッチに接続されていると仮定する。

ターミナル1では

$ # ssh to host0
$ sudo apt install linuxptp
$ sudo hwstamp_ctl -i eth0 -t 1 -r 1
$ sudo phc2sys -s eth0 -O 0 -m

これで、ハードウェアタイムスタンプが有効になり、node0で NICKernel の時刻が同期されます。

ターミナル 2 で `node0` のロギングエコーサーバを起動します：

$ # ssh to node0
$ git clone https://github.com/ArneVogel/hw-timestamping
$ cd hw-timestamping
$ make
$ make run

ターミナル 3 の node1でパケットジェネレータを起動する：

$ # ssh to node1
$ sudo apt install cargo
$ git clone https://github.com/ArneVogel/hw-timestamping
$ cd hw-timestamping/rust-packets
$ sudo cargo run --release eth0

実験が実行されるまで約20秒かかります。
その後、ターミナル2にlatency.txt、ターミナル3にend_to_end_latency.txtができます。

以下のコマンドでプロットを作成します。

# 得られた結果をローカルマシンの `hw-timestamping` を含むフォルダに Rsync 等でコピーします。
# ローカルのマシンにて、
$ git clone https://github.com/ArneVogel/hw-timestamping
$ cd hw-timestamping

# 得られた結果とは node0の`latency.txt` と node1の`end_to_end_latency.txt` のことです。
$ python3 summarize.py
$ python3 bar_plot.py

Pierre Louis Aublin

2023年10月30日月曜日

I'm a researcher at IIJ Research Laboratory, working on security and fault-tolerance of distributed systems to making the Internet a safe place for everyone.