Debug Tool

    Fe is a java process. Here are just a few simple and commonly used java debugging commands.

    1. Statistics of current memory usage details

      This command can enumerate and sort the memory occupation of living objects. (replace PID with Fe process ID)

      2. ----------------------------------------------
      3. 1:         33528       10822024  [B
      4. 2:         80106        8662200  [C
      5. 3:           143        4688112  [Ljava.util.concurrent.ForkJoinTask;
      6. 4:         80563        1933512  java. lang.String
      7. 5:         15295        1714968  java. lang.Class
      8. 6:         45546        1457472  java. util. concurrent. ConcurrentHashMap$Node
      9. 7:         15483        1057416  [Ljava.lang.Object;

      You can use this method to view the total memory occupied by the currently living objects (at the end of the file) and analyze which objects occupy more memory.

      Note that this method will trigger fullgc because `: live ‘is specified.

    2. Check JVM memory usage

      1. jstat -gcutil pid 1000 1000

      This command can scroll through the memory usage of each region of the current JVM. (replace PID with Fe process ID)

      1. S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT
      2. 0.00   0.00  22.61   3.03  95.74  92.77     68    1.249     5    0.794    2.043
      3. 0.00   0.00  22.61   3.03  95.74  92.77     68    1.249     5    0.794    2.043
      4. 0.00   0.00  22.61   3.03  95.74  92.77     68    1.249     5    0.794    2.043
      5. 0.00   0.00  22.92   3.03  95.74  92.77     68    1.249     5    0.794    2.043
      6. 0.00   0.00  22.92   3.03  95.74  92.77     68    1.249     5    0.794    2.043

      The main focus is on the percentage of old area (o) (3% in the example). If the occupancy is too high, oom or fullgc may occur.

    3. Print Fe thread stack

      1. jstack -l pid > 1. js

      This command can print the thread stack of the current Fe. (replace PID with Fe process ID). -L the parameter will detect whether there is deadlock at the same time. This method can check the operation of Fe thread, whether there is deadlock, where it is stuck, etc.

    BE debugging

    : from gperftools, it is used to transform the content generated by gperftools into a format that is easy for people to read, such as PDF, SVG, text, etc.

    graphvizDebug Tool - 图2 (opens new window): in the absence of this library, pprof can only be converted to text format, but this way is not easy to view. After the library is installed, pprof can be converted to SVG, PDF and other formats, and the call relationship is clearer.

    : Linux kernel comes with performance analysis tool. hereDebug Tool - 图4 (opens new window) there are some examples of perf usage.

    : a visualization tool used to show the output of perf in the form of flame graph.

    Debugging memory is generally divided into two aspects. One is whether the total amount of memory use is reasonable. On the one hand, the excessive amount of memory use may be due to memory leak in the system, on the other hand, it may be due to improper use of program memory. The second is whether there is a problem of memory overrun and illegal access, such as program access to memory with an illegal address, use of uninitialized memory, etc. For the debugging of memory, we usually use the following ways to track the problems.

    Log

    When we find that the memory usage is too large, we can first check the be.out log to see if there is a large memory application. Because of the TCMalloc currently used by Doris to manage memory, when a large memory application is encountered, the stack of the application will be printed to the be.out file. The general form is as follows:

    1. tcmalloc: large alloc 1396277248 bytes == 0x3f3488000 @  0x2af6f63 0x2c4095b 0x134d278 0x134bdcb 0x133d105 0x133d1d0 0x19930ed
    1. $ addr2line -e lib/palo_be  0x2af6f63 0x2c4095b 0x134d278 0x134bdcb 0x133d105 0x133d1d0 0x19930ed
    3. /home/ssd0/zc/palo/doris/core/thirdparty/src/gperftools-gperftools-2.7/src/tcmalloc.cc:1335
    4. /home/ssd0/zc/palo/doris/core/thirdparty/src/gperftools-gperftools-2.7/src/tcmalloc.cc:1357
    5. /home/disk0/baidu-doris/baidu/bdg/doris-baidu/core/be/src/exec/hash_table.cpp:267
    6. /home/disk0/baidu-doris/baidu/bdg/doris-baidu/core/be/src/exec/hash_join_node.cpp:239
    7. /home/disk0/baidu-doris/baidu/bdg/doris-baidu/core/be/src/exec/hash_join_node.cpp:213
    8. thread.cpp:?

    HEAP PROFILE

    Sometimes the application of memory is not caused by the application of large memory, but by the continuous accumulation of small memory. Then there is no way to locate the specific application information by viewing the log, so you need to get the information through other ways.

    At this time, we can take advantage of TCMalloc’s heapprofileDebug Tool - 图6 (opens new window). If the heapprofile function is set, we can get the overall memory application usage of the process. The usage is to set the ‘heapprofile’ environment variable before starting Doris be. For example:

    In this way, when the dump condition of the heapprofile is met, the overall memory usage will be written to the file in the specified path. Later, we can use the ‘pprof’ tool to analyze the output content.

    1. $ pprof --text lib/palo_be /tmp/doris_be.hprof.0012.heap | head -30
    3. Using local file lib/palo_be.
    4. Using local file /tmp/doris_be.hprof.0012.heap.
    5. Total: 668.6 MB
    6.    610.6  91.3%  91.3%    610.6  91.3% doris::SystemAllocator::allocate_via_malloc (inline)
    7.     18.1   2.7%  94.0%     18.1   2.7% _objalloc_alloc
    9.      5.1   0.8%  95.6%      7.1   1.1% butil::ResourcePool::add_block (inline)
    10.      3.7   0.5%  96.2%      3.7   0.5% butil::iobuf::create_block (inline)
    11.      3.4   0.5%  96.7%      3.4   0.5% butil::FlatMap::init
    12.      3.2   0.5%  97.2%      5.2   0.8% butil::ObjectPool::add_block (inline)
    13.      2.6   0.4%  97.6%      2.6   0.4% __gnu_cxx::new_allocator::allocate (inline)
    14.      2.0   0.3%  97.9%      2.0   0.3% butil::ObjectPool::add_block_group (inline)
    15.      2.0   0.3%  98.2%      2.0   0.3% butil::ResourcePool::add_block_group (inline)
    16.      1.7   0.3%  98.4%      1.7   0.3% doris::SegmentReader::_load_index

    Contents of each column of the above documents:

    • Column 1: the memory size directly applied by the function, in MB
    • Column 4: the total memory size of the function and all the functions it calls.
    • The second column and the fifth column are the proportion values of the first column and the fourth column respectively.
    • The third column is the cumulative value of the second column.

    Of course, it can also generate call relation pictures, which is more convenient for analysis. For example, the following command can generate a call graph in SVG format.

    1. pprof --svg lib/palo_be /tmp/doris_be.hprof.0012.heap > heap.svg

    NOTE: turning on this option will affect the execution performance of the program. Please be careful to turn on the online instance.

    pprof remote server

    Although heapprofile can get all the memory usage information, it has some limitations. 1. Restart be. 2. You need to enable this command all the time, which will affect the performance of the whole process.

    For Doris be, you can also use the way of opening and closing the heap profile dynamically to analyze the memory application of the process. Doris supports the remote server debugging of gperftools (opens new window). Then you can use ‘pprof’ to directly perform dynamic head profile on the remote running Doris be. For example, we can check the memory usage increment of Doris through the following command

    1. $ pprof --text --seconds=60 http://be_host:be_webport/pprof/heap 
    3. Total: 1296.4 MB
    4.    484.9  37.4%  37.4%    484.9  37.4% doris::StorageByteBuffer::create
    5.    272.2  21.0%  58.4%    273.3  21.1% doris::RowBlock::init
    6.    157.5  12.1%  70.5%    157.5  12.1% doris::RowBatch::RowBatch
    7.     90.7   7.0%  77.5%     90.7   7.0% doris::SystemAllocator::allocate_via_malloc
    8.     66.6   5.1%  82.7%     66.6   5.1% doris::IntegerColumnReader::init
    9.     47.9   3.7%  86.4%     47.9   3.7% __gnu_cxx::new_allocator::allocate
    10.     20.8   1.6%  88.0%     35.4   2.7% doris::SegmentReader::_load_index
    11.     12.7   1.0%  89.0%     12.7   1.0% doris::DecimalColumnReader::init
    12.     12.7   1.0%  89.9%     12.7   1.0% doris::LargeIntColumnReader::init
    13.     12.7   1.0%  90.9%     12.7   1.0% doris::StringColumnDirectReader::init
    14.     12.3   0.9%  91.9%     12.3   0.9% std::__cxx11::basic_string::_M_mutate
    15.     10.0   0.8%  93.4%     10.0   0.8% doris::PlainTextLineReader::PlainTextLineReader

    The output of this command is the same as the output and view mode of heap profile, which will not be described in detail here. Statistics will be enabled only during execution of this command, which has a limited impact on process performance compared with heap profile.

    LSAN

    LSANDebug Tool - 图8 (opens new window) is an address checking tool, GCC has been integrated. When we compile the code, we can enable this function by turning on the corresponding compilation options. When the program has a determinable memory leak, it prints the leak stack. Doris be has integrated this tool, only need to compile with the following command to generate be binary with memory leak detection version.

    1. BUILD_TYPE=LSAN ./build.sh

    When the system detects a memory leak, it will output the corresponding information in be. Out. For the following demonstration, we intentionally insert a memory leak code into the code. We insert the following code into the open function of StorageEngine.

    1.     char* leak_buf = new char[1024];
    2.     strcpy(leak_buf, "hello world");
    3.     LOG(INFO) << leak_buf;

    We get the following output in be.out

    1. =================================================================
    2. ==24732==ERROR: LeakSanitizer: detected memory leaks
    5.     #0 0xd10586 in operator new[](unsigned long) ../../../../gcc-7.3.0/libsanitizer/lsan/lsan_interceptors.cc:164
    6.     #1 0xe333a2 in doris::StorageEngine::open(doris::EngineOptions const&, doris::StorageEngine**) /home/ssd0/zc/palo/doris/core/be/src/olap/storage_engine.cpp:104
    7.     #2 0xd3cc96 in main /home/ssd0/zc/palo/doris/core/be/src/service/doris_main.cpp:159
    8.     #3 0x7f573b5eebd4 in __libc_start_main (/opt/compiler/gcc-4.8.2/lib64/libc.so.6+0x21bd4)
    10. SUMMARY: LeakSanitizer: 1024 byte(s) leaked in 1 allocation(s).

    From the above output, we can see that 1024 bytes have been leaked, and the stack information of memory application has been printed out.

    NOTE: turning on this option will affect the execution performance of the program. Please be careful to turn on the online instance.

    NOTE: if the LSAN switch is turned on, the TCMalloc will be automatically turned off

    ASAN

    Except for the unreasonable use and leakage of memory. Sometimes there will be memory access illegal address and other errors. At this time, we can use ASAN (opens new window) to help us find the cause of the problem. Like LSAN, ASAN is integrated into GCC. Doris can open this function by compiling as follows

    1.     char* invalid_buf = new char[1024];
    2.     for (int i = 0; i < 1025; ++i) {
    3.         invalid_buf[i] = i;
    4.     }
    5.     LOG(INFO) << invalid_buf;

    We get the following output in be.out

    1. =================================================================
    2. ==23284==ERROR: AddressSanitizer: heap-buffer-overflow on address 0x61900008bf80 at pc 0x00000129f56a bp 0x7fff546eed90 sp 0x7fff546eed88
    3. WRITE of size 1 at 0x61900008bf80 thread T0
    4.     #0 0x129f569 in doris::StorageEngine::open(doris::EngineOptions const&, doris::StorageEngine**) /home/ssd0/zc/palo/doris/core/be/src/olap/storage_engine.cpp:106
    5.     #1 0xe2c1e3 in main /home/ssd0/zc/palo/doris/core/be/src/service/doris_main.cpp:159
    6.     #2 0x7fa5580fbbd4 in __libc_start_main (/opt/compiler/gcc-4.8.2/lib64/libc.so.6+0x21bd4)
    7.     #3 0xd30794  (/home/ssd0/zc/palo/doris/core/output3/be/lib/palo_be+0xd30794)
    9. 0x61900008bf80 is located 0 bytes to the right of 1024-byte region [0x61900008bb80,0x61900008bf80)
    10. allocated by thread T0 here:
    11.     #0 0xdeb040 in operator new[](unsigned long) ../../../../gcc-7.3.0/libsanitizer/asan/asan_new_delete.cc:82
    12.     #1 0x129f50d in doris::StorageEngine::open(doris::EngineOptions const&, doris::StorageEngine**) /home/ssd0/zc/palo/doris/core/be/src/olap/storage_engine.cpp:104
    13.     #2 0xe2c1e3 in main /home/ssd0/zc/palo/doris/core/be/src/service/doris_main.cpp:159
    14.     #3 0x7fa5580fbbd4 in __libc_start_main (/opt/compiler/gcc-4.8.2/lib64/libc.so.6+0x21bd4)
    16. SUMMARY: AddressSanitizer: heap-buffer-overflow /home/ssd0/zc/palo/doris/core/be/src/olap/storage_engine.cpp:106 in doris::StorageEngine::open(doris::EngineOptions const&, doris::StorageEngine**)

    From this message, we can see that at the address of 0x61900008bf80, we tried to write a byte, but this address is illegal. We can also see the application stack of the address [0x61900008bb80, 0x61900008bf80].

    NOTE: turning on this option will affect the execution performance of the program. Please be careful to turn on the online instance.

    NOTE: if the ASAN switch is turned on, the TCMalloc will be automatically turned off

    In addition, if stack information is output in be.out, but there is no function symbol, then we need to handle it manually to get readable stack information. The specific processing method needs a script to parse the output of ASAN. At this time, we need to use to help with parsing. The specific usage is as follows:

    1. cat be.out | python asan_symbolize.py | c++filt

    With the above command, we can get readable stack information.

    When the CPU idle of the system is very low, it means that the CPU of the system has become the main bottleneck. At this time, it is necessary to analyze the current CPU usage. For the be of Doris, there are two ways to analyze the CPU bottleneck of Doris.

    pprof

    Because Doris has integrated and compatible with GPERF rest interface, users can analyze remote Doris be through the ‘pprof’ tool. The specific usage is as follows:

    1. pprof --svg --seconds=60 http://be_host:be_webport/pprof/profile > be.svg

    In this way, a CPU consumption graph of be execution can be generated.

    perf + flamegragh

    This is a quite common CPU analysis method. Compared with pprof, this method must be able to log in to the physical machine of the analysis object. However, compared with pprof, which can only collect points on time, perf can collect stack information through different events. The specific usage is as follows:

      This command counts the CPU operation of be for 60 seconds and generates perf.data. For the analysis of perf.data, the command of perf can be used for analysis.

      1. perf report

      The analysis results in the following pictures

      Perf Report

      To analyze the generated content. Of course, you can also use flash graph to complete the visual display.

      This will also generate a graph of CPU consumption at that time.