一个erlang nif野指针的追踪过程

概述

最近半年, 经常出现一些奇怪的bug.

• CPU非常高, 但etop并没有red特别高的进程.
• 内存占用非常高, 和etop看到的内存不吻合.
• coredump.

因为erlang层面无法定位问题, 那问题只能在c了.

BUG现场

cpu %100

ErtsRunQueue被写坏

#0  sched_prep_cont_spin_wait (ssi=<optimized out>) at beam/erl_process.c:2947
#1  scheduler_wait (fcalls=<synthetic pointer>, rq=<optimized out>, esdp=0x7fac4d7c7b40) at beam/erl_process.c:3377
#2  erts_schedule () at beam/erl_process.c:9419
#3  0x0000000000464e31 in erts_dirty_process_main () at beam/beam_emu.c:1175
#4  0x000000000044d6f0 in sched_dirty_cpu_thread_func (vesdp=0x7fac4d7c7b40) at beam/erl_process.c:8396
#5  0x0000000000674cf9 in thr_wrapper (vtwd=0x7ffcb5f11cf0) at pthread/ethread.c:118
#6  0x00007fac908226ba in start_thread (arg=0x7fac4c3b1700) at pthread_create.c:333
#7  0x00007fac9035041d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

erts_schedule () at beam/erl_process.c:9419
9419    in beam/erl_process.c
(gdb) p rq
$9 = (ErtsRunQueue *) 0x20
(gdb) p *rq
Cannot access memory at address 0x20

AOFF_RBTree_t被写坏. rb_tree存在环.

#0  rbt_insert (order=FF_BF, root=root@entry=0x7f0c9c6000e8, blk=0x7f0c9c605a58) at beam/erl_ao_firstfit_alloc.c:796
#1  0x00000000005e8a42 in aoff_link_free_block (allctr=<optimized out>, block=<optimized out>) at beam/erl_ao_firstfit_alloc.c:750
#2  0x000000000049b444 in mbc_free (allctr=0x22e90c0, p=<optimized out>, busy_pcrr_pp=0x7f0c98376a30) at beam/erl_alloc_util.c:2579
#3  0x000000000049be8f in dealloc_block (allctr=allctr@entry=0x22e90c0, ptr=ptr@entry=0x7f0c9c605a60, fix=fix@entry=0x0, dec_cc_on_redirect=dec_cc_on_redirect@entry=1) at beam/erl_alloc_util.c:2321
#4  0x000000000049f440 in dealloc_block (fix=0x0, dec_cc_on_redirect=1, ptr=0x7f0c9c605a60, allctr=0x22e90c0) at beam/erl_alloc_util.c:2306
#5  handle_delayed_dealloc (need_more_work=<optimized out>, thr_prgr_p=<optimized out>, need_thr_progress=0x7f0c98376b28, ops_limit=20, use_limit=<optimized out>, allctr_locked=0, allctr=0x22e90c0) at beam/erl_alloc_util.c:2174
#6  erts_alcu_check_delayed_dealloc (allctr=0x22e90c0, limit=limit@entry=1, need_thr_progress=need_thr_progress@entry=0x7f0c98376b28, thr_prgr_p=thr_prgr_p@entry=0x7f0c98376b30, more_work=more_work@entry=0x7f0c98376b2c)
    at beam/erl_alloc_util.c:2276
#7  0x000000000048df73 in erts_alloc_scheduler_handle_delayed_dealloc (vesdp=0x7f0c9a56dcc0, need_thr_progress=need_thr_progress@entry=0x7f0c98376b28, thr_prgr_p=thr_prgr_p@entry=0x7f0c98376b30, 
    more_work=more_work@entry=0x7f0c98376b2c) at beam/erl_alloc.c:1895
#8  0x0000000000461812 in handle_delayed_dealloc_thr_prgr (waiting=1, aux_work=4, awdp=0x7f0c9a56ddd8) at beam/erl_process.c:2101
#9  handle_aux_work (awdp=awdp@entry=0x7f0c9a56ddd8, orig_aux_work=orig_aux_work@entry=4, waiting=waiting@entry=1) at beam/erl_process.c:2596
#10 0x0000000000460ced in scheduler_wait (fcalls=<synthetic pointer>, rq=<optimized out>, esdp=0x7f0c9a56dcc0) at beam/erl_process.c:3292
#11 erts_schedule () at beam/erl_process.c:9419
#12 0x0000000000451920 in process_main () at beam/beam_emu.c:689
#13 0x000000000044d863 in sched_thread_func (vesdp=0x7f0c9a56dcc0) at beam/erl_process.c:8349
#14 0x0000000000674cf9 in thr_wrapper (vtwd=0x7ffe71ca9770) at pthread/ethread.c:118
#15 0x00007f0cdd1976ba in start_thread (arg=0x7f0c98377700) at pthread_create.c:333
#16 0x00007f0cdccc541d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

(gdb) p *root->right->right
$25 = {hdr = {bhdr = 1185, u = {carrier = 0x7f0c9c600000, udata__ = ""}}, parent = 0x7f0c9c607b80, left = 0x0, right = 0x7f0c9c605ac0, flags = 3, max_sz = 1288, u = {next = 0x0, birth_time = 0}}
(gdb) p *root->right->right
$26 = {hdr = {bhdr = 1185, u = {carrier = 0x7f0c9c600000, udata__ = ""}}, parent = 0x7f0c9c607b80, left = 0x0, right = 0x7f0c9c605ac0, flags = 3, max_sz = 1288, u = {next = 0x0, birth_time = 0}}
(gdb) p *root->right->right
$27 = {hdr = {bhdr = 1185, u = {carrier = 0x7f0c9c600000, udata__ = ""}}, parent = 0x7f0c9c607b80, left = 0x0, right = 0x7f0c9c605ac0, flags = 3, max_sz = 1288, u = {next = 0x0, birth_time = 0}}
(gdb) p *root->right->right->right

memory leak

见cpu %100中的AOFF_RBTree_t问题. memory leak的现场较少. 目前只分析一个.
因AOFF_RBTree_t busy loop. 导致分配的内存无法释放, 主要内存分配的源头是普罗米修斯监控采集.

#Cp<0x9a6153d8>  (I)
#Cp<ram_file:ll_open/3+0x80>.
#Cp<0x9c0d3510>.
#Cp<prometheus_text_format:format/1+0x60>.
#Cp<'Elixir.Prometheus.Format.Text':format/1+0x58>.
#Cp<'Elixir.Prometheus.MetricsRouter':'-do_match/4-fun-1-'/1+0x48>.
#Cp<'Elixir.Prometheus.MetricsRouter':plug_builder_call/2+0xd0>.
#Cp<0x9c02b7a0>.
#Cp<0x827211d8>.
#Cp<cowboy_stream_h:execute/3+0x60>.
#Cp<cowboy_stream_h:request_process/3+0xb8>.
#Cp<proc_lib:init_p_do_apply/3+0x50>.
#Cp<terminate process normally>.

coredump

如下两个coredump较为典型.

#0  0x00000000005e7a7b in lower_max_size (stop_at=0x0, node=0x7eff735b2d68) at beam/erl_ao_firstfit_alloc.c:161
#1  rbt_delete (root=root@entry=0x7eff735800e8, del=0x7eff735bc2f8) at beam/erl_ao_firstfit_alloc.c:617
#2  0x00000000005e826e in aoff_unlink_free_block (allctr=<optimized out>, blk=<optimized out>) at beam/erl_ao_firstfit_alloc.c:548
#3  0x00000000005e84aa in aoff_get_free_block (allctr=<optimized out>, size=<optimized out>, cand_blk=<optimized out>, cand_size=<optimized out>) at beam/erl_ao_firstfit_alloc.c:911
#4  0x0000000000499191 in create_carrier (allctr=allctr@entry=0xb0bdc0, umem_sz=umem_sz@entry=65544, flags=<optimized out>, flags@entry=2) at beam/erl_alloc_util.c:3921
#5  0x000000000049a700 in mbc_alloc_block (blk_szp=<synthetic pointer>, size=65536, allctr=0xb0bdc0) at beam/erl_alloc_util.c:2357
#6  mbc_alloc (allctr=0xb0bdc0, size=65536) at beam/erl_alloc_util.c:2483
#7  0x00000000004a1491 in erts_alcu_alloc_thr_pref (type=107, extra=<optimized out>, size=65536) at beam/erl_alloc_util.c:5650
#8  0x00007f002eff82d0 in deflateInit2_ () from /lib/x86_64-linux-gnu/libz.so.1
#9  0x00007f002eff841e in deflateInit_ () from /lib/x86_64-linux-gnu/libz.so.1
#10 0x00000000005d67b0 in erl_zlib_deflate_start (streamp=<optimized out>, source=<optimized out>, sourceLen=<optimized out>, level=<optimized out>) at beam/erl_zlib.c:60
#11 0x000000000053cf9f in erts_term_to_binary_int (p=p@entry=0x7effecf00438, Term=<optimized out>, level=<optimized out>, flags=<optimized out>, context_b=0x7eff73a438f8, context_b@entry=0x0) at beam/external.c:2049
#12 0x000000000053f7b2 in term_to_binary_2 (A__p=0x7effecf00438, BIF__ARGS=<optimized out>, A__I=<optimized out>) at beam/external.c:1204
#13 0x00000000004525cc in process_main () at x86_64-unknown-linux-gnu/opt/smp/beam_hot.h:310
#14 0x000000000044d863 in sched_thread_func (vesdp=0x7effec184dc0) at beam/erl_process.c:8349
#15 0x0000000000674cf9 in thr_wrapper (vtwd=0x7fffdd513f70) at pthread/ethread.c:118
#16 0x00007f002eddc6ba in pthread_getattr_np (thread_id=139637642776000, attr=0x0) at pthread_getattr_np.c:88
#17 0x0000000000000000 in ?? ()

#0  0x00000000005e870d in tree_insert_fixup (blk=<optimized out>, root=<optimized out>) at beam/erl_ao_firstfit_alloc.c:476
#1  rbt_insert (order=FF_BF, root=root@entry=0x7f0b7ad400e8, blk=0x7f0b7ad775d8) at beam/erl_ao_firstfit_alloc.c:830
#2  0x00000000005e8a42 in aoff_link_free_block (allctr=<optimized out>, block=<optimized out>) at beam/erl_ao_firstfit_alloc.c:750
#3  0x000000000049a5dc in mbc_alloc_finalize (valid_blk_info=1, want_blk_sz=31720, crr=0x7f0b7ad40000, flags=<optimized out>, org_blk_sz=<optimized out>, blk=0x7f0b7ad6f9f0, allctr=0x1cb1dc0) at beam/erl_alloc_util.c:2421
#4  mbc_alloc (allctr=0x1cb1dc0, size=<optimized out>) at beam/erl_alloc_util.c:2487
#5  0x00000000004a1491 in erts_alcu_alloc_thr_pref (type=86, extra=<optimized out>, size=31712) at beam/erl_alloc_util.c:5650
#6  0x0000000000486f0d in erts_alloc (type=11060, size=31712) at beam/erl_alloc.h:230
#7  erts_start_staging_ranges (num_new=num_new@entry=1) at beam/beam_ranges.c:131
#8  0x0000000000486a4a in erts_start_staging_code_ix (num_new=num_new@entry=1) at beam/code_ix.c:74
#9  0x000000000047aca8 in finish_loading_1 (A__p=0x7f0be94c1e38, BIF__ARGS=<optimized out>, A__I=<optimized out>) at beam/beam_bif_load.c:373
#10 0x00000000004525cc in process_main () at x86_64-unknown-linux-gnu/opt/smp/beam_hot.h:310
#11 0x000000000044d863 in sched_thread_func (vesdp=0x7f0bec784dc0) at beam/erl_process.c:8349
#12 0x0000000000674cf9 in thr_wrapper (vtwd=0x7ffe8f8841e0) at pthread/ethread.c:118
#13 0x00007f0c2f3df6ba in pthread_getattr_np (thread_id=139689188675008, attr=0x0) at pthread_getattr_np.c:88
#14 0x0000000000000000 in ?? ()

追踪过程

理论上erlang不应该有那么大BUG. 问题大概率出现在我们使用的三方库上.汇总后有dyntrace,crypto,asn1rt_nif,Elixir.CBson,jiffy.三方的nif有CBson, jiffy, 因jiffy使用的人更多. 怀疑CBson.

通过被破坏的内存将范围限定在越界和野指针

见上面的现场分析，可能存在越界或野指针写坏了内存．从CBson开始，阅读代码未发现问题．

构造出CBson的coredump, 但和线上不吻合

并发encode/decode一些较大的随机生成数据, 能够有一定概率coredump, 调用栈如下, 发现是decode时，判断长度没有考虑负数．仔细阅读了decode代码，在bson字节流正确时，理论上不应该引发崩溃．

#0  0x00007febcdf0bb79 in decode_iter (env=0x7fec455bbd70, argc=<optimized out>, argv=0x7fec482041c0) at src/bson_decoder.c:516
#1  0x0000000000455158 in process_main () at x86_64-unknown-linux-gnu/opt/smp/beam_cold.h:119
#2  0x000000000044d80e in sched_thread_func (vesdp=0x7fec4668f180) at beam/erl_process.c:8349
#3  0x0000000000674cc9 in thr_wrapper (vtwd=0x7ffface81c50) at pthread/ethread.c:118
#4  0x00007fec895b76db in start_thread (arg=0x7fec455bc700) at pthread_create.c:463
#5  0x00007fec890d888f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

此外测试了如下情况:

• 和并发无关.
• 和decode的yield无关
• 和value binary大小无关.
• 和value binary是否随机无关.

erlang crash in instrument:allocations

因有相当多coredump都和erl_alloc相关. 查了erlang对erl_alloc的最近修改. 发现一个有意思的提交:

~/git/otp/erts/emulator/beam(a0ae44f*) » git log -p master erl_alloc*

commit 2193618f3524d6115693c8e710fffbdf9a68b533
Author: John Högberg <[e-mail]>
Date:   Mon Aug 12 15:09:17 2019 +0200

    erts: Fix crash in instrument:allocations/0-1
    
    The current carrier list was read when the allocator wasn't locked,
    crashing the emulator if a block scan raced with a carrier
    allocation

看起来能解释AOFF_RBTree_t问题. 可惜升级到erlang 21.3.8.9后, 仍然能够重现BUG.

构造了吻合线上coredump的用例

如果decode在bson字节流正确的情况下没有问题, 说明encode生成了错误的字节流. 经过验证发现. encode同样数据, 生成的字节流可能不一致. 尝试diff字节流寻找灵感, 因为字节流实在太大. 如果没有分析decode过程的工具, 无法简单地看出问题. 
接着尝试.

1. 单纯反复decode同一份数据.
2. 单纯反复encode同一份数据.

发现, 并发encode同一份数据, 能够在1-2MIN重现coredump. 而且调用栈极为近似.

定位到一个野指针bug

在范围更加缩小的情况下, 继续把encode代码再次过了一遍. 重点看memcpy, 指针写逻辑, 最终发现一个野指针. 可能改写一片已释放内存.

erlang nif的调试

程序在做什么

top -H

如，找到cpu %100的线程.

top -H -p 12229

Threads:  32 total,   1 running,  27 sleeping,   0 stopped,   0 zombie
%Cpu(s): 20.1 us,  3.9 sy,  0.0 ni, 75.2 id,  0.1 wa,  0.0 hi,  0.7 si,  0.0 st
KiB Mem : 32939792 total,  1596620 free, 19476236 used, 11866936 buff/cache
KiB Swap:        0 total,        0 free,        0 used. 12275476 avail Mem 

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND                                                                                                                                                                  
13760 root      20   0  9.836g 6.811g   2348 R 99.9 21.7  17782:37 8_dirty_cpu_sch                                                                                                                                                          
12229 root      20   0  9.836g 6.811g   2348 t  0.0 21.7   0:00.08 beam.smp                                                                                                                                                                 
13669 root      20   0  9.836g 6.811g   2348 S  0.0 21.7   0:00.02 sys_sig_dispatc 

pstack

....
Thread 2 (Thread 0x7fee70b3f700 (LWP 3863)):
#0  0x00007feeb2cb851d in read () at ../sysdeps/unix/syscall-template.S:84
#1  0x00000000005fd38c in read (__nbytes=4, __buf=0x7fee70b3eee0, __fd=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2  signal_dispatcher_thread_func (unused=<optimized out>) at sys/unix/sys.c:993
#3  0x0000000000674cf9 in thr_wrapper (vtwd=0x7fff9fbb3770) at pthread/ethread.c:118
#4  0x00007feeb2caf6ba in start_thread (arg=0x7fee70b3f700) at pthread_create.c:333
#5  0x00007feeb27dd41d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
Thread 1 (Thread 0x7feeb3a2d700 (LWP 3721)):
#0  0x00007feeb27d35d3 in select () at ../sysdeps/unix/syscall-template.S:84
#1  0x00000000005fe4f0 in erts_sys_main_thread () at sys/unix/sys.c:1140
#2  0x00000000004a8c3c in erl_start (argc=32, argv=<optimized out>) at beam/erl_init.c:2327
#3  0x00000000004518a9 in main (argc=<optimized out>, argv=<optimized out>) at sys/unix/erl_main.c:30

etp-stacktrace

可以在gdbinit里source etp-commands.in, 更方便地使用etp-stacktrace. 这样可以知道程序在erlang层在干什么.

~/git/elixir-cbson(dee7f1d*) » cat ~/.gdbinit                                                                                                                                enjolras@ubuntu
set target-async 1
set pagination off
set non-stop on
source /home/enjolras/git/otp/erts/etc/unix/etp-commands.in

(gdb) etp-stacktrace p
% Stacktrace (24)
#Cp<0x37d953d8>  (I)
#Cp<rand:seed_put/1+0x58>  (cp)
#Cp<rand:uniform/1+0x40>.
#Cp<'Elixir.Ejoy.Service.Discovery':get_service/2+0xe8>.
#Cp<'Elixir.Ejoy.Service.Discovery':'-get_service_by_names/2-fun-0-'/3+0x88>.
#Cp<'Elixir.Enum':'-reduce/3-lists^foldl/2-0-'/3+0x50>.
#Cp<'Elixir.Ejoy.Services.Client':call_game/3+0xc0>.
#Cp<'Elixir.Gangplank.Srpc':rpc/4+0x80>.
#Cp<'Elixir.OnlineCounter':get_count_subprocess/3+0x78>.
#Cp<terminate process normally>.

gdb

source /home/enjolras/git/otp/erts/etc/unix/etp-commands.in
可以使用一些更方便查看erlang内部结构的命令. 最好用是etp打印eterm, 比如打印atom.
各个语言都有类似的脚手架. 如cpython的cpython\Misc\gdbinit.

总结

野指针BUG的查找非常看运气. 关键在于如何重现BUG, 能够重现之后, 如何缩小BUG范围就是老生常谈了:

如何重现问题

分析现场. 阅读代码. 大胆假设, 细心验证.
如, 现场发现内存又被写坏. 而且不只一个地方被写坏. 那么堆上的越界/野指针是可能的.
erlang 的The current carrier list was read when the allocator wasn't locked, 可能导致allocator对应的数据结构被写坏, 但不可能导致ErtsRunQueue被写坏.
如, bug是随机二进制数据触发的吗? 字典中有随机二进制数据可触发BUG, 替换成固定字符串呢?
如, bug和encode包大小相关吗? 和yield相关吗? 和并发相关？
信息越多，就离重现／解决问题越近．

缩小BUG范围.

• Taints将范围缩小至特定几个库
• 构造不同的测试用例将范围缩小到部分逻辑. 
• 2分搜索最近提交.