Actions
Bug #35998
closedceph-mgr active daemon memory leak since mimic
Added by Tomasz Sętkowski over 5 years ago. Updated about 5 years ago.
Status:
Resolved
Priority:
Urgent
Assignee:
-
Category:
ceph-mgr
Target version:
-
% Done:
0%
Source:
Community (user)
Tags:
Backport:
Regression:
Yes
Severity:
2 - major
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
Crash signature (v1):
Crash signature (v2):
Description
I am pretty sure I have been seeing memory leak like pattern on active ceph-mgr daemon since I have upgraded cluster to mimic v13.2.0 from luminous.
I have attached a screenshot from memory graph on the host with active mgr. After a few hours it can use few GB of RAM. It grows linearly until restarted.
I am building ceph from source, the official release v13.2.0 with additional parameter in CMAKE to use jemalloc (-DALLOCATOR=jemalloc).
Deployment with openstack-kolla project. Each daemon is running in docker with -net host.
Cluster is operational, although I am seeing exactly 240 messages per minute like this from host with active mgr:
-- 192.168.200.49:6802/7 >> 192.168.200.41:0/7 conn(0x7f77f7b21d00 :6802 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=1).handle_connect_msg accept replacing existing (lossy) channel (new one lossy=1)
There was definitely no such leak or log messages in luminous.
I have found a few sources saying this message is normal. Although I wonder if it is still normal at rate of 240/min? Considering that cluster is small - it has only 8 OSDs, 3 MONs, 3 MGRs.
I could debug this further, but please provide some tips on how to approach it.
Can I safely run ceph-mgr with valgrind in production, would it help at all?
Or should I definitely reproduce this somehow on a development built?
I can deploy a small cluster on VMs too, which is using all the same tools as production.
Files
| ceph_mgr_leak.png (30.4 KB) ceph_mgr_leak.png | Tomasz Sętkowski, 09/15/2018 02:51 PM |
Updated by John Spray over 5 years ago
You can certainly try running with valgrind, you'll find it's (much) slower than usual but if you only need to run for a minute or two that might not be a problem.
Updated by Tomasz Sętkowski over 5 years ago
I have compiled and started a development cluster and there is a definite leak reported by valgrind in same place where it was supposedly fixed 2 years ago.
The issue which touched the reported line in DaemonServer.cc:170 was http://tracker.ceph.com/issues/19591
I also noticed that leak is slower when turn off the standby mgr daemons. Which starts to make sense since the buggy code seems to be in handling new connections.
I haven't gotten to running valgrind in production cluster yet. But I'll try it soon.
Compiled with:
ARGS="-DALLOCATOR=jemalloc" ./do_cmake.sh
Started cluster with 3 MGRs
MGR=3 ../src/vstart.sh -d -n -x --without-dashboard
Valgrind output:
==17402== HEAP SUMMARY:
==17402== in use at exit: 32,420 bytes in 639 blocks
==17402== total heap usage: 73,017 allocs, 72,378 frees, 7,585,417 bytes allocated
==17402==
==17402== 547 (272 direct, 275 indirect) bytes in 1 blocks are definitely lost in loss record 2 of 6
==17402== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==17402== by 0x20C2FE: DaemonServer::ms_verify_authorizer(Connection*, int, int, ceph::buffer::list&, ceph::buffer::list&, bool&, CryptoKey&) (DaemonServer.cc:170)
==17402== by 0x51F3820: ms_deliver_verify_authorizer (Messenger.h:812)
==17402== by 0x51F3820: verify_authorizer (AsyncMessenger.h:388)
==17402== by 0x51F3820: AsyncConnection::handle_connect_msg(ceph_msg_connect&, ceph::buffer::list&, ceph::buffer::list&) (AsyncConnection.cc:1499)
==17402== by 0x51F75A6: AsyncConnection::_process_connection() (AsyncConnection.cc:1313)
==17402== by 0x51FAE57: AsyncConnection::process() (AsyncConnection.cc:822)
==17402== by 0x520BA64: EventCenter::process_events(unsigned int, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> >*) (Event.cc:413)
==17402== by 0x520E72B: operator() (Stack.cc:53)
==17402== by 0x520E72B: std::_Function_handler<void (), NetworkStack::add_thread(unsigned int)::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:316)
==17402== by 0xE74D57E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==17402== by 0xE2766B9: start_thread (pthread_create.c:333)
==17402== by 0xF04441C: clone (clone.S:109)
==17402==
==17402== 31,873 (2,448 direct, 29,425 indirect) bytes in 9 blocks are definitely lost in loss record 6 of 6
==17402== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==17402== by 0x20C2FE: DaemonServer::ms_verify_authorizer(Connection*, int, int, ceph::buffer::list&, ceph::buffer::list&, bool&, CryptoKey&) (DaemonServer.cc:170)
==17402== by 0x51F3820: ms_deliver_verify_authorizer (Messenger.h:812)
==17402== by 0x51F3820: verify_authorizer (AsyncMessenger.h:388)
==17402== by 0x51F3820: AsyncConnection::handle_connect_msg(ceph_msg_connect&, ceph::buffer::list&, ceph::buffer::list&) (AsyncConnection.cc:1499)
==17402== by 0x51F75A6: AsyncConnection::_process_connection() (AsyncConnection.cc:1313)
==17402== by 0x51FAE57: AsyncConnection::process() (AsyncConnection.cc:822)
==17402== by 0x520BDC6: EventCenter::process_events(unsigned int, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> >*) (Event.cc:439)
==17402== by 0x520E72B: operator() (Stack.cc:53)
==17402== by 0x520E72B: std::_Function_handler<void (), NetworkStack::add_thread(unsigned int)::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:316)
==17402== by 0xE74D57E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==17402== by 0xE2766B9: start_thread (pthread_create.c:333)
==17402== by 0xF04441C: clone (clone.S:109)
==17402==
==17402== LEAK SUMMARY:
==17402== definitely lost: 2,720 bytes in 10 blocks
==17402== indirectly lost: 29,700 bytes in 629 blocks
==17402== possibly lost: 0 bytes in 0 blocks
==17402== still reachable: 0 bytes in 0 blocks
==17402== suppressed: 0 bytes in 0 blocks
==17402==
==17402== For counts of detected and suppressed errors, rerun with: -v
==17402== ERROR SUMMARY: 2 errors from 2 contexts (suppressed: 0 from 0)
Updated by Tomasz Sętkowski over 5 years ago
I ran valgrind on active mgr in production for a few minutes, when there was another standby in cluster. There are more leaks then just ms_verify_authorizer. It seems that generating performance counters is also leaking.
==47== Memcheck, a memory error detector
==47== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==47== Using Valgrind-3.11.0 and LibVEX; rerun with -h for copyright info
==47== Command: /usr/bin/ceph-mgr -f -i *****
==47==
--47-- WARNING: unhandled amd64-linux syscall: 324
--47-- You may be able to write your own handler.
--47-- Read the file README_MISSING_SYSCALL_OR_IOCTL.
--47-- Nevertheless we consider this a bug. Please report
--47-- it at http://valgrind.org/support/bug_reports.html.
^C==47==
==47== HEAP SUMMARY:
==47== in use at exit: 292,084 bytes in 5,807 blocks
==47== total heap usage: 650,845 allocs, 645,038 frees, 331,997,087 bytes allocated
==47==
==47== 272 bytes in 1 blocks are possibly lost in loss record 3 of 12
==47== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==47== by 0x20C2FE: DaemonServer::ms_verify_authorizer(Connection*, int, int, ceph::buffer::list&, ceph::buffer::list&, bool&, CryptoKey&) (DaemonServer.cc:170)
==47== by 0x51F3820: ms_deliver_verify_authorizer (Messenger.h:812)
==47== by 0x51F3820: verify_authorizer (AsyncMessenger.h:388)
==47== by 0x51F3820: AsyncConnection::handle_connect_msg(ceph_msg_connect&, ceph::buffer::list&, ceph::buffer::list&) (AsyncConnection.cc:1499)
==47== by 0x51F75A6: AsyncConnection::_process_connection() (AsyncConnection.cc:1313)
==47== by 0x51FAE57: AsyncConnection::process() (AsyncConnection.cc:822)
==47== by 0x520BA64: EventCenter::process_events(unsigned int, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> >*) (Event.cc:413)
==47== by 0x520E72B: operator() (Stack.cc:53)
==47== by 0x520E72B: std::_Function_handler<void (), NetworkStack::add_thread(unsigned int)::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:316)
==47== by 0xE74D57E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==47== by 0xE2766B9: start_thread (pthread_create.c:333)
==47== by 0xF04441C: clone (clone.S:109)
==47==
==47== 973 bytes in 43 blocks are possibly lost in loss record 4 of 12
==47== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==47== by 0x202BD1: void std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_construct<char*>(char*, char*, std::forward_iterator_tag) [clone .isra.136] (basic_string.tcc:219)
==47== by 0x205B93: _M_construct_aux<char*> (basic_string.h:236)
==47== by 0x205B93: _M_construct<char*> (basic_string.h:255)
==47== by 0x205B93: basic_string (basic_string.h:440)
==47== by 0x205B93: construct<std::__cxx11::basic_string<char>, const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&> (new_allocator.h:136)
==47== by 0x205B93: construct<std::__cxx11::basic_string<char>, const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&> (alloc_traits.h:475)
==47== by 0x205B93: _M_construct_node<const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&> (stl_tree.h:626)
==47== by 0x205B93: _M_create_node<const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&> (stl_tree.h:643)
==47== by 0x205B93: operator()<const std::__cxx11::basic_string<char>&> (stl_tree.h:556)
==47== by 0x205B93: _M_insert_<const std::__cxx11::basic_string<char>&, std::_Rb_tree<std::__cxx11::basic_string<char>, std::__cxx11::basic_string<char>, std::_Identity<std::__cxx11::basic_string<char> >, std::less<std::__cxx11::basic_string<char> >, std::allocator<std::__cxx11::basic_string<char> > >::_Alloc_node> (stl_tree.h:1753)
==47== by 0x205B93: _M_insert_unique<const std::__cxx11::basic_string<char>&> (stl_tree.h:2096)
==47== by 0x205B93: insert (stl_set.h:501)
==47== by 0x205B93: DaemonPerfCounters::update(MMgrReport*) (DaemonState.cc:143)
==47== by 0x20EDCB: DaemonServer::handle_report(MMgrReport*) (DaemonServer.cc:541)
==47== by 0x5149AA1: ms_deliver_dispatch (Messenger.h:667)
==47== by 0x5149AA1: DispatchQueue::entry() (DispatchQueue.cc:201)
==47== by 0x51E7D1C: DispatchQueue::DispatchThread::entry() (DispatchQueue.h:101)
==47== by 0xE2766B9: start_thread (pthread_create.c:333)
==47== by 0xF04441C: clone (clone.S:109)
==47==
==47== 3,392 bytes in 53 blocks are possibly lost in loss record 5 of 12
==47== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==47== by 0x205B74: allocate (new_allocator.h:111)
==47== by 0x205B74: allocate (alloc_traits.h:436)
==47== by 0x205B74: _M_get_node (stl_tree.h:588)
==47== by 0x205B74: _M_create_node<const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&> (stl_tree.h:642)
==47== by 0x205B74: operator()<const std::__cxx11::basic_string<char>&> (stl_tree.h:556)
==47== by 0x205B74: _M_insert_<const std::__cxx11::basic_string<char>&, std::_Rb_tree<std::__cxx11::basic_string<char>, std::__cxx11::basic_string<char>, std::_Identity<std::__cxx11::basic_string<char> >, std::less<std::__cxx11::basic_string<char> >, std::allocator<std::__cxx11::basic_string<char> > >::_Alloc_node> (stl_tree.h:1753)
==47== by 0x205B74: _M_insert_unique<const std::__cxx11::basic_string<char>&> (stl_tree.h:2096)
==47== by 0x205B74: insert (stl_set.h:501)
==47== by 0x205B74: DaemonPerfCounters::update(MMgrReport*) (DaemonState.cc:143)
==47== by 0x20EDCB: DaemonServer::handle_report(MMgrReport*) (DaemonServer.cc:541)
==47== by 0x5149AA1: ms_deliver_dispatch (Messenger.h:667)
==47== by 0x5149AA1: DispatchQueue::entry() (DispatchQueue.cc:201)
==47== by 0x51E7D1C: DispatchQueue::DispatchThread::entry() (DispatchQueue.h:101)
==47== by 0xE2766B9: start_thread (pthread_create.c:333)
==47== by 0xF04441C: clone (clone.S:109)
==47==
==47== 13,103 (2,448 direct, 10,655 indirect) bytes in 9 blocks are definitely lost in loss record 8 of 12
==47== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==47== by 0x20C2FE: DaemonServer::ms_verify_authorizer(Connection*, int, int, ceph::buffer::list&, ceph::buffer::list&, bool&, CryptoKey&) (DaemonServer.cc:170)
==47== by 0x51F3820: ms_deliver_verify_authorizer (Messenger.h:812)
==47== by 0x51F3820: verify_authorizer (AsyncMessenger.h:388)
==47== by 0x51F3820: AsyncConnection::handle_connect_msg(ceph_msg_connect&, ceph::buffer::list&, ceph::buffer::list&) (AsyncConnection.cc:1499)
==47== by 0x51F75A6: AsyncConnection::_process_connection() (AsyncConnection.cc:1313)
==47== by 0x51FAE57: AsyncConnection::process() (AsyncConnection.cc:822)
==47== by 0x520BDC6: EventCenter::process_events(unsigned int, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> >*) (Event.cc:439)
==47== by 0x520E72B: operator() (Stack.cc:53)
==47== by 0x520E72B: std::_Function_handler<void (), NetworkStack::add_thread(unsigned int)::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:316)
==47== by 0xE74D57E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==47== by 0xE2766B9: start_thread (pthread_create.c:333)
==47== by 0xF04441C: clone (clone.S:109)
==47==
==47== 35,529 (5,440 direct, 30,089 indirect) bytes in 20 blocks are definitely lost in loss record 9 of 12
==47== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==47== by 0x20C2FE: DaemonServer::ms_verify_authorizer(Connection*, int, int, ceph::buffer::list&, ceph::buffer::list&, bool&, CryptoKey&) (DaemonServer.cc:170)
==47== by 0x51F3820: ms_deliver_verify_authorizer (Messenger.h:812)
==47== by 0x51F3820: verify_authorizer (AsyncMessenger.h:388)
==47== by 0x51F3820: AsyncConnection::handle_connect_msg(ceph_msg_connect&, ceph::buffer::list&, ceph::buffer::list&) (AsyncConnection.cc:1499)
==47== by 0x51F75A6: AsyncConnection::_process_connection() (AsyncConnection.cc:1313)
==47== by 0x51FAE57: AsyncConnection::process() (AsyncConnection.cc:822)
==47== by 0x520BA64: EventCenter::process_events(unsigned int, std::chrono::duration<unsigned long, std::ratio<1l, 1000000000l> >*) (Event.cc:413)
==47== by 0x520E72B: operator() (Stack.cc:53)
==47== by 0x520E72B: std::_Function_handler<void (), NetworkStack::add_thread(unsigned int)::{lambda()#1}>::_M_invoke(std::_Any_data const&) (std_function.h:316)
==47== by 0xE74D57E: ??? (in /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25)
==47== by 0xE2766B9: start_thread (pthread_create.c:333)
==47== by 0xF04441C: clone (clone.S:109)
==47==
==47== 238,815 (5,056 direct, 233,759 indirect) bytes in 79 blocks are definitely lost in loss record 12 of 12
==47== at 0x4C2E0EF: operator new(unsigned long) (in /usr/lib/valgrind/vgpreload_memcheck-amd64-linux.so)
==47== by 0x205B74: allocate (new_allocator.h:111)
==47== by 0x205B74: allocate (alloc_traits.h:436)
==47== by 0x205B74: _M_get_node (stl_tree.h:588)
==47== by 0x205B74: _M_create_node<const std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&> (stl_tree.h:642)
==47== by 0x205B74: operator()<const std::__cxx11::basic_string<char>&> (stl_tree.h:556)
==47== by 0x205B74: _M_insert_<const std::__cxx11::basic_string<char>&, std::_Rb_tree<std::__cxx11::basic_string<char>, std::__cxx11::basic_string<char>, std::_Identity<std::__cxx11::basic_string<char> >, std::less<std::__cxx11::basic_string<char> >, std::allocator<std::__cxx11::basic_string<char> > >::_Alloc_node> (stl_tree.h:1753)
==47== by 0x205B74: _M_insert_unique<const std::__cxx11::basic_string<char>&> (stl_tree.h:2096)
==47== by 0x205B74: insert (stl_set.h:501)
==47== by 0x205B74: DaemonPerfCounters::update(MMgrReport*) (DaemonState.cc:143)
==47== by 0x20EDCB: DaemonServer::handle_report(MMgrReport*) (DaemonServer.cc:541)
==47== by 0x5149AA1: ms_deliver_dispatch (Messenger.h:667)
==47== by 0x5149AA1: DispatchQueue::entry() (DispatchQueue.cc:201)
==47== by 0x51E7D1C: DispatchQueue::DispatchThread::entry() (DispatchQueue.h:101)
==47== by 0xE2766B9: start_thread (pthread_create.c:333)
==47== by 0xF04441C: clone (clone.S:109)
==47==
==47== LEAK SUMMARY:
==47== definitely lost: 12,944 bytes in 108 blocks
==47== indirectly lost: 274,503 bytes in 5,602 blocks
==47== possibly lost: 4,637 bytes in 97 blocks
==47== still reachable: 0 bytes in 0 blocks
==47== suppressed: 0 bytes in 0 blocks
==47==
==47== For counts of detected and suppressed errors, rerun with: -v
==47== ERROR SUMMARY: 6 errors from 6 contexts (suppressed: 0 from 0)
Updated by Sage Weil over 5 years ago
- Status changed from New to In Progress
- Priority changed from Normal to Urgent
- Backport set to mimic
Can you try this patch?
diff --git a/src/mgr/DaemonServer.cc b/src/mgr/DaemonServer.cc
index 00f480a239..8891b74c9f 100644
--- a/src/mgr/DaemonServer.cc
+++ b/src/mgr/DaemonServer.cc
@@ -226,7 +226,7 @@ bool DaemonServer::ms_verify_authorizer(
is_valid = false;
}
}
- con->set_priv(s->get());
+ con->set_priv(s);
if (peer_type == CEPH_ENTITY_TYPE_OSD) {
Mutex::Locker l(lock);
or wait for the test build to appear on branch wip-35998-mimic at shaman.ceph.com in an hour or so
Updated by Tomasz Sętkowski over 5 years ago
I have compiled mimic branch with your patch and tested on a dev cluster, then in production. Valgrind shows no leaks in neither.
Briefly when running 13.2.0 mgrs with the patched ones, memory usage was still growing and saw a lot of messages about replacing connections.
-- 192.168.200.41:6803/196 >> 192.168.200.34:0/1569290446 conn(0x7f61eabe5900 :6803 s=STATE_ACCEPTING_WAIT_CONNECT_MSG_AUTH pgs=0 cs=0 l=1).handle_connect_msg accept replacing existing (lossy) channel (new one lossy=1)
But when all mgrs are patched, it works fine. Memory usage is about 27M on active daemon and 12M on others. There is no log about replacing channels.
Thank you for your help.
Updated by Sage Weil over 5 years ago
- Backport changed from mimic to luminous
https://github.com/ceph/ceph/pull/24233
I'm not sure but I think this is also in luminous...
Updated by Tomasz Sętkowski over 5 years ago
I haven't seen it on luminous in my cluster.
Updated by Yuri Weinstein over 5 years ago
Sage Weil wrote:
https://github.com/ceph/ceph/pull/24233
I'm not sure but I think this is also in luminous...
merged
Updated by Nathan Cutler over 5 years ago
- Status changed from In Progress to Pending Backport
Updated by Nathan Cutler over 5 years ago
- Copied to Backport #36342: luminous: ceph-mgr active daemon memory leak since mimic added
Updated by Nathan Cutler over 5 years ago
- Status changed from Pending Backport to Resolved
Updated by Corin Langosch about 5 years ago
This bug should be reopened, because it's still present in latest mimic 13.2.5. Please see http://tracker.ceph.com/issues/36471
Updated by Nathan Cutler about 5 years ago
- Related to Bug #36471: connection resetting tcp errors between mgr daemons added
Updated by Nathan Cutler about 5 years ago
Corin Langosch wrote:
This bug should be reopened, because it's still present in latest mimic 13.2.5. Please see http://tracker.ceph.com/issues/36471
Hi Corin: We try to open new issues instead of reopening old ones for issues that have already gone through backporting. You opened a new issue and I have added the "Related To" tag to it, so reopening this one should not be needed I guess.
Actions