Menu
▾
▴
#328 memory usage explosion
Arno reports that after a temporary network disconnect,
Mnet started using > 200 MB (?? I don't remember what
he said exactly).
This could be a bug in peerman, but on the other hand
it could also be a lot of other things. It is easy to
start gulping down memory in Python, and hard to find
out where you are doing it after the fact.
Logged In: YES
user_id=642335
it looks like the broker does not nicely reconnect to the
netwrk, and peerman does not handle that... will look into
that as soon as i find some time
Logged In: YES
user_id=52562
Increasing priority, because my server is currently using
343 MB virt, 230 MB resident, even though it has been doing
nothing but serving for a couple of days.
Logged In: YES
user_id=52562
Okay, this is almost certainly the same as the "message
storm" bug.
I have run a good test and I see what is very likely the
problem. I have a fix in mind, and it is a fix that I've
implemented before. It is also a fix that Arno and I have
previously discussed: making multiple successive calls to
peerman.lookup_contact_info() with the *same* MT and the
*same* peerId get demultiplexed so that they result in only
a single outgoing "lookup" msg.
That may not be the only problem, but it is worth doing.
Now, when will I implement this? MAYBE I will wake up
early, before Irby does, tomorrow morning and do it then...
Logged In: YES
user_id=52562
I have not observed this event except when all MTs were
unreachable. Arno says he has observed it even when MTs
were reachable. Or, actually, maybe the bug he was talking
about wasn't memory-usage-explosion, but a different one
involving the node not being able to talk to any peers.
Maybe Arno should post his own words to the issue tracker
himself. ;-)
Logged In: YES
user_id=52562
Personally I'm inclined to leave this as a Known Bug in
v0.6.2. Arno and I have investigated extensively, and I
definitely understand why this happens sometimes. I don't
know if my explanation explains all occurrences. Anyway, I
don't see a way to *really* make sure this can never happen.
I do have a patch that demultiplexes multiple overlapping
"lookup contact info"'s to the same MT for the same peerId.
I will CVS commit that patch to the HEAD branch and then
maybe Arno will consider whether it is worth porting that
patch to the branch_v062 branch. I think that patch
probably reduces or eliminates the memory usage explosion in
the case of a network outage, but I haven't tested that yet.
Logged In: YES
user_id=52562
Downgrading priority because it doesn't happen all that often.
There is a patch in v0.6.3 [1] that probably helps with this
quite a lot (as well as improving network usage in general).
The improvements in bootpage loading and hello'ing that we
are currently planning might also reduce the frequency and
intensity of these memory usage explosions.
Hopefully Arno will close this or bump it to "v0.6.3" group
after he tries out these patches.
[1] peerman.py, rev. 1.38:
http://cvs.sourceforge.net/viewcvs.py/mnet/mnet/common/peerman.py?r1=1.38
Logged In: YES
user_id=52562
Arno is now testing several new patches, the combination of
which may help with this problem.
Logged In: YES
user_id=52562
I observed this again. After being up for two days, my node
(running HEAD == v0.6.3) went from 45 MB virt/7 MB res to
149 MB virt/32 MB res and stayed there. This happened over
10 minutes. Here are the relevant log entries:
2004-03-12_16:10:28 () Crypto++ version: 5.0
2004-03-12_16:10:28 () Berkeley DB version: (4, 1, 25)
2004-03-12_16:10:28 () PyBSDDB version: 4.1.6
2004-03-12_16:10:46 (Broker) This Broker's ID is: <nw31m>
(full name: nw31me8ggzzah1td6uc1wrhau7hhsuqe) or in
mojosixbit encoding: FTMloOY1745KI_TZKhOYn3nLTcg
2004-03-13_22:06:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(45846528, 7322)
2004-03-13_22:11:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(45858816, 7324)
2004-03-13_22:16:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(72863744, 13933)
2004-03-13_22:21:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(150106112, 32814)
2004-03-13_22:26:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(149262336, 32608)
increasing priority of this issue and investigating in my
log file.
Logged In: YES
user_id=52562
Okay, one possible clue is that <nw31m>, acting as relay
server, stored some messages for slow delivery during that time:
2004-03-13_22:11:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(45858816, 7324)
2004-03-13_22:10:54 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 2, msgs: 2, sum of
sizes of msgs: 1912, len(self.mtm._cm._map_inmsgid_to
2004-03-13_22:15:54 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 5376044, len(self.mtm._cm._map_inmsg
2004-03-13_22:16:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(72863744, 13933)
2004-03-13_22:16:54 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 10899508, len(self.mtm._cm._map_inms
2004-03-13_22:21:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(150106112, 32814)
2004-03-13_22:21:55 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 10899508, len(self.mtm._cm._map_inms
And it has continued to store them (and to occupy that much
RAM) for the next 14 hours or so.
Logged In: YES
user_id=52562
This is a strong correlation of events, but it is a mystery
why the amount of RAM used would go up superlinearly with
the amount of bytes of message stored.
From the first sample to the second, the RAM went up
27,004,928 virt / 6,609 res. From the second sample to the
third, the RAM went up 77,242,368 virt, / 18,881 res. From
the first sample to the second, the bytes of stored message
went up 5,374,132. From the second sample to the third, the
bytes of stored message went up another 5,523,464. Why
would storing 5 MB of messages take 27 MB virt, and then
storing another 5 MB of messages takes another 77 MB virt ?
Logged In: YES
user_id=52562
Another interesting fact: all of the messages storing had
finished *before* the second increase in RAM happened:
2004-03-13_22:15:54 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 5376044, len(self.mtm._cm._map_inmsg
2004-03-13_22:16:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(72863744, 13933)
2004-03-13_22:16:54 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 10899508, len(self.mtm._cm._map_inms
2004-03-13_22:20:55 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 10899508, len(self.mtm._cm._map_inms
2004-03-13_22:21:21 (XXXDEBUG) get_mem_usage_virt_and_res():
(150106112, 32814)
2004-03-13_22:21:55 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips: 1, senders: 3, msgs: 104, sum
of sizes of msgs: 10899508, len(self.mtm._cm._map_inms
Logged In: YES
user_id=52562
Okay, between the first and second samples there were a
large number of relay server and "lookup contact info"
messages. Between the second and third samples there were
an even larger number of the same. Each sample interval is
about 5 minutes, and during a normal sample interval we
exchanged maybe 50 or so messages total. During the first
memory-increasing sample interval, we exchanged 1500 or so.
During the second memory-increasing sample interval, we
exchanged 2100 or so (again, almost every one was a relay
server message or a "lookup contact info").
Note that it cannot be a memory leak that occurs with every
such message, because over the other dozens of hours of
operation, thousands of messages go through with zero
increase in memory usage.
Logged In: YES
user_id=52562
Another issue is that it looks a lot like messages stored by
the relay server for slow delivery don't get garbage
collected after they are delivered. See this:
2004-03-16_14:11:07 (XXXDEBUG) get_mem_usage_virt_and_res():
(49090560, 8204)
2004-03-16_14:11:43 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips:
0, senders: 0, msgs: 0, sum of sizes of msgs: 0,
len(self.mtm._cm._map_inmsgid_to_i
2004-03-16_14:15:43 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips:
1, senders: 2, msgs: 37, sum of sizes of msgs: 2949124,
len(self.mtm._cm._map_inmsg
2004-03-16_14:16:07 (XXXDEBUG) get_mem_usage_virt_and_res():
(58159104, 10399)
2004-03-16_14:16:43 (RelayServer) <RelayServerHandlers
1>._doq_loop_debug(); recips:
0, senders: 0, msgs: 0, sum of sizes of msgs: 0, le
2004-03-16_14:21:07 (XXXDEBUG) get_mem_usage_virt_and_res():
(58155008, 10399)
n(self.mtm._cm._map_inmsgid_to_i
It looks a lot like storing those messages cost 10 MB (why
??) and then the 10 MBs is never recovered for the rest of
the life of the program.
Now a big question I have is: suppose 37 new messages come
in, weighing 2949124 bytes in total, then will the RAM usage
got up *another* 10 MB, or will the memory already allocated
be reused??
Logged In: YES
user_id=52562
I committed a patch which completely changes the way relay
servers store messages for slow delivery. The new way
actually calculates the aggregate size of all stored
messages, and drops messages (randomly) if it goes over the
limit.
Unfortunately, since I started a node that runs this patch
yesterday, there haven't been any stored messages on my
relay server. This is a problem with testing things on the
real live public Mnet.
I guess I'll just wait patiently.
Logged In: YES
user_id=52562
Fixed?
I've seen my relay server process lots of messages, and
store messages in RAM for slow delivery, and so forth, and I
haven't seen any memory usage explosion. It's been up for
two days in the most recent trial.
Logged In: YES
user_id=52562
Assigning to Arno so that he can be responsible for closing it.
Arno is a good person to be the "issue closer" because he is good at
finding bugs and bad behavior.
Logged In: YES
user_id=52562
Uh-oh.
Last night I ran a new node on my Mac laptop. It is behind
NAT, and its relay server was <nw31m>. This morning <nw31m>
is using 175 MB RAM!
Logged In: YES
user_id=52562
I'm testing a patch which prints out diags that will
identify if msgs held in the closure of
post-timeout-callbacks is the problem.
If the diags show that this is a problem, then I'll fix it.
Logged In: YES
user_id=52562
Well, I've experimented and experimented. I have a patch
that reduces memory usage by about 6 to 12 MB, but I'm not
sure it is worth putting that patch into v0.6.2.
I've never seen memory usage exceed 200 MB.
I've only very rarely seen it get up to 175 MB.
I'm about to give up and list it as a "known bug" in v0.6.2.