イントロ

とある php なサービスを動かしている production サーバで、 100% CPUバウンドな php-fpm プロセスが複数いたので調査をしていた。

調べていた内容

strace を取ると、 mremap(2) をひたすら繰り返しているだけのプロセスだった。 gdb でphp レベルのバックトレースを採取してソースコードと照らし合わせた読んだ所、アプリケーションのバグで以下のような挙動になっていた

ループの内部で文字列連結を行っている
バグで無限ループしちゃってる

というものだった。ああ、無限文字列連結 …

文字列が長くなるほど必要なメモリが増えるので、 php のランタイムがメモリを割り当てる際に mremap(2) を呼び出しているのだろうとアタリをつけた

擬似コードで再現

結局、問題のあったコードは以下のようなことをやってるのに、大体の意味で、等しい (注: 実際のコードはこのようなものでは全然ない)

<?php

# strace を見やすくするために write(2) を呼び出してマーカーを付ける
echo "-- start --";

$foo = "";

# ループ祭り
for (;;) { 
  $foo .= "a";
}

このコードのループ部分で strace を取るのが今日の本題

$ strace php test.php

php のコード上ではシステムコールを呼び出す記述は一切出てこないが、実際に strace を取ると mmap(2), mremap(2) がワラワラとでてくる。なぜなのかは、ランタイムの動きを把握する必要がある。

5.6.31 と 7.19 で試したところ挙動が違ったので、両者の記録をのせておく

php-5.6.31

先程のコードを strace すると mremap(2) を延々と繰り返す

write(1, "-- start --", 11-- start --)             = 11
mmap(NULL, 266240, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f30b3b28000
mremap(0x7f30b3b28000, 266240, 528384, MREMAP_MAYMOVE) = 0x7f30a3cd1000
mremap(0x7f30a3cd1000, 528384, 790528, MREMAP_MAYMOVE) = 0x7f30a3c10000
mremap(0x7f30a3c10000, 790528, 1052672, MREMAP_MAYMOVE) = 0x7f30a3c10000
mremap(0x7f30a3c10000, 1052672, 1314816, MREMAP_MAYMOVE) = 0x7f30a3c10000
mremap(0x7f30a3c10000, 1314816, 1576960, MREMAP_MAYMOVE) = 0x7f30a3a8f000
mremap(0x7f30a3a8f000, 1576960, 1839104, MREMAP_MAYMOVE) = 0x7f30a3a8f000
mremap(0x7f30a3a8f000, 1839104, 2101248, MREMAP_MAYMOVE) = 0x7f30a3a8f000
mremap(0x7f30a3a8f000, 2101248, 2363392, MREMAP_MAYMOVE) = 0x7f30a3a8f000
mremap(0x7f30a3a8f000, 2363392, 2625536, MREMAP_MAYMOVE) = 0x7f30a3a8f000
mremap(0x7f30a3a8f000, 2625536, 2887680, MREMAP_MAYMOVE) = 0x7f30a3a8f000
mremap(0x7f30a3a8f000, 2887680, 3149824, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 3149824, 3411968, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 3411968, 3674112, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 3674112, 3936256, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 3936256, 4198400, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 4198400, 4460544, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 4460544, 4722688, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 4722688, 4984832, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 4984832, 5246976, MREMAP_MAYMOVE) = 0x7f30a378e000
mremap(0x7f30a378e000, 5246976, 5509120, MREMAP_MAYMOVE) = 0x7f30a378e000

... 続く

gdb で呼び出し元とソースを確認する

(gdb) b mremap
Breakpoint 2 at 0x7ffff1908ef0: file ../sysdeps/unix/syscall-template.S, line 81.
(gdb) c

(gdb) c
Continuing.

Breakpoint 2, mremap () at ../sysdeps/unix/syscall-template.S:81
81  T_PSEUDO (SYSCALL_SYMBOL, SYSCALL_NAME, SYSCALL_NARGS)
(gdb) bt
#0  mremap () at ../sysdeps/unix/syscall-template.S:81
#1  0x00007ffff1891552 in mremap_chunk (new_size=41947136, p=0x7fffe5065000) at malloc.c:2857
#2  __GI___libc_realloc (oldmem=0x7fffe5065010, bytes=41943040) at malloc.c:2999
#3  0x0000000000838fa6 in _zend_mm_realloc_int (heap=0x11cf000, p=0x7fffe5065030, size=41680849) at /tmp/php-build/source/5.6.31/Zend/zend_alloc.c:2296
#4  0x000000000085bd4b in concat_function (result=0x7ffff7fc3300, op1=0x7ffff7fc3300, op2=0x7ffff7fc4d60) at /tmp/php-build/source/5.6.31/Zend/zend_operators.c:1471
#5  0x00000000008e73a2 in zend_binary_assign_op_helper_SPEC_CV_CONST (binary_op=0x85bb10 <concat_function>, execute_data=0x7ffff7f900e8)
    at /tmp/php-build/source/5.6.31/Zend/zend_vm_execute.h:32426
#6  0x0000000000896168 in execute_ex (execute_data=0x7ffff7f900e8) at /tmp/php-build/source/5.6.31/Zend/zend_vm_execute.h:363
#7  0x00007fffe803b8a8 in xdebug_execute_ex (execute_data=0x7ffff7f900e8) at /tmp/php-build/source/xdebug-2.5.5/xdebug.c:2056
#8  0x0000000000861880 in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /tmp/php-build/source/5.6.31/Zend/zend.c:1341
#9  0x0000000000800132 in php_execute_script (primary_file=primary_file@entry=0x7fffffffcff0) at /tmp/php-build/source/5.6.31/main/main.c:2613
#10 0x00000000009072ac in do_cli (argc=2, argv=0x11ced50) at /tmp/php-build/source/5.6.31/sapi/cli/php_cli.c:998
#11 0x0000000000442c4f in main (argc=2, argv=0x11ced50) at /tmp/php-build/source/5.6.31/sapi/cli/php_cli.c:1382

5.6.31 で呼び出し元のソースは以下の部分ぽい

static void *_zend_mm_realloc_int(zend_mm_heap *heap, void *p, size_t size ZEND_FILE_LINE_DC ZEND_FILE_LINE_ORIG_DC)
{
    zend_mm_block *mm_block = ZEND_MM_HEADER_OF(p);
    zend_mm_block *next_block;
    size_t true_size;
    size_t orig_size;
    void *ptr;
#ifdef ZEND_SIGNALS
    TSRMLS_FETCH();
#endif
    if (UNEXPECTED(!p) || !ZEND_MM_VALID_PTR(p)) {
        return _zend_mm_alloc_int(heap, size ZEND_FILE_LINE_RELAY_CC ZEND_FILE_LINE_ORIG_RELAY_CC);
}

... 略

        segment = ZEND_MM_STORAGE_REALLOC(segment_copy, segment_size);

ZEND_MM_STORAGE_REALLOC の正体は、たぶん、下記のソース。関数ポインタであれこれやっているので、バックトレースを取っただけだと絞り込めない。ソースを grep すると mremap(2) 呼び出しがここしか無いので合ってると思うが。

static zend_mm_segment* zend_mm_mem_mmap_realloc(zend_mm_storage *storage, zend_mm_segment* segment, size_t size)
{
    zend_mm_segment *ret;
#ifdef HAVE_MREMAP
#if defined(__NetBSD__)
    /* NetBSD 5 supports mremap but takes an extra newp argument */
    ret = (zend_mm_segment*)mremap(segment, segment->size, segment, size, MREMAP_MAYMOVE);
#else
    ret = (zend_mm_segment*)mremap(segment, segment->size, size, MREMAP_MAYMOVE); ⭐
#endif
    if (ret == MAP_FAILED) {
#endif
        ret = storage->handlers->_alloc(storage, size);
        if (ret) {
            memcpy(ret, segment, size > segment->size ? segment->size : size);
            storage->handlers->_free(storage, segment);
        }
#ifdef HAVE_MREMAP
    }
#endif
    return ret;
}

php-7.19

php-7.19 でトレースを取ると mmap(2) を繰り返す。ランタイムの改善が入ってメモリのあれこれの挙動が変わったのだろう (詳しいところはチョトワカラナイ)

write(1, "-- start --\n", 12-- start --
)           = 12
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779dc34000
munmap(0x7f779dc34000, 2097152)         = 0
mmap(NULL, 4190208, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779da35000
munmap(0x7f779da35000, 1880064)         = 0
munmap(0x7f779de00000, 212992)          = 0
madvise(0x7f779dc00000, 2097152, MADV_HUGEPAGE) = 0
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779da00000
madvise(0x7f779da00000, 2097152, MADV_HUGEPAGE) = 0
mmap(0x7f779dc00000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f77ae19b000
munmap(0x7f77ae19b000, 4096)            = 0
mmap(NULL, 2101248, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d7ff000
munmap(0x7f779d7ff000, 2101248)         = 0
mmap(NULL, 4194304, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d600000
munmap(0x7f779d801000, 2093056)         = 0
madvise(0x7f779d600000, 2101248, MADV_HUGEPAGE) = 0
munmap(0x7f779da00000, 2097152)         = 0
mmap(0x7f779d801000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d801000
mmap(0x7f779d802000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d802000
mmap(0x7f779d803000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d803000
mmap(0x7f779d804000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d804000
mmap(0x7f779d805000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d805000
mmap(0x7f779d806000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d806000
mmap(0x7f779d807000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d807000
mmap(0x7f779d808000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d808000
mmap(0x7f779d809000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d809000
mmap(0x7f779d80a000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d80a000
mmap(0x7f779d80b000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f779d80b000


... 続く

munmap(0x7fbcce1d9000, 4096)            = 0
mmap(NULL, 6295552, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbcfff000
munmap(0x7fbcbcfff000, 6295552)         = 0
mmap(NULL, 8388608, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbce00000
munmap(0x7fbcbd401000, 2093056)         = 0
madvise(0x7fbcbce00000, 6295552, MADV_HUGEPAGE) = 0
munmap(0x7fbcbd600000, 6291456)         = 0
mmap(0x7fbcbd401000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbd401000
mmap(0x7fbcbd402000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbd402000
mmap(0x7fbcbd403000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbd403000
mmap(0x7fbcbd404000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbd404000
mmap(0x7fbcbd405000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fbcbd405000

... 続く

gdb で呼び出し元とソースを確認する

(gdb) b mmap
Breakpoint 1 at 0x7ffff1902d90: file ../sysdeps/unix/sysv/linux/wordsize-64/mmap.c, line 32.

(gdb) c
Continuing.

(gdb) bt
#0  __mmap (addr=addr@entry=0x7fffe764e000, len=len@entry=4096, prot=prot@entry=3, flags=flags@entry=34, fd=fd@entry=-1, offset=offset@entry=0)
    at ../sysdeps/unix/sysv/linux/wordsize-64/mmap.c:32
#1  0x000000000084d261 in zend_mm_mmap_fixed (size=4096, addr=0x7fffe764e000) at /tmp/php-build/source/7.1.9/Zend/zend_alloc.c:427
#2  zend_mm_chunk_extend (heap=0x7fffee600040, new_size=2420736, old_size=2416640, addr=0x7fffe7400000) at /tmp/php-build/source/7.1.9/Zend/zend_alloc.c:805
#3  zend_mm_realloc_heap (heap=0x7fffee600040, ptr=0x7fffe7400000, size=<optimized out>, copy_size=<optimized out>) at /tmp/php-build/source/7.1.9/Zend/zend_alloc.c:1487
#4  0x00000000008691c9 in zend_string_extend (persistent=0, len=2416616, s=<optimized out>) at /tmp/php-build/source/7.1.9/Zend/zend_string.h:208
#5  concat_function (result=0x7fffee613080, op1=0x7fffee613080, op2=0x7fffee68a020) at /tmp/php-build/source/7.1.9/Zend/zend_operators.c:1759
#6  0x00000000008eaf2b in zend_binary_assign_op_helper_SPEC_CV_CONST (binary_op=0x869070 <concat_function>) at /tmp/php-build/source/7.1.9/Zend/zend_vm_execute.h:37102
#7  0x00000000008b866b in execute_ex (ex=<optimized out>) at /tmp/php-build/source/7.1.9/Zend/zend_vm_execute.h:429
#8  0x00007fffe7c43b3e in xdebug_execute_ex (execute_data=0x7fffee613030) at /tmp/php-build/source/xdebug-2.5.5/xdebug.c:2056
#9  0x000000000090b614 in zend_execute (op_array=op_array@entry=0x7fffee681000, return_value=return_value@entry=0x0) at /tmp/php-build/source/7.1.9/Zend/zend_vm_execute.h:474
#10 0x0000000000873924 in zend_execute_scripts (type=type@entry=8, retval=retval@entry=0x0, file_count=file_count@entry=3) at /tmp/php-build/source/7.1.9/Zend/zend.c:1480
#11 0x0000000000814a30 in php_execute_script (primary_file=primary_file@entry=0x7fffffffd000) at /tmp/php-build/source/7.1.9/main/main.c:2552
#12 0x000000000090d7af in do_cli (argc=2, argv=0x122ad50) at /tmp/php-build/source/7.1.9/sapi/cli/php_cli.c:993
#13 0x000000000044b010 in main (argc=2, argv=0x122ad50) at /tmp/php-build/source/7.1.9/sapi/cli/php_cli.c:1381

バックトレースと対応付けたソースは下記の通り

static void *zend_mm_mmap_fixed(void *addr, size_t size)
{
#ifdef _WIN32
    return VirtualAlloc(addr, size, MEM_COMMIT | MEM_RESERVE, PAGE_READWRITE);
#else
    /* MAP_FIXED leads to discarding of the old mapping, so it can't be used. */
    void *ptr = mmap(addr, size, PROT_READ | PROT_WRITE, MAP_PRIVATE | MAP_ANON /*| MAP_POPULATE | MAP_HUGETLB*/, -1, 0);

    if (ptr == MAP_FAILED) {
#if ZEND_MM_ERROR
        fprintf(stderr, "\nmmap() failed: [%d] %s\n", errno, strerror(errno));
#endif
        return NULL;
    } else if (ptr != addr) {
        if (munmap(ptr, size) != 0) {
#if ZEND_MM_ERROR
            fprintf(stderr, "\nmunmap() failed: [%d] %s\n", errno, strerror(errno));
#endif
        }
        return NULL;
    }
    return ptr;
#endif
}

感想

アプリケーションの php コードが mmap(2) や mremap(2) を呼び出すことは (まず) 無いだろうから、これらのシステムコールが頻繁に呼び出されていたらメモリのアロケート周りしつづけてしまう何か異常が起こっていると推測をつけることができそう。今回は文字列の無限連結だった。
言語のランタイム内部で呼び出すシステムコールのパターンを把握しておくと、障害や不具合の調査・解析がスムーズになるケースもあるだろう
作業のおまけで php5.6 と php7.1 とで挙動が違うのを把握できた