Bug 723809

Summary: Possible memory leak in qpid-cpp-server
Product: Red Hat Enterprise MRG Reporter: Tomas Rusnak <trusnak>
Component: qpid-cppAssignee: messaging-bugs <messaging-bugs>
Status: CLOSED CURRENTRELEASE QA Contact: Frantisek Reznicek <freznice>
Severity: high Docs Contact:
Priority: medium    
Version: 2.0CC: esammons, freznice, jross, matt, ppecka
Target Milestone: 3.1Keywords: TestOnly
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: qpid-cpp-0.18 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-04-30 16:13:50 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
Pmap from qpidd
none
Semi automated reproduction scripts none

Description Tomas Rusnak 2011-07-21 08:50:40 UTC 
Description of problem:
Running qpid-cpp-server longer then 1 month without any messages sent over eats a lot of memory ~484MB.

Version-Release number of selected component (if applicable):
qpid-cpp-server-0.10-6.el6.x86_64

How reproducible:
I'm not sure

Steps to Reproduce:
1. install qpid-cpp-server
2. service qpidd start
3. let it run for a month without any traffic
  
Actual results:

qpidd    30161  0.0  1.0 496052  5132 ?        Ssl  Jun09  12:51 /usr/sbin/qpidd --data-dir /var/lib/qpidd --daemon

# qpid-stat -q
Queues
  queue                                                         dur  autoDel  excl  msg   msgIn  msgOut  bytes  bytesIn  bytesOut  cons  bind
  =============================================================================================================================================
  qmfagent-577aacc4-2122-4f68-934f-df4e4866aef9                      Y        Y        0     4      4       0     68       68         1     4
  qmfagent-c8bf6c22-a03e-4667-9fc3-ca997ba0aa55                      Y        Y        0     4      4       0     68       68         1     4
  reply-rhel6_64.mrg-qe-12.lab.eng.brq.redhat.com.18048.1            Y        Y        0    58     58       0   22.2k    22.2k        1     2
  qmfc-v2-ui-rhel6_64.mrg-qe-12.lab.eng.brq.redhat.com.18048.1       Y        Y        0     0      0       0      0        0         1     1
  qmfagent-308e4fd4-0dee-4a7d-a4bc-ede61eb0727a                      Y        Y        0     4      4       0     68       68         1     4
  topic-rhel6_64.mrg-qe-12.lab.eng.brq.redhat.com.18048.1            Y        Y        0     0      0       0      0        0         1     4
  qmfagent-75d1e024-2408-48a3-9d8a-b41aa1680d96                      Y        Y        0     4      4       0     68       68         1     4
  qmfc-v2-rhel6_64.mrg-qe-12.lab.eng.brq.redhat.com.18048.1          Y        Y        0    21     21       0   18.5k    18.5k        1     2
  qmfagent-ea27ab64-fa90-4e48-84fd-5ad2ffaf7adf                      Y        Y        0     4      4       0     68       68         1     4
  qmfc-v2-hb-rhel6_64.mrg-qe-12.lab.eng.brq.redhat.com.18048.1       Y        Y        0     1      1       0    227      227         1     2


Take a look at attached file for complete pmap, interesting part:
00000000022a3000   2000K rw---    [ anon ]
00007f15b8000000   1984K rw---    [ anon ]
00007f15b81f0000  63552K -----    [ anon ]
00007f15bc000000    668K rw---    [ anon ]
00007f15bc0a7000  64868K -----    [ anon ]
00007f15c0000000    852K rw---    [ anon ]
00007f15c00d5000  64684K -----    [ anon ]
00007f15c4000000    880K rw---    [ anon ]
00007f15c40dc000  64656K -----    [ anon ]
00007f15c8000000   1152K rw---    [ anon ]
00007f15c8120000  64384K -----    [ anon ]
00007f15cf46d000      4K -----    [ anon ]
00007f15cf46e000  10240K rw---    [ anon ]
00007f15cfe6e000      4K -----    [ anon ]
00007f15cfe6f000  10240K rw---    [ anon ]
00007f15d086f000      4K -----    [ anon ]
00007f15d0870000  10240K rw---    [ anon ]
00007f15d1270000      4K -----    [ anon ]
00007f15d1271000  10240K rw---    [ anon ]

Expected results:
No anonymous memory consumption - no leaks.
Comment 1 Tomas Rusnak 2011-07-21 08:52:28 UTC 
Created attachment 514163 [details]
Pmap from qpidd
Comment 7 Frantisek Reznicek 2014-04-15 08:40:53 UTC 
Memory leak analysis needed to prove this one is gone with bug 726379.
Comment 8 Frantisek Reznicek 2015-03-26 08:04:16 UTC 
Comparable qpidd usage measurement have started between MRG/M 2.0 (qpid-0.10) and current candidate bits. Results ready in 10 days or so. Stay tuned.
Comment 9 Frantisek Reznicek 2015-03-26 11:36:01 UTC 
Created attachment 1006766 [details]
Semi automated reproduction scripts
Comment 10 Frantisek Reznicek 2015-03-30 07:00:51 UTC 
The issue have been reproduced on qpid-cpp-server-0.10-6.el6.x86_64 and candidate builds show results proving no leak:


el6.x86_64 old leaking version

[root@dhcp-75-232 bz723809]# ./resulter.sh
anonymous memory fields analysis report:
Base name:pmap.2015-03-26:09:01.log.anon, base value:234528768

indx:0, pmap.2015-03-26:09:01.log.anon, 234528768, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.anon, 236478464, [100.83%]
indx:568, pmap.2015-03-30:08:21.log.anon, 236478464, [100.83%]
indx:569, pmap.2015-03-30:08:31.log.anon, 236478464, [100.83%]
total memory analysis report:
Base name:pmap.2015-03-26:09:01.log.total, base value:359374848

indx:0, pmap.2015-03-26:09:01.log.total, 359374848, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.total, 361324544, [100.54%]
indx:568, pmap.2015-03-30:08:21.log.total, 361324544, [100.54%]
indx:569, pmap.2015-03-30:08:31.log.total, 361324544, [100.54%]
[root@dhcp-75-232 bz723809]# rpm -qa | grep qpid | sort
python-qpid-qmf-0.10-10.el6.x86_64
python-qpid-0.10-1.el6.noarch
qpid-cpp-client-devel-docs-0.10-6.el6.noarch
qpid-cpp-client-devel-0.10-6.el6.x86_64
qpid-cpp-client-rdma-0.10-6.el6.x86_64
qpid-cpp-client-ssl-0.10-6.el6.x86_64
qpid-cpp-client-0.10-6.el6.x86_64
qpid-cpp-debuginfo-0.10-6.el6.x86_64
qpid-cpp-server-devel-0.10-6.el6.x86_64
qpid-cpp-server-rdma-0.10-6.el6.x86_64
qpid-cpp-server-ssl-0.10-6.el6.x86_64
qpid-cpp-server-store-0.10-6.el6.x86_64
qpid-cpp-server-xml-0.10-6.el6.x86_64
qpid-cpp-server-0.10-6.el6.x86_64
qpid-java-client-0.10-6.el6.noarch
qpid-java-common-0.10-6.el6.noarch
qpid-java-example-0.10-6.el6.noarch
qpid-java-jca-0.10-6.el6.noarch
qpid-qmf-debuginfo-0.10-10.el6.x86_64
qpid-qmf-devel-0.10-10.el6.x86_64
qpid-qmf-0.10-10.el6.x86_64
qpid-tests-0.10-1.el6.noarch
qpid-tools-0.10-3.el6.noarch
rh-qpid-cpp-tests-0.10-6.el6.x86_64



el6.i686 candidate
[root@dhcp-75-230 bz723809]# ./resulter.sh
anonymous memory fields analysis report:
Base name:pmap.2015-03-26:09:01.log.anon, base value:36024320

indx:0, pmap.2015-03-26:09:01.log.anon, 36024320, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.anon, 36024320, [100.00%]
indx:568, pmap.2015-03-30:08:21.log.anon, 36024320, [100.00%]
indx:569, pmap.2015-03-30:08:31.log.anon, 36024320, [100.00%]
total memory analysis report:
Base name:pmap.2015-03-26:09:01.log.total, base value:70729728

indx:0, pmap.2015-03-26:09:01.log.total, 70729728, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.total, 70729728, [100.00%]
indx:568, pmap.2015-03-30:08:21.log.total, 70729728, [100.00%]
indx:569, pmap.2015-03-30:08:31.log.total, 70729728, [100.00%]
[root@dhcp-75-230 bz723809]# rpm -qa | grep qpid | sort
python-qpid-qmf-0.30-5.el6.i686
python-qpid-0.30-6.el6.noarch
qpid-cpp-client-devel-docs-0.30-7.el6.noarch
qpid-cpp-client-devel-0.30-7.el6.i686
qpid-cpp-client-rdma-0.30-7.el6.i686
qpid-cpp-client-0.30-7.el6.i686
qpid-cpp-debuginfo-0.30-7.el6.i686
qpid-cpp-server-devel-0.30-7.el6.i686
qpid-cpp-server-ha-0.30-7.el6.i686
qpid-cpp-server-linearstore-0.30-7.el6.i686
qpid-cpp-server-rdma-0.30-7.el6.i686
qpid-cpp-server-xml-0.30-7.el6.i686
qpid-cpp-server-0.30-7.el6.i686
qpid-java-client-0.30-4.el6.noarch
qpid-java-common-0.30-4.el6.noarch
qpid-java-example-0.30-4.el6.noarch
qpid-jca-xarecovery-0.22-2.el6.noarch
qpid-jca-0.22-2.el6.noarch
qpid-proton-c-devel-0.7-4.el6.i686
qpid-proton-c-0.7-4.el6.i686
qpid-proton-debuginfo-0.7-4.el6.i686
qpid-qmf-debuginfo-0.30-5.el6.i686
qpid-qmf-devel-0.30-5.el6.i686
qpid-qmf-0.30-5.el6.i686
qpid-tools-0.30-4.el6.noarch



el6.x86_64 candidate
[root@dhcp-75-231 bz723809]# ./resulter.sh
anonymous memory fields analysis report:
Base name:pmap.2015-03-26:09:01.log.anon, base value:234631168

indx:0, pmap.2015-03-26:09:01.log.anon, 234631168, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.anon, 234921984, [100.12%]
indx:568, pmap.2015-03-30:08:21.log.anon, 234921984, [100.12%]
indx:569, pmap.2015-03-30:08:31.log.anon, 234921984, [100.12%]
total memory analysis report:
Base name:pmap.2015-03-26:09:01.log.total, base value:386498560

indx:0, pmap.2015-03-26:09:01.log.total, 386498560, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.total, 386793472, [100.08%]
indx:568, pmap.2015-03-30:08:21.log.total, 386793472, [100.08%]
indx:569, pmap.2015-03-30:08:31.log.total, 386793472, [100.08%]
[root@dhcp-75-231 bz723809]# rpm -qa | grep qpid | sort
python-qpid-qmf-0.30-5.el6.x86_64
python-qpid-0.30-6.el6.noarch
qpid-cpp-client-devel-docs-0.30-7.el6.noarch
qpid-cpp-client-devel-0.30-7.el6.x86_64
qpid-cpp-client-rdma-0.30-7.el6.x86_64
qpid-cpp-client-0.30-7.el6.x86_64
qpid-cpp-debuginfo-0.30-7.el6.x86_64
qpid-cpp-server-devel-0.30-7.el6.x86_64
qpid-cpp-server-ha-0.30-7.el6.x86_64
qpid-cpp-server-linearstore-0.30-7.el6.x86_64
qpid-cpp-server-rdma-0.30-7.el6.x86_64
qpid-cpp-server-xml-0.30-7.el6.x86_64
qpid-cpp-server-0.30-7.el6.x86_64
qpid-java-client-0.30-4.el6.noarch
qpid-java-common-0.30-4.el6.noarch
qpid-java-example-0.30-4.el6.noarch
qpid-jca-xarecovery-0.22-2.el6.noarch
qpid-jca-0.22-2.el6.noarch
qpid-proton-c-devel-0.7-4.el6.x86_64
qpid-proton-c-0.7-4.el6.x86_64
qpid-proton-debuginfo-0.7-4.el6.x86_64
qpid-qmf-debuginfo-0.30-5.el6.x86_64
qpid-qmf-devel-0.30-5.el6.x86_64
qpid-qmf-0.30-5.el6.x86_64
qpid-tools-0.30-4.el6.noarch


el7.x86_64 candidate
[root@dhcp-75-233 bz723809]# ./resulter.sh
anonymous memory fields analysis report:
Base name:pmap.2015-03-26:09:01.log.anon, base value:227692544

indx:0, pmap.2015-03-26:09:01.log.anon, 227692544, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.anon, 227962880, [100.12%]
indx:568, pmap.2015-03-30:08:21.log.anon, 227962880, [100.12%]
indx:569, pmap.2015-03-30:08:31.log.anon, 227962880, [100.12%]
total memory analysis report:
Base name:pmap.2015-03-26:09:01.log.total, base value:369319936

indx:0, pmap.2015-03-26:09:01.log.total, 369319936, [100.00%]
...
indx:567, pmap.2015-03-30:08:11.log.total, 369590272, [100.07%]
indx:568, pmap.2015-03-30:08:21.log.total, 369590272, [100.07%]
indx:569, pmap.2015-03-30:08:31.log.total, 369590272, [100.07%]
[root@dhcp-75-233 bz723809]# rpm -qa | grep qpid | sort
python-qpid-qmf-0.30-5.el7.x86_64
python-qpid-0.30-6.el7.noarch
qpid-cpp-client-devel-docs-0.30-7.el7.noarch
qpid-cpp-client-devel-0.30-7.el7.x86_64
qpid-cpp-client-rdma-0.30-7.el7.x86_64
qpid-cpp-client-0.30-7.el7.x86_64
qpid-cpp-debuginfo-0.30-7.el7.x86_64
qpid-cpp-server-devel-0.30-7.el7.x86_64
qpid-cpp-server-ha-0.30-7.el7.x86_64
qpid-cpp-server-linearstore-0.30-7.el7.x86_64
qpid-cpp-server-rdma-0.30-7.el7.x86_64
qpid-cpp-server-0.30-7.el7.x86_64
qpid-java-client-0.30-5.el7.noarch
qpid-java-common-0.30-5.el7.noarch
qpid-java-example-0.30-5.el7.noarch
qpid-proton-c-devel-0.7-5.el7.x86_64
qpid-proton-c-0.7-5.el7.x86_64
qpid-proton-debuginfo-0.7-5.el7.x86_64
qpid-qmf-debuginfo-0.30-5.el7.x86_64
qpid-qmf-devel-0.30-5.el7.x86_64
qpid-qmf-0.30-5.el7.x86_64
qpid-tools-0.30-4.el7.noarch


Note: el[67].x86_64 are showing increase of 0.12% (anon pages) which is way less than old version also el7.x86_64 shows that there are moment where relative value returns back to 100% and then increases up (oscilation 100 - 100.12) which is normal. el6.x86_64 data do not show this oscilation up, but this can be caused by low sampling rate.


-> VERIFIED
Comment 11 Frantisek Reznicek 2015-04-03 07:14:04 UTC 
> Note: el[67].x86_64 are showing increase of 0.12% (anon pages) which is way
> less than old version also el7.x86_64 shows that there are moment where
> relative value returns back to 100% and then increases up (oscilation 100 -
> 100.12) which is normal. el6.x86_64 data do not show this oscilation up, but
> this can be caused by low sampling rate.
> 

Long term running test proved that suspicious el6 x86_64 behavior (mem consumption increase of 0.124% of anon pages) is not growing and thus not representing any memory leak.

Moreover the amount of increased anon memory pages matches with the el7 x86_64 one with only difference that el7 unallocates and then allocates those repeatedly while el6 keep them allocated.


Test results while running over 7 days:
  === candidate el6i ====
  [root@el6i bz723809]# ./resulter.sh 
  anonymous memory fields analysis report:
  Base name:pmap.2015-03-26:09:01.log.anon, base value:36024320
  
  indx:0, pmap.2015-03-26:09:01.log.anon, 36024320, [100.000%]
  ...
  indx:1144, pmap.2015-04-03:08:21.log.anon, 36024320, [100.000%]
  indx:1145, pmap.2015-04-03:08:31.log.anon, 36024320, [100.000%]
  indx:1146, pmap.2015-04-03:08:41.log.anon, 36024320, [100.000%]
  
  === candidate el6x ====
  [root@el6x bz723809]# ./resulter.sh 
  anonymous memory fields analysis report:
  Base name:pmap.2015-03-26:09:01.log.anon, base value:234631168
  
  indx:0, pmap.2015-03-26:09:01.log.anon, 234631168, [100.000%]
  ...
  indx:1144, pmap.2015-04-03:08:21.log.anon, 234921984, [100.124%]
  indx:1145, pmap.2015-04-03:08:31.log.anon, 234921984, [100.124%]
  indx:1146, pmap.2015-04-03:08:41.log.anon, 234921984, [100.124%]
  
  === candidate el7x ====
  [root@el7x bz723809]# ./resulter.sh 
  anonymous memory fields analysis report:
  Base name:pmap.2015-03-26:09:01.log.anon, base value:227692544
  
  indx:0, pmap.2015-03-26:09:01.log.anon, 227692544, [100.000%]
  ...
  indx:1144, pmap.2015-04-03:08:21.log.anon, 227962880, [100.119%]
  indx:1145, pmap.2015-04-03:08:31.log.anon, 227962880, [100.119%]
  indx:1146, pmap.2015-04-03:08:41.log.anon, 227962880, [100.119%]



Just for completeness buggy version shows already noticeable difference:

  === old stable el6x ====
  [root@el6x2 bz723809]# ./resulter.sh 
  anonymous memory fields analysis report:
  Base name:pmap.2015-03-26:09:01.log.anon, base value:234528768
  
  indx:0, pmap.2015-03-26:09:01.log.anon, 234528768, [100.000%]
  ...
  indx:1144, pmap.2015-04-03:08:21.log.anon, 237748224, [101.373%]
  indx:1145, pmap.2015-04-03:08:31.log.anon, 237748224, [101.373%]
  indx:1146, pmap.2015-04-03:08:41.log.anon, 237748224, [101.373%]