Doris開發手記3:利用CoreDump文件快速定位Doris的查詢問題

Apache Doris的BE部分是由C++編寫,當出現一些記憶體越界,非法訪問的問題時會導致BE進程的Crash。這部分的問題常常較難排查,同時也很難快速定位到對應的觸發SQL,給使用者帶來較大的困擾。所以下面會介紹通過Linux的CoreDump快速定位到問題SQL,並復現問題的方式。

1.查看日誌

當BE進程Crash的時候,可以先查看be.out日誌,確認是否存在stack trace的記錄。當BE出現進程Crash的時,都會將運行時的堆棧列印到be.out文件中,一般如下圖所示:

image.png

但是由於這部分資訊並不完整,只能大致的幫助定位到可能的SQL查詢。所以需要進一步的通過CoreDump來定位到觸發BE Crash的查詢。

2. 如何生成CoreDump

  • 查看生成CoreDump文件的開關是否開啟,輸入命令ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 513562
max locked memory       (kbytes, -l) 64
max memory size         (kbytes, -m) unlimited
open files                      (-n) 10240
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 10240
cpu time               (seconds, -t) unlimited
max user processes              (-u) 513562
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

第一行core file size為0,則不會生成CoreDump。使用 ulimit -c [kbytes]命令可以設置系統允許生成的CoreDump的文件大小。

ulimit -c 1024            #設置CoreDump文件大小為1024k

ulimit -c unlimited      #不限制CoreDump文件大小   

執行命令 ulimit -c unlimited,這樣當BE進程Crash時就可以生成CoreDump文件。通過BE的start_be.sh腳本啟動BE時,腳本會自動設置ulimit的參數。由於CoreDump文件較大,默認情況下不會開啟CoreDump,所以這裡需要修改BE的啟動腳本。

chmod 755 ${DORIS_HOME}/lib/palo_be
echo "start time: "$(date) >> $LOG_DIR/be.out

#if [ ! -f /bin/limit3 ]; then
#    LIMIT=
#else
#    LIMIT="/bin/limit -c unlimited -n 65536"
#fi

ulimit -c unlimited -n 65536
if [ ${RUN_DAEMON} -eq 1 ]; then
    nohup $LIMIT ${DORIS_HOME}/lib/palo_be "$@" >> $LOG_DIR/be.out 2>&1 </dev/null &
else
    $LIMIT ${DORIS_HOME}/lib/palo_be "$@" >> $LOG_DIR/be.out 2>&1 </dev/null
fi

直接在啟動BE進程之前手動通過ulimit -c unlimited -n 65536的方式開啟CoreDump。

  • 指定生成CoreDump文件的路徑

默認情況下,CoreDump生成的文件名為core,而且就在運行啟動BE腳本目錄下,新生成的CoreDump文件會覆蓋舊的CoreDump文件。

而如果proc/sys/kernel/core_uses_pid內容為1,則CoreDump文件會以core.進程id的方式被生成。(這裡建議通過系統管理員將該開關打開)。

如果在運行啟動BE腳本目錄下沒有找到對應的CoreDump文件的話,可能是系統管理員修改了core_pattern

cat /proc/sys/kernel/core_pattern
/tmp/core_%t_%e_%p

這裡顯示CoreDump文件被core_pattern定義設置在了/tmp目錄下,所以需要到對應的目錄查找BE生成的CoreDump文件。

3.利用CoreDump定位問題Query

通過合理的配置之後,BE在Crash時就能正常生成CoreDump文件。利用GDB的打開CoreDump文件就能幫助我們取得對應的Query ID。

  • 使用GDB打開CoreDump文件
gdb be/lib/palo_be core.13610 

通常core文件會生成在BE進程的啟動目錄,但是如果額外配置過core-pattern,就得到對應的目錄上找到對應的coredump文件,然後通過gdb be的binary coredump來打開它。

  • 通過查詢棧索引到QueryID

打開之後,用bt命令展開堆棧,得到展開之後詳細的堆棧資訊

#0  0x00000000013957c6 in std::_Bit_reference::operator bool (this=<optimized out>) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/stl_bvector.h:916
#1  std::_Bit_const_iterator::operator* (this=<optimized out>) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/stl_bvector.h:348
#2  std::vector<bool, std::allocator<bool> >::operator[] (__n=<optimized out>, this=<optimized out>) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/stl_bvector.h:918
#3  doris::RowDescriptor::tuple_is_nullable (this=0xc39f343f8, tuple_idx=-2073834344) at ../src/runtime/descriptors.cpp:357
#4  0x000000000113ae73 in doris::SlotRef::prepare(doris::RuntimeState*, doris::RowDescriptor const&, doris::ExprContext*) () at ../src/exprs/slot_ref.cpp:100
#5  0x0000000001124a33 in doris::ExprContext::prepare(doris::RuntimeState*, doris::RowDescriptor const&, std::shared_ptr<doris::MemTracker> const&) () at ../src/exprs/expr_context.cpp:61
#6  0x000000000111b29e in doris::Expr::prepare(std::vector<doris::ExprContext*, std::allocator<doris::ExprContext*> > const&, doris::RuntimeState*, doris::RowDescriptor const&, std::shared_ptr<doris::MemTracker> const&) () at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/stl_vector.h:1061
#7  0x0000000001ae4233 in doris::ResultSink::prepare_exprs(doris::RuntimeState*) () at ../src/runtime/result_sink.cpp:57
#8  0x0000000001ae4a07 in doris::ResultSink::prepare(doris::RuntimeState*) () at ../src/runtime/result_sink.cpp:69
#9  0x000000000146691b in doris::PlanFragmentExecutor::prepare(doris::TExecPlanFragmentParams const&, doris::QueryFragmentsCtx const*) ()
    at /var/local/thirdparty/installed/include/boost/smart_ptr/scoped_ptr.hpp:109
#10 0x00000000013e033e in doris::FragmentExecState::prepare (this=this@entry=0xc8fc6a00, params=...) at ../src/runtime/fragment_mgr.cpp:229
#11 0x00000000013e4217 in doris::FragmentMgr::exec_plan_fragment(doris::TExecPlanFragmentParams const&, std::function<void (doris::PlanFragmentExecutor*)>) () at ../src/runtime/fragment_mgr.cpp:609
#12 0x00000000013e5e5d in doris::FragmentMgr::exec_plan_fragment(doris::TExecPlanFragmentParams const&) () at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/std_function.h:87
#13 0x00000000014ab4e4 in doris::PInternalServiceImpl<doris::PBackendService>::_exec_plan_fragment (this=this@entry=0x8e80ef00, ser_request=...) at ../src/runtime/exec_env.h:117
#14 0x00000000014ab59f in doris::PInternalServiceImpl<doris::PBackendService>::exec_plan_fragment (this=0x8e80ef00, cntl_base=<optimized out>, request=<optimized out>, response=0x8b1aa7c00,
    done=0x7fc493fc0) at /var/local/thirdparty/installed/include/google/protobuf/arenastring.h:231
#15 0x0000000002086c97 in brpc::policy::ProcessHttpRequest(brpc::InputMessageBase*) () at ../src/brpc/policy/http_rpc_protocol.cpp:1484
#16 0x00000000020540b7 in brpc::ProcessInputMessage (void_arg=void_arg@entry=0x3fd337d50) at ../src/brpc/input_messenger.cpp:135
#17 0x0000000002054f7e in brpc::RunLastMessage::operator() (last_msg=0x3fd337d50, this=<synthetic pointer>) at ../src/brpc/input_messenger.cpp:141
#18 std::unique_ptr<brpc::InputMessageBase, brpc::RunLastMessage>::~unique_ptr (this=<synthetic pointer>, __in_chrg=<optimized out>) at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:361
#19 brpc::InputMessenger::OnNewMessages(brpc::Socket*) () at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/unique_ptr.h:355
#20 0x00000000020fd52e in brpc::Socket::ProcessEvent(void*) () at ../src/brpc/socket.cpp:1017
#21 0x00000000021a5e6f in bthread::TaskGroup::task_runner(long) () at ../src/bthread/task_group.cpp:296
#22 0x0000000002197271 in bthread_make_fcontext () at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/stl_iterator.h:953
Backtrace stopped: Cannot access memory at address 0x7f644bcef000

doris::PlanFragmentExecutor的成員變數之中存儲了對應的_query_id,也就是執行這個查詢的全局唯一標識。我們可以看到,棧9上是doris::PlanFragmentExecutor的函數調用,所以通過f 9切換到棧9,並列印_query_id

(gdb) f 9
#9  0x000000000176d346 in doris::PlanFragmentExecutor::prepare (this=this@entry=0xcdf2cd8, request=..., fragments_ctx=<optimized out>)
    at /home/happen/mycode/baidu/bdg/doris/thirdparty-gcc10/installed/include/boost/smart_ptr/scoped_ptr.hpp:109
109	    T * get() const BOOST_SP_NOEXCEPT
(gdb) p _query_id
$1 = {_vptr.TUniqueId = 0x3e41ed8 <vtable for doris::TUniqueId+16>, hi = -374422143996836436, lo = -6672731362362486359}

這裡的query_id並不是我們真正需要的十六進位,所以還得繼續通過GDB列印對應的十六進位的query_id。

(gdb) p /x -374422143996836436
$2 = 0xfacdc90b370745ac

到此已經定位到對應的query_id了,需要到FE的之中通過十六進位的query_id來查找對應的Query,這裡的query_id, 不包括前面的0x。

通過FE的fe.audit.log搜索上文的facdc90b370745ac,由於FE對於查詢失敗的query有重試機制,所以這裡定位到重試的query_id: 9427f07d3c964dc8-b6bc0e004f52508f來最終定位到觸發問題的SQL為:select sum(cast(k9 as largeint)) from baseall

2021-07-11 18:46:32,098 [query] Query facdc90b370745ac-a365b22df8c691a9 1 times with new query id: 9427f07d3c964dc8-b6bc0e004f52508f
2021-07-11 18:46:32,100 [query] |Client=10.152.24.30:53143|User=root|Db=default_cluster:test|State=ERR|Time=257|ScanBytes=0|ScanRows=0|ReturnRows=0|StmtId=7|QueryId=9427f07d3c964dc8-b6bc0e004f52508f|IsQuery=true|feIp=10.152.24.30|Stmt=select sum(cast(k9 as largeint)) from baseall|CpuTimeMS=0

注意,由於可能存在多FE的情況,所以這裡可能需要查詢所有FE的fe.audit.log來搜索對應的query_id

到此,我們已經按圖索驥的找到觸發BE Crash的問題查詢了。接下來就是嘗試通過該查詢來複現問題,並分析原因,嘗試解決或規避問題查詢。當然,如果希望社區能夠提供幫助,可以將建表語句和脫敏過的數據提供給到社區的小夥伴們。

4.參考資料

Apache Doris源程式碼
100個GDB小技巧
函數調用知識