概述
最近半年, 經常出現一些奇怪的bug.
CPU非常高, 但etop并沒有red特别高的程序.
記憶體占用非常高, 和etop看到的記憶體不吻合.
coredump.
因為erlang層面無法定位問題, 那問題隻能在c了.
BUG現場
cpu %100
ErtsRunQueue被寫壞
#0 sched_prep_cont_spin_wait (ssi=) at beam/erl_process.c:2947
#1 scheduler_wait (fcalls=, rq=, 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, [email protected]=0x7f0c9c6000e8, blk=0x7f0c9c605a58) at beam/erl_ao_firstfit_alloc.c:796
#1 0x00000000005e8a42 in aoff_link_free_block (allctr=, block=) at beam/erl_ao_firstfit_alloc.c:750
#2 0x000000000049b444 in mbc_free (allctr=0x22e90c0, p=, busy_pcrr_pp=0x7f0c98376a30) at beam/erl_alloc_util.c:2579
#3 0x000000000049be8f in dealloc_block ([email protected]=0x22e90c0, [email protected]=0x7f0c9c605a60, [email protected]=0x0, dec_cc_on_re[email protected]=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=, thr_prgr_p=, need_thr_progress=0x7f0c98376b28, ops_limit=20, use_limit=, allctr_locked=0, allctr=0x22e90c0) at beam/erl_alloc_util.c:2174
#6 erts_alcu_check_delayed_dealloc (allctr=0x22e90c0, [email protected]=1, [email protected]=0x7f0c98376b28, thr_prgr_p=thr_prgr_p@entry=0x7f0c98376b30, [email protected]=0x7f0c98376b2c)
at beam/erl_alloc_util.c:2276
#7 0x000000000048df73 in erts_alloc_scheduler_handle_delayed_dealloc (vesdp=0x7f0c9a56dcc0, [email protected]=0x7f0c98376b28, [email protected]=0x7f0c98376b30,
mo[email protected]=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 ([email protected]=0x7f0c9a56ddd8, orig_aux_work=orig_aux_w[email protected]=4, [email protected]=1) at beam/erl_process.c:2596
#10 0x0000000000460ced in scheduler_wait (fcalls=, rq=, 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.
#Cp<0x9c0d3510>.
#Cp.
#Cp.
#Cp.
#Cp.
#Cp<0x9c02b7a0>.
#Cp<0x827211d8>.
#Cp.
#Cp.
#Cp.
#Cp.
coredump
如下兩個coredump較為典型.
#0 0x00000000005e7a7b in lower_max_size (stop_at=0x0, node=0x7eff735b2d68) at beam/erl_ao_firstfit_alloc.c:161
#1 rbt_delete ([email protected]=0x7eff735800e8, del=0x7eff735bc2f8) at beam/erl_ao_firstfit_alloc.c:617
#2 0x00000000005e826e in aoff_unlink_free_block (allctr=, blk=) at beam/erl_ao_firstfit_alloc.c:548
#3 0x00000000005e84aa in aoff_get_free_block (allctr=, size=, cand_blk=, cand_size=) at beam/erl_ao_firstfit_alloc.c:911
#4 0x0000000000499191 in create_carrier ([email protected]=0xb0bdc0, [email protected]=65544, flags=, [email protected]=2) at beam/erl_alloc_util.c:3921
#5 0x000000000049a700 in mbc_alloc_block (blk_szp=, 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=, 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=, source=, sourceLen=, level=) at beam/erl_zlib.c:60
#11 0x000000000053cf9f in erts_term_to_binary_int ([email protected]=0x7effecf00438, Term=, level=, flags=, context_b=0x7eff73a438f8, [email protected]=0x0) at beam/external.c:2049
#12 0x000000000053f7b2 in term_to_binary_2 (A__p=0x7effecf00438, BIF__ARGS=, A__I=) 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=, root=) at beam/erl_ao_firstfit_alloc.c:476
#1 rbt_insert (order=FF_BF, [email protected]=0x7f0b7ad400e8, blk=0x7f0b7ad775d8) at beam/erl_ao_firstfit_alloc.c:830
#2 0x00000000005e8a42 in aoff_link_free_block (allctr=, block=) 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=, org_blk_sz=, blk=0x7f0b7ad6f9f0, allctr=0x1cb1dc0) at beam/erl_alloc_util.c:2421
#4 mbc_alloc (allctr=0x1cb1dc0, size=) at beam/erl_alloc_util.c:2487
#5 0x00000000004a1491 in erts_alcu_alloc_thr_pref (type=86, extra=, 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 ([email protected]=1) at beam/beam_ranges.c:131
#8 0x0000000000486a4a in erts_start_staging_code_ix ([email protected]=1) at beam/code_ix.c:74
#9 0x000000000047aca8 in finish_loading_1 (A__p=0x7f0be94c1e38, BIF__ARGS=, A__I=) 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=, 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
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過程的工具, 無法簡單地看出問題.
接着嘗試.
單純反複decode同一份資料.
單純反複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=) at /usr/include/x86_64-linux-gnu/bits/unistd.h:44
#2 signal_dispatcher_thread_func (unused=) 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=) at beam/erl_init.c:2327
#3 0x00000000004518a9 in main (argc=, argv=) at sys/unix/erl_main.c:30
etp-stacktrace
可以在gdbinit裡source etp-commands.in, 更友善地使用etp-stacktrace. 這樣可以知道程式在erlang層在幹什麼.
~/git/elixir-cbson(dee7f1d*) » cat ~/.gdbinit [email protected]
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 (cp)
#Cp.
#Cp.
#Cp.
#Cp.
#Cp.
#Cp.
#Cp.
#Cp.
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分搜尋最近送出.