Timestamping を使ってネットワークレイテンシを分析することで、ゲスト VM の Disk 性能低下問題を解決した

OpenStack の Compute Node を更新する際にゲスト VM の Disk 性能が低下する問題を、 Linux の Timestamping という機能を使ってネットワークレイテンシを分析することで解決できた事例をご紹介します。

本事例は fukabori.fm #127 でもご紹介しています。

はじめに
前提: 仮想サーバの構成
初期調査
- 仮想化レイヤの問題を切り分ける
- CPv2 と CPv3 の違いに着目する
CPv3 において RTT が高い問題を切り分ける
まとめ
お知らせ

はじめに

こんにちは。 SDPF クラウド・仮想サーバーチームの杉浦 (@Kumassy_) です。普段は OpenStack の開発・運用をしており、最近は仮想マシンの性能解析やトラブルシューティングなどに取り組んでいます。

仮想サーバーチームでは、 OpenStack の Nova, Cinder, Glance 等を活用し、仮想マシン (VM) と、それを動かすのに必要なディスクやイメージを管理できる機能を提供しています。 VM が稼働しているホストは Compute Node と呼ばれます。

仮想サーバーチームでは、 Compute Node に使用している物理サーバーや OS の更新のため、新しい世代の Compute Node である CPv3 を開発しています。

余談ですが、初代の Compute Node である CPv1 から 2 世代目の CPv2 に移行する苦労話は CODT 2021 でご紹介しています¹。

CPv3 の変更点は次の図の通りです。物理サーバーと OS、仮想マシンを動かすための qemu や libvirtd を更新する計画です。

Compute Node の設定を変更したり、ソフトウェアを入れ替えたりする際には、ゲスト VM の性能に問題が出ないか試験をする必要があります。そのため、複数のベンチマークツールを使用して、ゲスト VM の性能が基準値を満たしているかを確認しています。しかし、ベンチマークの結果、 CPv3 では前世代の CPv2 と比べて、ゲスト VM の Disk 性能が 33 - 50 % 程度になっていることがわかりました。ハードウェアが新しくなったのにもかかわらず、ゲスト VM の性能が大幅に低下してしまったのは問題です。

本記事では、この問題をどのように解決したのかをご紹介します。

前提: 仮想サーバの構成

仮想サーバのアーキテクチャは次の図のようになっています。

ゲスト VM のディスクは NFS Server 上のファイルとして保存されています。 Compute Node は NFS Server のストレージプールをマウントしており、 qemu はディスクのイメージファイルをブロックストレージとしてゲスト VM に見せています。

Compute Node のアップデート期間中は、 CPv2 と CPv3 は同じ NFS Server に接続されます。

初期調査

仮想化レイヤの問題を切り分ける

ゲスト VM の性能試験として、 Linux ゲストの Disk 性能試験には fio ² というベンチマークツールを利用しています。 CPv2 と CPv3 のそれぞれに VM をデプロイし、 VM の中で fio を動作させたところ、 CPv3 では bw 及び iops スコアが CPv2 と比べて 33 - 50 % 程度であることがわかりました。

CPv3 ではハードウェアではなく OS や qemu, KVM 等のバージョンも違い変更範囲が大きいので、何が影響しているかを絞り込む必要があります。そこで、まずはホストで fio を直接動かしてベンチマークのスコアが低下するか調べることにしました。次のコマンドのように、 NFS Server 上のファイルに対して I/O リクエストを発生させます。

sudo fio -filename=/path/to/nfs/storage/fio -direct=1 -rw=randread -rwmixread=30 -bs=4k -size=3G -numjobs=1 -runtime=180 -group_reporting -name=test

その結果、次のグラフのように、 CPv3 は CPv2 と比べて fio のスコアが明らかに悪いことがわかりました。グラフでは CPv2 のスコアを 1 として正規化しています。 CPv3 における fio のスコアは CPv2 の 0.51 倍くらいのスコアでした。

CPv2 と CPv3 の違いに着目する

仮想サーバの構成図で示したように、 CPv2 と CPv3 の Compute Node は同じ NFS Server に接続されているので、 NFS Server 側は問題なさそうです。よって、 NFS Client である Compute Node か途中のネットワークに問題がありそうです。

CPv2 と CPv3 の差分を調査してみると、 NFS Server とのネットワークレイテンシに違いが見つかりました。 CPv2 と CPv3 それぞれの Compute Node から NFS Server との間の RTT を ping コマンドで測定すると、次のようになりました。

CPv3 は CPv2 と比べて、 NFS Server との RTT が 0.1 ms くらい大きいようです。この RTT の違いはどれくらい fio のスコアに影響するでしょうか。それを確かめるために、 tc コマンドを使い CPv2 の NIC に対して意図的に遅延をつけることで、 fio のスコアがどれくらい低下するか調べました。

上記の図に示すように、 1 ms のレイテンシを追加すると fio の性能が 10 % 程度に、 100 us のレイテンシを追加すると fio の性能が 65 % くらいに低下することがわかりました。

これまでの調査の結果から、「 CPv3 では NFS Server へのネットワークレイテンシが高いことで、 NFS 上のファイルへの I/O 性能が低い」という仮説を立てて、以降の調査ではネットワークレイテンシが高くなってしまった理由を深堀りすることにしました。

CPv3 において RTT が高い問題を切り分ける

Timestamping

RTT が高い理由を分析するためには、全体のレイテンシを分解し、どの部分でどれだけ時間がかかっているか分析できるようにしたいです。この用途に使えるのが Timestamping³ です。

Timestamping とは、パケットが Linux システム内の特定のポイントを通過した時間を記録する機能で、パケットが Kernel に到着した、もしくは Kernel から出ていく時刻を調べることができます。さらに、 NIC が hardware timestamping をサポートしている場合、パケットが NIC に到着した、もしくは NIC から出ていく時刻を知ることができます。パケットにつけられたタイムスタンプを分析することで、パケットが Application, Kernel, NIC の各レイヤでどれくらい時間がかかったかを分析できます。 Timestamping を使ってネットワークレイテンシを分析する手法は How to measure network latency using hardware timestamps | IIJ Engineers Blog ⁴ で詳しく紹介されており、本記事でも IIJ Engineers Blog のプログラムを利用しています。

本手法を使って hardware timestamping を利用するには、 NIC が以下のように hardware-transmit, hardware-receive capablity と、 Hardware Receive Filter Modes: all をサポートしている必要があります。

$ sudo ethtool -T ens15f0
Time stamping parameters for ens15f0:
Capabilities:
    hardware-transmit
    software-transmit
    hardware-receive
    software-receive
    software-system-clock
    hardware-raw-clock
PTP Hardware Clock: 1
Hardware Transmit Timestamp Modes:
    off
    on
Hardware Receive Filter Modes:
    none
    all

Compute Node と NFS Server 間のネットワークレイテンシを分析できればよかったのですが、 NFS Server 上で任意のプログラムを動かすのは難しかったので、隣接する Compute Node 間のネットワークレイテンシを分析することにしました。

実験の構成図

実験環境は以下の図のようになります。

Rust 言語で書かれた packet generator から rx_timestamping.c もしくは tx_timestamping.c に向かってパケットが送られます。 rx_timestamping.c は packet generator からパケットを受信するたびに、パケットに紐づけられたタイムスタンプを取得して保存することで、 RX 方向のレイテンシを分析します。 tx_timestamping.c は packet generator からパケットを受信するたびに packet generator へパケットを echo back し、その際に得られたタイムスタンプを取得して保存することで、 TX 方向のレイテンシを分析します。

特にチューニングを加えない状態では、隣接 Compute Node 間の RTT は 0.35 ms くらいでした。

RX 方向のレイテンシを分析する

RX 方向のタイムスタンプを取得するコード rx_timestamping.c は、 IIJ Engineers Blog で紹介されているコード⁵ を元に、アドレスを書き換えたものを利用しました。

コードを動かす前に次の手順が必要です。

hwstamp_ctl を使って、 NIC の hardware timestamping を有効化する
カーネルと NIC は別のクロックを利用しているため、 phc2sys を使ってカーネルと NIC の時刻を同期し続ける

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

# 実験が終わるまで動かし続ける
receiver$ sudo phc2sys -s ens15f1 -O 0 -m
phc2sys[9050057.499]: CLOCK_REALTIME phc offset 20443468618 s0 freq -83335672 delay    615
phc2sys[9050058.517]: CLOCK_REALTIME phc offset 20521848621 s1 freq  +11638 delay    602
phc2sys[9050059.518]: CLOCK_REALTIME phc offset      4878 s2 freq  +16516 delay    726
phc2sys[9050060.518]: CLOCK_REALTIME phc offset        10 s2 freq  +13111 delay    652

準備ができたら、 rx_timestamping.c を動かします。

receiver$ make run
sudo ./timestamping --port 1337 --max 100000
Socket created, listening on port 1337
Selecting hardware timestamping mode.
enabled timestamping sockopt

最後に、 packet generator を動かして実験を開始します。

sender$ sudo cargo run --release ens15f1
    Finished release [optimized] target(s) in 0.06s
     Running `target/release/tranquil ens15f1`

実験で得られたタイムスタンプを可視化すると、次のグラフのようになります。

横方向は時間軸です。 packet generator は 100,000 パケットを rx_timestamping.c に向かって送信しますが、グラフでは最初と最後の10,000パケットを除いた 80,000 パケットを表示しています。縦方向はレイテンシの内訳を示します。各レイテンシの説明は次の表の通りです。

レイテンシ	取得元	説明
End to End	sender	パケットを `sendto` してから `recv_from` するまでの時間
NIC -> User	receiver	パケットが NIC に到着してから User 空間で `recvmsg` するまでの時間。 `gettimeofday() - SOF_TIMESTAMPING_RX_HARDWARE`
NIC -> Kernel	receiver	パケットが NIC に到着してからパケットが Kernel 空間に到着するまでの時間。 (`SOF_TIMESTAMPING_RX_SOFTWARE` の時刻) - (`SOF_TIMESTAMPING_RX_HARDWARE` の時刻)
Kernel -> User	receiver	パケットが Kernel 空間に到着してから User 空間で `recvmsg` するまでの時間

グラフから、 Kernel → User のレイテンシにノイズが発生していることがわかりました。このノイズにより、通常は約 10 us のレイテンシが、時折 100 us 程度まで増加する場合があります。この影響で、 RTT が往復で約 200 us 増加していることが確認されました。

RX 方向のタイムスタンプを取得するコード

RX 方向のタイムスタンプを取得するコード rx_timestamping.c の中身を見てみましょう。

コードの最初のほうでは、 socket にタイムスタンプを取得するためのフラグを設定します。

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

https://github.com/ArneVogel/hw-timestamping/blob/main/rx_timestamping.c#L237-L239

上記のように socket にフラグを設定すると、 recvmsg したときにタイムスタンプがメタデータとして渡されてきます。 recvmsg は以下の部分で呼び出されています。

  /* 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);

https://github.com/ArneVogel/hw-timestamping/blob/main/rx_timestamping.c#L410C1-L422C32

次に示すコードのように、特定のマクロを使うことで、 msg からパケットに紐づいたタイムスタンプを取得できます。

static void handle_time(struct msghdr *msg, struct configuration *cfg) {
  struct timespec *ts = NULL;
  struct cmsghdr *cmsg;

  for (cmsg = CMSG_FIRSTHDR(msg); cmsg; cmsg = CMSG_NXTHDR(msg, cmsg)) {
    if (cmsg->cmsg_level != SOL_SOCKET)
      continue;

    switch (cmsg->cmsg_type) {
    case SO_TIMESTAMPNS:
      ts = (struct timespec *)CMSG_DATA(cmsg);
      break;
    case SO_TIMESTAMPING:
      ts = (struct timespec *)CMSG_DATA(cmsg);
      break;
    default:
      /* Ignore other cmsg options */
      break;
    }
  }

https://github.com/ArneVogel/hw-timestamping/blob/main/rx_timestamping.c#L344C1-L363C4

タイムスタンプは ts 配列の中に格納されます。 ts 配列の中身は、以下のコメントを参考にするとよいでしょう。

  /* Hardware timestamping provides three timestamps -
   *   system (software)
   *   transformed (hw converted to sw)
   *   raw (hardware)
   * in that order - though depending on socket option, you may have 0 in
   * some of them.
   */

https://github.com/ArneVogel/hw-timestamping/blob/main/rx_timestamping.c#L281-L287

最後に、 ts から NIC -> User, NIC -> Kernel, Kernel -> User の各区間のレイテンシを計算します。

  diff_nic_kernel = (ts[0].tv_sec - ts[2].tv_sec) * 1000000000 +
                    (ts[0].tv_nsec - ts[2].tv_nsec);

  nic_kernel_latency_numbers[total_received++] =
      diff_nic_kernel; // all latency numbers are in nanoseconds

  if (old_diff_nic_kernel != 0) {
    nic_kernel_total_diff += diff_nic_kernel - old_diff_nic_kernel;
  }
  diff_kernel_user = (time_user.tv_sec - ts[0].tv_sec) * 1000000000 +
                     (time_user.tv_usec * 1000 - ts[0].tv_nsec);
  diff_nic_user = (time_user.tv_sec - ts[2].tv_sec) * 1000000000 +
                  (time_user.tv_usec * 1000 - ts[2].tv_nsec);

https://github.com/ArneVogel/hw-timestamping/blob/main/rx_timestamping.c#L312-L324

TX 方向のレイテンシを分析する

パケットが送信時に詰まってしまい、 TX 方向でレイテンシが増加している可能性も考えられたので、RX 方向と同様の分析を TX 方向でも実施しました。

IIJ Engineers Blog では RX 方向のレイテンシのみを分析しており、 TX 方向のレイテンシを分析するコードはありません。そこで、 majek/openonload リポジトリの src/tests/onload/hwtimestamping/tx_timestamping.c ⁶ を改造して動かしました。なお、 rx_timestamping.c と同じように、 tx_timestamping.c と動かす前に hardware timestamping を有効化し、 NIC とクロックを同期する必要があります。

TX 方向では、 Kernel のタイムスタンプ SOF_TIMESTAMPING_TX_SOFTWARE がなぜか取得できなかったため、 User -> NIC のレイテンシのみを集計しました。また、タイムスタンプの取得にときどき失敗し、安定性は高くない印象でした。

User-> NIC のレイテンシを可視化すると次の図のようになります。

レイテンシは 4 - 40 us 程度であり、 RX と比べると十分小さいことがわかりました。

TX 方向のタイムスタンプを取得するコード

TX 方向のタイムスタンプを取得するコード tx_timestamping.c の中身を見てみましょう。

RX 方向の場合、 User Space でパケットを受信できるころにはパケットが NIC や Kernel を通過した時刻が確定しているので、比較的簡単にタイムスタンプを取得できます。一方で TX 方向の場合、 User Space からパケットを送信しても、パケットが Kernel や NIC を通過する時刻は未確定のため、タイムスタンプを取得するにはひと工夫必要です。具体的には、パケットを sendmsg して送信したあと、 error queue から recvmsg することでタイムスタンプを取得できます。

最初に、 socket に対して timestamp を取得するようにフラグを設定します。

    enable = SOF_TIMESTAMPING_TX_HARDWARE | SOF_TIMESTAMPING_SYS_HARDWARE |
      SOF_TIMESTAMPING_RAW_HARDWARE;
    if (cfg->cfg_protocol == IPPROTO_TCP)
      enable |= ONLOAD_SOF_TIMESTAMPING_STREAM;
    ok = setsockopt(sock, SOL_SOCKET, SO_TIMESTAMPING, &enable, sizeof(int));

https://github.com/majek/openonload/blob/master/src/tests/onload/hwtimestamping/tx_timestamping.c#L338-L339

まずは sendmsg を呼び出し、パケットを送信します。

  /* recvmsg header structure */
  make_address(0, 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;



  TRY(sendmsg(sock, &msg, 0));

https://github.com/majek/openonload/blob/master/src/tests/onload/hwtimestamping/tx_timestamping.c#L494-L518C1

次に MSG_ERRQUEUE フラグを指定し、 error queue から recvmsg することで、送信したパケットを msg に読み出します。その後、 RX の場合と同様に、 msg を CMSG_FIRSTHDR マクロで読み出せばタイムスタンプを得られます。

sendmsg してから recvmsg できるようになる時刻がわからないので、コードでは busy loop で recvmsg を読み出す作りになっていて、動作の安定性に欠けるようです。

  /* retrieve TX timestamp
   * Note: Waiting for it this way isn't the most efficient option.
   * For higher throughput, check associate times to packets afterwards.
   */
  msg.msg_control = control;
  iov.iov_len = 2048;
  do {
    msg.msg_controllen = 1024;
    got = recvmsg(sock, &msg, MSG_ERRQUEUE);
  } while (got < 0 && errno == EAGAIN && check++ < check_max);
  if ( got < 0 && errno == EAGAIN ) {
    printf("Gave up acquiring timestamp.\n");
    return -EAGAIN;
  }

https://github.com/majek/openonload/blob/master/src/tests/onload/hwtimestamping/tx_timestamping.c#L520-L533

End to End レイテンシの内訳

RX と TX の双方向のタイムスタンプを分析したので、 RTT の内訳を以下のように推定できます。

Sender でのレイテンシは計測していないので、 Receiver と同じ値と仮定しました。また、TX 方向のレイテンシは 40 us と仮定しました。全体の内訳でみると、TX: 18%, NW: 9%, RX: 73% となり、 RX 方向のレイテンシが全体の 73 % 程度を占めていることがわかりました。 RX 方向のレイテンシの内訳をみると、 Kernel -> User が半分以上を占めています。 Kernel -> User のレイテンシが時々 100 us 程度に増加する問題を解決し、 RX 方向のレイテンシを最適化することで、 End to End のレイテンシも小さくできそうです。

RX 方向にノイズが乗る原因調査: 他プロセスの影響

Kernel -> User のレイテンシが増加する原因としてまず疑ったのが、他のプロセスの影響です。

そこで、 rx_timestamping.c を実行するプロセスに専用のCPUコアを割り当てて、他のプロセスの影響を排除しました⁷。 Linux では特定のコアにプロセスがスケジューリングされないようにする方法として、 cgroup cpuset controller⁸ を使うこともできますが、今回は kernel parameters に isolcpus ⁹ を指定するようにしました。過去の経験を踏まえ、 SMT (Simultaneous Multi Threading) siblings も isolate しました。 SMT siblings とは、 Intel の Hyperthreading などで作られた論理コアのうち、物理コアを共有する論理コアのことです。

以下のようにして、 31, 63 番の論理コアとその SMT siblings である 95, 127 番の論理コアに通常のプロセスがスケジューリングされないようにします。

$ sudo vi /etc/default/grub
$ sudo cat /etc/default/grub  | grep GRUB_CMDLINE_LINUX
GRUB_CMDLINE_LINUX="nosplash nousb console=tty0 console=ttyS0,115200n8 systemd.unified_cgroup_hierarchy=false init=\/bin\/systemd isolcpus=31,63,95,127 nohz_full=31,63,95,127 rcu_nocbs=31,63,95,127"
$ sudo update-grub

31 番コアで rx_timestamping.c を実行します。

$ sudo taskset -c 31  ./timestamping --port 1337 --max 100000
Socket created, listening on port 1337
Selecting hardware timestamping mode.
enabled timestamping sockopt

この環境で実験すると、 Kernel -> User にノイズが常時乗るようになってしまい、レイテンシは改善するどころか悪化してしまいました。

RX 方向にノイズが乗る原因調査: 電力関連の設定

他のプロセスの影響を排除できたのにもかかわらずレイテンシが改善しなかったので、 CPU のコア自体の性能が悪くなってしまっているのではないかと考えました。具体的には CPU の電力関連の設定を疑いました。

cpupower コマンドを利用することで、 Scaling Governors¹⁰ や Idle State¹¹ の設定ができます。

Scaling Governors は CPU の動作周波数を制御するためのポリシーです。 CPU の動作周波数を上げることで性能も上がりますが、消費電力も増えてしまうため、 Scaling Govornors は CPU の性能と消費電力のバランスを最適化してくれます。

Idle State もしくは C-State とは、 CPU が使用されていないときに消費電力を削減するための機能です。 Idle State には複数のレベルが定義されており、深い State ほど消費電力は削減できますが、 Idle 状態からの復帰に時間がかかるようになります。

Scaling Governors には、デフォルトの schedutil に加え performance も評価しました。 Idle State として、デフォルトの C1 C1E C6 を有効化した場合、 C6 のみを無効化した場合、C1 C1E C6 をすべて無効化した場合を評価しました。

Scaling Governors と Idle State の条件を組み合わせてレイテンシを測定したところ、 Idle State の C6 を無効化すると Kernel -> User レイテンシを効果的に改善できることがわかりました。

RX 方向のレイテンシを可視化してみると、 Kernel -> User に発生していたノイズがなくなり、レイテンシも小さくなったことが確認できます。 20,000 - 40,000 パケットにかけて NIC -> User, NIC -> Kernel のグラフが乱れているのは時刻同期ズレの影響だと考えられます。

C6 を無効化した状態で隣接 Compute Node 間の RTT を ping により測定すると、 0.055 ms 程度となりました。 C6 を無効化する前と比較すると、 RTT を 85 % 削減できました。

CPv2 と CPv3 で一番深い Idle State からの Exit Latency を調査しました。 CPv2 では 133us でしたが、 CPv3 では 290us となっていて、 Idle からの復帰に 2.2 倍ほど時間がかかるようになりました。これがネットワークレイテンシを悪化させた要因と考えられます。

$ sudo cpupower idle-info
CPUidle driver: intel_idle
CPUidle governor: menu
analyzing CPU 31:
Number of idle states: 4
Available idle states: POLL C1 C1E C6
POLL:
Flags/Description: CPUIDLE CORE POLL IDLE
Latency: 0
Usage: 48503581
Duration: 12146315989
C1:
Flags/Description: MWAIT 0x00
Latency: 1
Usage: 9690
Duration: 9207119
C1E:
Flags/Description: MWAIT 0x01
Latency: 2
Usage: 2023442
Duration: 4474113815
C6 (DISABLED) :
Flags/Description: MWAIT 0x20
Latency: 290
Usage: 1702644
Duration: 840131162879

C6 を無効化してゲスト VM 上で fio を実行したところ、 CPv2 と同様の性能を CPv3 でも出すことができるようになりました。

まとめ

Timestamping はパケットが Linux システムの特定のポイントを通過した時刻を記録する機能です。
- NIC の hardware timestamping と組み合わせることで、 End to End のネットワークレイテンシを分解し、レイヤごとにレイテンシを分析できます。
CPU の電力関連の設定として、 Scaling Governors と Idle State があります。
- これらの設定を見直すことで、特定のワークロードのパフォーマンスを向上できるかもしれません。