There should be memory leak in Doris

[kangkaisen]

Describe the bug
This picture is a mem.memfree.percent monitor for one Doris BE cluster having stream load

This week, I found a few BE down without stack trace or core dump. I used dmesg command found the reason:

[26421178.578265] Out of memory: Kill process 11543 (palo_be) score 941 or sacrifice child
[26421178.578842] Killed process 11543 (palo_be) total-vm:129318072kB, anon-rss:123827392kB, file-rss:0kB
[26421178.604663] palo_be: page allocation failure: order:0, mode:0x201da
[26421178.604666] CPU: 35 PID: 11543 Comm: palo_be Tainted: GF    U     O--------------   3.10.0-229.el7.x86_64 #1

So, I think Doris has memory leak issue.

This picture is a mem.memfree.percent monitor for two Doris BE cluster without stream load

So, I guess the memory leak issue is related with stream load

Additional context

Today I try debugging this issue with valgrind:

I add the following command to start_be.sh script and restart BE

nohup $LIMIT /usr/local/bin/valgrind --tool=memcheck --leak-check=full --log-file=mem-log --error-limit=no ${DORIS_HOME}/lib/palo_be

but only run several minutes， there is a core dump:

    ==24637== Process terminating with default action of signal 11 (SIGSEGV)
==24637==    at 0x242E191: tcmalloc::CentralFreeList::FetchFromOneSpans(int, void**, void**) (central_freelist.cc:298)
==24637==    by 0x242E47B: tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) (central_freelist.cc:282)
==24637==    by 0x242E576: tcmalloc::CentralFreeList::RemoveRange(void**, void**, int) (central_freelist.cc:264)
==24637==    by 0x243AA42: tcmalloc::ThreadCache::FetchFromCentralCache(unsigned int, int, void* (*)(unsigned long)) (thread_cache.cc:126)
==24637==    by 0x258C104: tcmalloc::allocate_full_cpp_throw_oom(unsigned long) (in /opt/meituan/palo/be/lib/palo_be)
==24637==    by 0xE6EF5B: doris::BRpcService::BRpcService(doris::ExecEnv*) (brpc_service.cpp:30)
==24637==    by 0xA45B7D: main (doris_main.cpp:162)

==24637== Invalid free() / delete / delete[] / realloc()
==24637==    at 0x4E3EF7D: free (vg_replace_malloc.c:530)
==24637==    by 0x5ADEB7B: __libc_freeres (in /usr/lib64/libc-2.17.so)
==24637==    by 0x4C38749: _vgnU_freeres (vg_preloaded.c:77)
==24637==    by 0x2363: ???
==24637==    by 0x242E47B: tcmalloc::CentralFreeList::FetchFromOneSpansSafe(int, void**, void**) (central_freelist.cc:282)
==24637==    by 0x242E576: tcmalloc::CentralFreeList::RemoveRange(void**, void**, int) (central_freelist.cc:264)
==24637==    by 0x243AA42: tcmalloc::ThreadCache::FetchFromCentralCache(unsigned int, int, void* (*)(unsigned long)) (thread_cache.cc:126)
==24637==    by 0x258C104: tcmalloc::allocate_full_cpp_throw_oom(unsigned long) (in /opt/meituan/palo/be/lib/palo_be)
==24637==    by 0xE6EF5B: doris::BRpcService::BRpcService(doris::ExecEnv*) (brpc_service.cpp:30)

The following is partial output for valgrind:

==5145== 164,080 bytes in 5 blocks are definitely lost in loss record 4,148 of 4,200
==5145==    at 0x4E3DE83: malloc (vg_replace_malloc.c:299)
==5145==    by 0x5A2F280: __alloc_dir (in /usr/lib64/libc-2.17.so)
==5145==    by 0xC87171: doris::OlapStore::_check_path_exist() (store.cpp:104)
==5145==    by 0xC8A273: doris::OlapStore::load() (store.cpp:86)
==5145==    by 0xC62021: doris::OLAPEngine::open() (olap_engine.cpp:290)
==5145==    by 0xC635CC: doris::OLAPEngine::open(doris::EngineOptions const&, doris::OLAPEngine**) (olap_engine.cpp:95)
==5145==    by 0xA45ADA: main (doris_main.cpp:138)



==5145== 128 bytes in 16 blocks are definitely lost in loss record 2,604 of 4,200
==5145==    at 0x4E3EB48: operator new[](unsigned long) (vg_replace_malloc.c:423)
==5145==    by 0x137AC7A: rocksdb::VersionStorageInfo::VersionStorageInfo(rocksdb::InternalKeyComparator const*, rocksdb::Comparat
or const*, int, rocksdb::CompactionStyle, rocksdb::VersionStorageInfo*, bool) (version_set.cc:1091)
==5145==    by 0x137B378: rocksdb::Version::Version(rocksdb::ColumnFamilyData*, rocksdb::VersionSet*, rocksdb::EnvOptions const&,
unsigned long) (version_set.cc:1149)
==5145==    by 0x137B470: rocksdb::VersionSet::CreateColumnFamily(rocksdb::ColumnFamilyOptions const&, rocksdb::VersionEdit*) (ver
sion_set.cc:4152)
==5145==    by 0x137EC64: rocksdb::VersionSet::Recover(std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::Column
FamilyDescriptor> > const&, bool) (version_set.cc:3175)
==5145==    by 0x132AF2C: rocksdb::DBImpl::Recover(std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFami
lyDescriptor> > const&, bool, bool, bool) (db_impl_open.cc:379)
==5145==    by 0x132BC9B: rocksdb::DBImpl::Open(rocksdb::DBOptions const&, std::__cxx11::basic_string<char, std::char_traits<char>
, std::allocator<char> > const&, std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > co
nst&, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> >*, rocksdb::DB**, bool) (db_impl_ope
n.cc:1067)
==5145==    by 0x132D552: rocksdb::DB::Open(rocksdb::DBOptions const&, std::__cxx11::basic_string<char, std::char_traits<char>, st
d::allocator<char> > const&, std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > const&
, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> >*, rocksdb::DB**) (db_impl_open.cc:1008)
==5145==    by 0xCFC9FB: doris::OlapMeta::init() (olap_meta.cpp:81)
==5145==    by 0xC89D3C: doris::OlapStore::_init_meta() (store.cpp:284)
==5145==    by 0xC8A470: doris::OlapStore::load() (store.cpp:97)
==5145==    by 0xC62021: doris::OLAPEngine::open() (olap_engine.cpp:290)



==5145== 63,521,561 bytes in 13,309 blocks are possibly lost in loss record 4,191 of 4,200
==5145==    at 0x4E3EB48: operator new[](unsigned long) (vg_replace_malloc.c:423)
==5145==    by 0x13E4ADB: rocksdb::UncompressBlockContentsForCompressionType(char const*, unsigned long, rocksdb::BlockContents*,
unsigned int, rocksdb::Slice const&, rocksdb::CompressionType, rocksdb::ImmutableCFOptions const&) (format.cc:286)
==5145==    by 0x13E4EA8: rocksdb::UncompressBlockContents(char const*, unsigned long, rocksdb::BlockContents*, unsigned int, rock
sdb::Slice const&, rocksdb::ImmutableCFOptions const&) (format.cc:393)
==5145==    by 0x13E0FD8: rocksdb::BlockFetcher::ReadBlockContents() (block_fetcher.cc:228)
==5145==    by 0x13CF46B: rocksdb::(anonymous namespace)::ReadBlockFromFile(rocksdb::RandomAccessFileReader*, rocksdb::FilePrefetc
hBuffer*, rocksdb::Footer const&, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, std::unique_ptr<rocksdb::Block, std::d
efault_delete<rocksdb::Block> >*, rocksdb::ImmutableCFOptions const&, bool, rocksdb::Slice const&, rocksdb::PersistentCacheOptions const&, unsigned long, unsigned long) (block_based_table_reader.cc:87)
==5145==    by 0x13D1BD0: rocksdb::BlockBasedTable::MaybeLoadDataBlockToCache(rocksdb::FilePrefetchBuffer*, rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::Slice, rocksdb::BlockBasedTable::CachableEntry<rocksdb::Block>*, bool, rocksdb::GetContext*) (block_based_table_reader.cc:1614)
==5145==    by 0x13D1EAB: rocksdb::BlockBasedTable::NewDataBlockIterator(rocksdb::BlockBasedTable::Rep*, rocksdb::ReadOptions const&, rocksdb::BlockHandle const&, rocksdb::BlockIter*, bool, rocksdb::GetContext*, rocksdb::Status) (block_based_table_reader.cc:1494)
==5145==    by 0x13D29BD: rocksdb::BlockBasedTableIterator::InitDataBlock() (block_based_table_reader.cc:1910)
==5145==    by 0x13D2C79: rocksdb::BlockBasedTableIterator::FindKeyForward() (block_based_table_reader.cc:1933)
==5145==    by 0x136F778: Next (iterator_wrapper.h:61)
==5145==    by 0x136F778: rocksdb::(anonymous namespace)::LevelIterator::Next() (version_set.cc:613)
==5145==    by 0x13F3F34: Next (iterator_wrapper.h:61)
==5145==    by 0x13F3F34: rocksdb::MergingIterator::Next() (merging_iterator.cc:202)
==5145==    by 0x14B68CE: rocksdb::DBIter::Next() (db_iter.cc:375)


==5145== LEAK SUMMARY:
==5145==    definitely lost: 164,518 bytes in 30 blocks
==5145==    indirectly lost: 0 bytes in 0 blocks
==5145==      possibly lost: 69,780,519 bytes in 41,474 blocks
==5145==    still reachable: 2,611,746,489 bytes in 32,280,429 blocks
==5145==                       of which reachable via heuristic:
==5145==                         newarray           : 7,304 bytes in 25 blocks
==5145==                         multipleinheritance: 20,328 bytes in 3 blocks
==5145==         suppressed: 0 bytes in 0 blocks
==5145== Reachable blocks (those to which a pointer was found) are not shown.
==5145== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==5145==
==5145== For counts of detected and suppressed errors, rerun with: -v
==5145== Use --track-origins=yes to see where uninitialised values come from
==5145== ERROR SUMMARY: 6163542 errors from 1204 contexts (suppressed: 0 from 0)

I am trying the HEAPCHECK tool.

[chaoyli]

OK, you can use address sanitizer or leak sanitizer to compile palo_be, which is native gcc memory check tools.

[chaoyli]

To use address sanitizer, only

export BUILD_TYPE=ASAN

will be ok.

[chaoyli]

To use leak sanitizer, you should

export BUILD_TYPE=LSAN

and also add this patch to doris_main.cpp

#include "sanitizer/lsan_interface.h"
while(true) {
    sleep(60);
    __lsan_do_leak_check();
}

[chaoyli]

Address sanitizer is super set of Leak sanitizer, but consumes more memory.
You can try it.

[kangkaisen]

@chaoyli OK, thanks you! I will try.

[imay]

@kangkaisen
Normally Doris is built with tcmalloc, which is part of gperftools. When tcmalloc is used, valgrind isn't correct, because tcmalloc will manage memory itself.

You can use method as @chaoyli said. When LSAN is enable, if there is memory leak, information would be written to be.out.

In addition, if this flag is enable, performance will decrease and virtual memory will increase.

[kangkaisen]

@imay OK, I see. Thanks you.

[kangkaisen]

After @imay reminded, I found the _tablets_channels in TabletWriterMgr have memory leak.

W0309 17:57:55.167860 16631 tablet_writer_mgr.cpp:254] add key: (id=0D48E94A8C810F5B:B160B9E5318D72AB,index_id=3378242)
W0309 17:57:55.169076 16631 tablet_writer_mgr.cpp:255] channels size: 1695
W0309 17:57:55.170675 16651 tablet_writer_mgr.cpp:254] add key: (id=0D48E94A8C810F5B:B160B9E5318D72AB,index_id=3378283)
W0309 17:57:55.170835 16651 tablet_writer_mgr.cpp:255] channels size: 1696
W0309 17:57:55.199170 16644 tablet_writer_mgr.cpp:301] add_batch erase key: (id=0D48E94A8C810F5B:B160B9E5318D72AB,index_id=3378242
)
W0309 17:57:55.218492 16640 tablet_writer_mgr.cpp:301] add_batch erase key: (id=0D48E94A8C810F5B:B160B9E5318D72AB,index_id=3378283
)
W0309 17:57:55.324714 16630 tablet_writer_mgr.cpp:254] add key: (id=BD495FD379FEA718:5C3FA46F9A8ABAAB,index_id=3399270)
W0309 17:57:55.324998 16630 tablet_writer_mgr.cpp:255] channels size: 1695

[kangkaisen]

This issue need to reopen.

After I apply #718 and add log to TabletWriterMgr and LoadStreamMgr.

I find there is still memory leak and no memory leak in TabletWriterMgr and very very little memory leak in LoadStreamMgr.

W0321 11:34:00.352984 29291 tablet_writer_mgr.cpp:349] _tablets_channels size: 0
W0321 11:34:01.386181 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:09.973639 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:17.246053 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:19.745262 29283 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:21.754983 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:25.010174 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:36.844310 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:50.067078 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:51.429908 29287 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:54.800222 29283 load_stream_mgr.h:43] _stream_map size: 2
W0321 11:34:56.438650 29287 load_stream_mgr.h:43] _stream_map size: 2

[kangkaisen]

Just now, I compile Doris BE with BUILD_TYPE=LSAN. After BE start, the log is following:

==188287==ERROR: LeakSanitizer: detected memory leaks

Direct leak of 262528 byte(s) in 8 object(s) allocated from:
    #0 0xb40b46 in __interceptor_malloc ../../../../libsanitizer/lsan/lsan_interceptors.cc:53
    #1 0x7fb3e39a79c0 in __alloc_dir (/lib64/libc.so.6+0xc09c0)

SUMMARY: LeakSanitizer: 262528 byte(s) leaked in 8 allocation(s).
./start_be.sh: line 58: kill: (188287) - No such process
start time: Thu Mar 21 11:39:56 CST 2019
I0100 00:00:00.000000 189239 vlog_is_on.cc:192] RAW: Set VLOG level for "*" to 10

I think the detected result of LeakSanitizer is strange.

[chaoyli]

I also have not meets this problem. May be doris_main has memory leak in start thread?

[kangkaisen]

2160.pdf

1000_obt.pdf
2750_obt.pdf