CPU idle is still high when concurrent access is high #1726
Description
When there is high concurrent access to Doris, our BE CPU idle is still high. If we increase the concurrence, the latency increase but the CPU idle is still high.
When I see the backend stack, I saw some stack like this.
#0 0x00007fc5f1a3af4d in __lll_lock_wait () from /lib64/libpthread.so.0
#1 0x00007fc5f1a36d02 in _L_lock_791 () from /lib64/libpthread.so.0
#2 0x00007fc5f1a36c08 in pthread_mutex_lock () from /lib64/libpthread.so.0
#3 0x000000000233d6e6 in pthread_mutex_lock_impl (mutex=0x3227c128) at /var/local/incubator-doris/thirdparty/src/incubator-brpc-0.9.5/src/bthread/mutex.cpp:551
#4 pthread_mutex_lock (__mutex=__mutex@entry=0x3227c128) at /var/local/incubator-doris/thirdparty/src/incubator-brpc-0.9.5/src/bthread/mutex.cpp:809
#5 0x0000000000ef72e8 in pthread_mutex_lock (m=0x3227c128) at /var/local/thirdparty/installed/include/boost/thread/pthread/mutex.hpp:62
#6 boost::mutex::lock (this=0x3227c128) at /var/local/thirdparty/installed/include/boost/thread/pthread/mutex.hpp:116
#7 0x0000000000ef73ef in boost::unique_lock<boost::mutex>::lock (this=0x7fc38d344fa0) at /var/local/thirdparty/installed/include/boost/thread/lock_types.hpp:346
#8 0x000000000133e4bb in unique_lock (m_=..., this=0x7fc38d344fa0) at /var/local/thirdparty/installed/include/boost/thread/lock_types.hpp:124
#9 doris::OlapScanNode::scanner_thread (this=0x3227bb00, scanner=0x10568840) at /root/incubator-doris-DORIS-0.10.13-release/be/src/exec/olap_scan_node.cpp:1216
#10 0x0000000000efab36 in operator() (this=0x7fc38d345038) at /var/local/thirdparty/installed/include/boost/function/function_template.hpp:759
#11 doris::PriorityThreadPool::work_thread (this=0x683c300, thread_id=<optimized out>) at /root/incubator-doris-DORIS-0.10.13-release/be/src/util/priority_thread_pool.hpp:134
#12 0x000000000197073d in thread_proxy ()
#13 0x00007fc5f1a34dc5 in start_thread () from /lib64/libpthread.so.0
#14 0x00007fc5f1d3fced in clone () from /lib64/libc.so.6
and this
#0 0x0000000002ad7240 in tcmalloc::CentralFreeList::ReleaseToSpans (this=this@entry=0x4b90960 <tcmalloc::Static::central_cache_+62016>, object=0x26e33000) at src/central_freelist.cc:110
#1 0x0000000002ad73ab in tcmalloc::CentralFreeList::ReleaseListToSpans (this=this@entry=0x4b90960 <tcmalloc::Static::central_cache_+62016>, start=<optimized out>, start@entry=0x26e33000) at src/central_freelist.cc:85
#2 0x0000000002ad7687 in tcmalloc::CentralFreeList::InsertRange (this=0x4b90960 <tcmalloc::Static::central_cache_+62016>, start=0x26e33000, end=0x2da1e000, N=<optimized out>) at src/central_freelist.cc:243
#3 0x0000000002ae41ce in tcmalloc::ThreadCache::ReleaseToCentralCache (this=this@entry=0x63c7800, src=src@entry=0x63c7e60, cl=cl@entry=51, N=4) at src/thread_cache.cc:207
#4 0x0000000002ae4497 in tcmalloc::ThreadCache::Scavenge (this=0x63c7800) at src/thread_cache.cc:224
#5 0x0000000000f128e6 in doris::MemPool::~MemPool (this=0xfe2f380, __in_chrg=<optimized out>) at /root/incubator-doris-DORIS-0.10.13-release/be/src/runtime/mem_pool.cpp:62
#6 0x0000000000ea3677 in operator() (this=<optimized out>, __ptr=0xfe2f380) at /usr/include/c++/7.3.0/bits/unique_ptr.h:78
#7 ~unique_ptr (this=0x15e93368, __in_chrg=<optimized out>) at /usr/include/c++/7.3.0/bits/unique_ptr.h:268
#8 doris::SegmentReader::~SegmentReader (this=0x15e93000, __in_chrg=<optimized out>) at /root/incubator-doris-DORIS-0.10.13-release/be/src/olap/segment_reader.cpp:77
#9 0x0000000000e6dfdc in doris::ColumnData::~ColumnData (this=0x27af0c00, __in_chrg=<optimized out>) at /root/incubator-doris-DORIS-0.10.13-release/be/src/olap/column_data.cpp:59
#10 0x0000000000df85d8 in doris::OLAPTable::release_data_sources (this=<optimized out>, data_sources=data_sources@entry=0x125b1110) at /root/incubator-doris-DORIS-0.10.13-release/be/src/olap/olap_table.cpp:522
#11 0x0000000000e217a8 in doris::Reader::close (this=this@entry=0x125b1080) at /root/incubator-doris-DORIS-0.10.13-release/be/src/olap/reader.cpp:472
#12 0x0000000000e22173 in doris::Reader::~Reader (this=0x125b1080, __in_chrg=<optimized out>) at /root/incubator-doris-DORIS-0.10.13-release/be/src/olap/reader.cpp:300
#13 0x0000000001366382 in operator() (this=<optimized out>, __ptr=0x125b1080) at /usr/include/c++/7.3.0/bits/unique_ptr.h:78
#14 reset (__p=0x125b1080, this=0x68445cd0) at /usr/include/c++/7.3.0/bits/unique_ptr.h:376
#15 doris::OlapScanner::close (this=this@entry=0x68445b80, state=0xd5ebb600) at /root/incubator-doris-DORIS-0.10.13-release/be/src/exec/olap_scanner.cpp:481
#16 0x000000000133e7c3 in doris::OlapScanNode::scanner_thread (this=0x2c1a4d00, scanner=0x68445b80) at /root/incubator-doris-DORIS-0.10.13-release/be/src/exec/olap_scan_node.cpp:1248
#17 0x0000000000efab36 in operator() (this=0x7fc36d33d038) at /var/local/thirdparty/installed/include/boost/function/function_template.hpp:759
#18 doris::PriorityThreadPool::work_thread (this=0x683c300, thread_id=<optimized out>) at /root/incubator-doris-DORIS-0.10.13-release/be/src/util/priority_thread_pool.hpp:134
#19 0x000000000197073d in thread_proxy ()
#20 0x00007fc5f1a34dc5 in start_thread () from /lib64/libpthread.so.0
#21 0x00007fc5f1d3fced in clone () from /lib64/libc.so.6
So the problem is that the first scanner is waiting the second scanner because the second scanner holds the lock. The second scanner want to free the finished scanner, so that it would release memory which scanner used. This memory is so big that will be returned to TcMalloc's central pool, which need the lock of tcmalloc, which may cause wait.