読者です 読者をやめる 読者になる 読者になる

s_tajima:TechBlog

渋谷で働くインフラエンジニアのTechブログです。

アプリケーション内でhttpsによる外部APIを叩いているサーバのメモリ使用量が増加し続ける件について

問題

アプリケーション内でhttpsによる外部APIを叩いているサーバのメモリ使用量が増加し続ける件について調べた。

該当のサーバでは、以下のようにメモリの使用率が徐々に上昇していく。
また、アプリケーションのプロセス自体がメモリを消費しているわけではない状態。

f:id:s_tajima:20150220233254p:plain

原因

調査すると、このバグ仕様を踏んでいるのではないかと思われるページを見つけた。
https://bugzilla.redhat.com/show_bug.cgi?id=1044666

内容としては、curlを実行した際に
/etc/pki/nssdb/以下の存在しないファイル(毎回違うパス)に対してaccessシステムコールが大量にコールされ、
negative dentry cacheが溜まっていき、メモリ使用量が圧迫されるというもの。

実際、この状況が起きているサーバを調べるとメモリ使用率のうち多くを占めているのはnegative dentry cacheであることがわかる。

$ free -k
             total       used       free     shared    buffers     cached
Mem:       3849124    1848376    2000748          0     145780     202468
-/+ buffers/cache:    1500128    2348996
Swap:            0          0          0
$ cat /proc/meminfo | grep Slab
Slab:            1370992 kB
$ sar -v
13時22分26秒 dentunusd   file-nr  inode-nr    pty-nr
13時22分27秒   6652734       832     13046        33

curl実行時に大量のaccessがコールされている状況も再現できた。

$ strace -fc -e trace=access curl 'https://www.google.com' > /dev/null
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
131   262  131   262    0     0   1812      0 --:--:-- --:--:-- --:--:-- 18714
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000211           0       646       640 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000211                   646       640 total

このようなphpファイルを実行しても再現する。
https://gist.github.com/s-tajima/854936acc9526cd812b2

$ strace -fc -e trace=access php test.php

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.000238           2       142       131 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000238                   142       131 total

なぜこんなことになるのかというと、
https://hg.mozilla.org/projects/nss/file/4d876e0ee318/security/nss/lib/softoken/sdb.c#l372
ファイルシステムの性能を検査して、キャッシュを使うかどうかの判断をしているらしい。

対応

対応としては、
https://bugzilla.redhat.com/show_bug.cgi?id=1044666#c8
このパッチで使えるようになった、NSS_SDB_USE_CACHEのオプションを有効にして、
ファイルシステムの検査をせずにキャッシュを使うようにすればいいようだ。

$ sudo yum update nss-3.16.2.3-3.el6_6.x86_64.rpm nspr-4.10.6-1.el6_5.x86_64.rpm nss-util-3.16.2.3-2.el6_6.x86_64.rpm nss-softokn-3.14.3-22.el6_6.x86_64.rpm nss-softokn-freebl-3.14.3-22.el6_6.x86_64.rpm nss-sysinit-3.16.2.3-3.el6_6.x86_64.rpm
$ export NSS_SDB_USE_CACHE=yes ※phpのコード内でputenv("NSS_SDB_USE_CACHE=yes”)でもよい。
$ strace -fc -e trace=access php test.php
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  -nan    0.000000           0        12         7 access
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    12         7 total

改善された。