こんにちは。筆者が現在関わっているプロダクトで、数千のコンテナを起動する際に、ネットワークネームスペース(netns)の作成が律速になるという問題が発生しました。このエントリでは、そういった問題が発生した場合に、どのようにボトルネックを特定し、対応するかについて紹介したいと思います。

以前類似の調査をした内容は下記のスライドにまとめています。

netnsってなに？というかたは、 @ten_forward さんの連載記事がわかりやすいです。

まずは環境を作っていきましょう。実行環境はmacOS上で動くVirtualboxでcpuを2コア、メモリを2G割り当てた ubuntu/xenial64 です。netnsの作成はshellを書きます。

#!/bin/bash

if [ $# -ne 3 ]; then
  echo "usage netns.sh [add|del] from to" 1>&2
  exit 1
fi


for((i=$2;i<$3;i++))
do
  echo "create netns test_$i"
  ip netns $1 test_$i;
done

作ったshellを利用してサクッと、2000個くらいnetnsを作ってしまいます。

$ ./netns.sh add 0 2000
$ ip netns | wc -l
2000

この状態で2001個目をstarceしながら作ってみましょう。

$ strace -tt -s 1024 -o ./strace_2001 ip netns add test_2001
$ head -1 strace_2001 
22:08:52.027006 execve("/sbin/ip", ["ip", "netns", "add", "test_2001"], [/* 16 vars */]) = 0
$ tail -1 strace_2001 
22:08:54.974859 +++ exited with 0 +++

straceしつつでも2秒くらいで作れてしまうので、まださほど遅い状態ではありません。続いて4000個netnsを作って、同じように試してみます。

$ ./netns.sh add 2002 4000
create netns test_2002
...
create netns test_3938
create netns test_3939

3939個目のnetnsを作製しているところでかなり遅くなることが確認できました。またこの状態になると、インスタンスの操作ができなくなるほどの過負荷状態になります。盛り上がってきました!!!1

一度サーバを再起動して、再度トライします。ギリギリに攻めるとまた過負荷で操作できなくなるので、3930個作製してみます。

$ ./netns.sh add 0 3930
$ strace -tt -s 1024 -o ./strace_3931 ip netns add test_3931
$ head -1 strace_3931
00:52:45.225735 execve("/sbin/ip", ["ip", "netns", "add", "test_3931"], [/* 16 vars */]) = 0
$ tail -1 strace_3931
00:52:55.286222 +++ exited with 0 +++

おー、10秒くらいかかるようになりましたね。何が遅いのかstraceの結果を覗いてみます。

00:52:45.278671 open("/var/run/netns", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
00:52:45.279814 fstat(5, {st_mode=S_IFDIR|0755, st_size=78620, ...}) = 0
00:52:45.279979 brk(NULL)               = 0xc2d000
00:52:45.280305 brk(0xc56000)           = 0xc56000
00:52:45.280591 getdents(5, /* 1024 entries */, 32768) = 32752

00:52:45.281504 open("/var/run/netns/test_3929", O_RDONLY) = 6
00:52:45.281756 sendmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\34\0\0\0Z\0\1\0\316\325\305Z\0\0\0\0\0\0\0\0\10\0\3\0\6\0\0\0", 28}], msg_controllen=0, msg_flags=0}, 0) = 28
00:52:45.282098 recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\34\0\0\0X\0\0\0\316\325\305Z\231\27t\342\0\0\0\0\10\0\1\0\377\377\377\377", 32768}], msg_controllen=0, msg_flags=0}, 0) = 28
00:52:45.282332 close(6)                = 0

中身を見ると、getdentsで/var/run/netns/の一覧を取得後、既存のnentsのfdを開いて、何かしらメッセージを送ってますね。これがひたすらnetns分繰り返されているようです。さらに、perfでコールグラフを取得し、どの部分がボトルネックなのかを特定します。

$ perf record --call-graph dwarf -- ip netns add test_3945
$ perf report -g -G --stdio
    65.10%     0.21%  ip       [kernel.kallsyms]  [k] entry_SYSCALL_64_fastpath                
                 |
                 ---entry_SYSCALL_64_fastpath
                    |          
                    |--26.54%-- sys_open
                    |          |          
                    |          |--26.44%-- do_sys_open
                    |          |          |          
                    |          |          |--24.97%-- do_filp_open
                    |          |          |          |          
                    |          |          |          |--24.87%-- path_openat
                    |          |          |          |          |          
                    |          |          |          |          |--13.38%-- link_path_walk
                    |          |          |          |          |          |          
                    |          |          |          |          |          |--12.02%-- walk_component
                    |          |          |          |          |          |          |          
                    |          |          |          |          |          |          |--6.27%-- __lookup_hash

全結果はこちら

この時のメモリの状態はこのような感じでした。freeが 56324 とかなり枯渇しています。

$ free
              total        used        free      shared  buff/cache   available
Mem:        2048100     1144188      ★56324          12      847588       22628
Swap:        524284       86260      438024 5 total

sys_openの処理が支配的になっていることから、メモリが枯渇状態の時にsys_openを大量に実行するようなnetnsの挙動は律速なることがわかります。
考えうる対処としては、ipコマンドのパッチを書き、netnsの追加時にすべてのnetnsをopenするような挙動をやめることが挙げられます。

また余談ですが、メモリが枯渇していないときのperfの結果は このように なっており、sys_open
の負荷はさほどありません。

先のstraceの結果のsendmsgが何をやっているのかを確認します。

00:52:45.278671 open("/var/run/netns", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 5
00:52:45.279814 fstat(5, {st_mode=S_IFDIR|0755, st_size=78620, ...}) = 0
00:52:45.279979 brk(NULL)               = 0xc2d000
00:52:45.280305 brk(0xc56000)           = 0xc56000
00:52:45.280591 getdents(5, /* 1024 entries */, 32768) = 32752

00:52:45.281504 open("/var/run/netns/test_3929", O_RDONLY) = 6
00:52:45.281756 sendmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\34\0\0\0Z\0\1\0\316\325\305Z\0\0\0\0\0\0\0\0\10\0\3\0\6\0\0\0", 28}], msg_controllen=0, msg_flags=0}, 0) = 28
00:52:45.282098 recvmsg(4, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000000}, msg_iov(1)=[{"\34\0\0\0X\0\0\0\316\325\305Z\231\27t\342\0\0\0\0\10\0\1\0\377\377\377\377", 32768}], msg_controllen=0, msg_flags=0}, 0) = 28
00:52:45.282332 close(6)                = 0

ここからはみんな大好きgdb。

$ gdb ip
(gdb) b sendmsg # ブレークポイント打って
(gdb) run netns add test_1 # nents追加して
Starting program: /sbin/ip netns add test_1

Breakpoint 1, sendmsg () at ../sysdeps/unix/syscall-template.S:84
84      ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt # バックトレースで呼び出し履歴を見る
#0  sendmsg () at ../sysdeps/unix/syscall-template.S:84
#1  0x000000000043c8b3 in rtnl_talk ()
#2  0x0000000000413b1d in ?? ()
#3  0x000000000041453f in netns_map_init ()
#4  0x00000000004145ce in do_netns ()
#5  0x0000000000407284 in ?? ()
#6  0x0000000000406d72 in main ()

呼び出し箇所がわかったのでiproute2の実装を読みます。
do_netnsの実装を眺めて見たのですが、 netns_map_init はnetnsの名前からID(nsid)を取得して、構造体に保有するような実装でした。恐らくIDで管理される処理があるので、変数として保有するのでしょう。

しかし、実装を見ると、netns_map_initは引数がないときや listサブコマンドのときしか呼ばれないように見えます。

コミットを追い掛けてみると iproute2: build nsid-name cache only for commands that need it において、必要なときだけnsidを解決する処理が行われるように修正されていることがわかりました。

つまり、最新のiproute2を使うと今回の律速問題は改善する可能性がありますし、余計なsys_openが抑制されるので、netnsの追加が高速になることが期待されます。

$ apt-get update -qqy
$ apt-get install flex
$ git clone https://salsa.debian.org/debian/iproute2.git
$ cd iproute2
$ make
$ make install

先ほどと同じようにgdbで確認します。

$ gdb ip

(gdb) b sendmsg
Breakpoint 1 at 0x406dc0
(gdb) run netns add test_4
Starting program: /sbin/ip netns add test_4
[Inferior 1 (process 3248) exited normally]

先ほどと異なり、breakにかかることなく処理が完了しました。2000個のnetnsが存在する状態で速度を見てみましょう。

$ strace -tt -s 1024 -o ./strace_2001 ip netns add test_2001
$ head -1 strace_2001 
23:02:06.269076 execve("/sbin/ip", ["ip", "netns", "add", "test_2001"], [/* 16 vars */]) = 0
$ tail -1 strace_2001 
23:02:06.310005 +++ exited with 0 +++

もともと2秒ほどかかっていた処理が、0.05秒ほどで完了するようになりました。単純計算すると 40倍 ほど早くなったことになります。

次に過負荷状態でコールグラフを見てみましょう。

$ ./netns.sh add 2001 3935
$ perf record --call-graph dwarf -- ip netns add test_3936
$ perf report -g -G --stdio
    96.36%     0.00%  ip       [kernel.kallsyms]  [k] entry_SYSCALL_64_fastpath              
                 |
                 ---entry_SYSCALL_64_fastpath
                    |          
                    |--92.12%-- sys_unshare
                    |          unshare_nsproxy_namespaces
                    |          create_new_namespaces
                    |          copy_net_ns
                    |          setup_net
                    |          ops_init
                    |          |          
                    |          |--41.21%-- loopback_net_init
                    |          |          register_netdev
                    |          |          register_netdevice

このようにボトルネックがsys_openからsys_unshareに移ったことがわかります。

まとめ

iproute2を用いて、netnsを追加する場合に、ubuntu/xenial64の環境だと、既存のnetns全てにID解決要求を投げてしまうため、sys_open~recvmessageのオーバーヘッドが存在します。これらのオーバーヘッドは最新のiproute2をコンパイルし、インストールすることで改善することができます。またこれらの問題において、strace、perf、gdbを利用すればボトルネックの特定から改善まで至ることが出来ます。

みなさんもぜひ呼吸するようにLinuxコマンドを使い倒していきましょう。