Zugg Software :: View topic

Beginner Joined: 22 Dec 2008 Posts: 21

I couldn't find a specific topic on the General forums for this, so I am essentially moving this over from the Beta forums with some test code that actually reproduces the issue.

Background that I've see:

Testing and Results (using Win7 "Working Set" task manager numbers when the CMUD process is idle; exited and restarted CMUD between each run, edited the scripts after recording the finished memory values for the next test before exiting CMUD for the current test):

I hope this helps track down what data structures aren't being freed correctly for garbage collection.
OR
Someone point out what I am doing wrong that is causing the memory consumption (I believe all I am doing is copying data from one area into pre-existing variables). I did try access the GMCP fields directly from the buttons, but not all of them update when the GMCP data changes (HP updates "always" and Mana rarely/never changes with direct button access to GMCP structure which is not in the code below).

Let me know if there are questions about this testing and code.

Thanks,
-- Delgar

Wizard Joined: 22 Mar 2007 Posts: 2320

How big is your scrollback buffer?

Beginner Joined: 22 Dec 2008 Posts: 21

Scrollback set to 4242 lines.

If this were a scrollback issue, all of the tests would show very similar increases.
Only when triggers are actually enabled, is this a big issue and it only became a huge issue to me when
I added a GMCP trigger.
If there is something that causes triggers (esp GMCP ones) to cause the scrollback buffer to take up memory
and not release it, then this is an issue that needs to be fixed.

Actually, if there is something that causes the scrollback buffer to take up memory and then not release it,
this also needs to be fixed.

One more test

Wizard Joined: 22 Mar 2007 Posts: 2320

I wasn't suggesting that the scrollback buffer wasn't releasing memory. I just wanted to check whether the scrollback buffer was large enough to cause the problem. If triggers were turned off, you wouldn't be generating all those lines from the mud, which is what fills up the scrollback buffer. But 4242 lines is probably not the problem.

Are these scripts you posted the only scripts on the session you tested this on? You didn't explicitly say.

Posted: Mon Dec 06, 2010 5:39 pm

Now that you have a way to reproduce the problem, can you start playing with your GMCP triggers to see if you can track down the problem. Some things to try:

1) If you remove the buttons completely, does the memory still increase the same? Don't just disable the button...remove it completely.

2) Start removing some of the sections in the GMCP trigger. For example, how does the memory usage change if you remove the section for assigning the %gmcp.char.vitals data vs removing the %gmcp.char.maxstats data. For example, I'm wondering if there is a problem in CMUD accessing the %gmcp variables for a message that didn't cause the trigger. In other words, if the GMCP message is char.vitals but you access char.status.align, is that causing a memory leak?

3) Does the memory usage scale with the number of %gmcp variables referenced in your GMCP trigger?

Any way you can start simplifying your script to try and nail down the exact problem would be a huge help.

Beginner Joined: 22 Dec 2008 Posts: 21

Rahab,
I was just giving additional information and where my thought process was with regard to scrollback.
Yes, I do clean runs when trying to track down bugs, so what I posted is the only thing in CMUD other than the login triggers (user name and password).

Zugg,
I probably should have put this comment in my original that I did do a test where the GMCP trigger only copied the hp vitals and maxstats with no real change from the worst case test 4.
I will do some additional testing as requested, but I may not be able to post the results until Thursday (long runs and I'm going to be doing some traveling tomorrow and Wednesday with only sporadic Internet access). I may post interim results if anything interesting pops up.
Order of additional tests:

Any other specific combinations you would want?

Posted: Tue Dec 07, 2010 1:28 am

Just keep removing stuff from the GMCP trigger until the memory usage goes away. If you can track it down to a single line in the script, that would be great. I'm not doing the December version until next week, so Thursday is fine.

Beginner Joined: 22 Dec 2008 Posts: 21

Ok, I was actually able to get the testing done enough and the results are interesting (all modifications to script, including deletion of data fields done at the end of previous run after collecting memory information, so that the editor memory use won't impact readings, this was done in all testing so far).

Rates shown are the K per hour increase from start memory to the finish memory readings.
1. Full data copy from GMCP trigger, but buttons completely removed: 56,785K/hr.
2. Copy only vitals hp/mana/moves, and deleted the data fields prior to run: 21,146K/hr
3. Copy only max hp/mana/moves, and deleted the data fields prior to run: 18,029K/hr
4. Copy only vitals hp, and deleted the data fields prior to run: 4,393K/hr
5. Copy nothing, and deleted the data fields prior to run: essentially 0K/hr

You will notice that if you add #2 and #3 together and take into consideration that there were some fields that were being copied in #1 that didn't get copied in either #2 or #3 (i.e. tnl, align, ...), they add up to be approximately the increase rate of #1.
#4 is approximately one third of #2 and #3 (order of magnitude wise, I'm sure if I ran the tests longer they would be a lot closer).
Since having the GMCP trigger still firing, but not copying anything #5, does not cause any memory issue; it appears that any data fields being copied in the GMCP trigger are the culprits in not always being garbage collected when no longer being used.

When I get to a point where I have time and an Internet connection again (Thursday), I can do additional testing, but the only thing I can think of is to copy non-%gmcp fields from inside the GMCP trigger; other than that I don't know what more I can do since it appears that the copying of any data inside the GMCP trigger is what is causing the leak.

Posted: Tue Dec 07, 2010 6:09 pm

I need to come up with a good way to test this offline. Are any of the Gurus interested in putting together a CMUD script that uses #SHOW to send GMCP data to CMUD in a loop of some kind so we can try to ramp this up. A 4MB/hour leak is awfully slow for debugging. We need a way to make this leak more obvious and easier to test.

Actually, here is another test for Delgar to try. In your test #4, what happens if you put your data assignment within your GMCP trigger into a loop. Something like this:

Beginner Joined: 22 Dec 2008 Posts: 21

Good idea (tried this from really slow hotel internet).
This actually found a much higher rate of memory leak.
I used 1000 instead of 100 and with only "loopkill 50" got a memory loss rate of 3,729,150K/hr (yes, 3.7GB/hr).
Usage went from 56,588K to 553,808K in 7 minutes (good thing I didn't try to run the full 500 loops, would have crashed my system if CMUD didn't crash or lock up first).

The test only ran for 23 of the 50 loops before the test port crashed (not due to this), but I figured that was long enough to get us the information needed.

Posted: Wed Dec 08, 2010 10:27 pm

Wow, ok then...that's good info. I'll try putting a #LOOP into my own GMCP trigger and see what happens. It's possible the leak was just too small for me to notice in my normal testing before.

Posted: Wed Dec 08, 2010 10:46 pm

Woot!! That did it. Adding a #LOOP 1000 in my own GMCP trigger also shows the memory leak. So I should be able to track this down and fix it in the next update. Thanks for your patience and help on this.

Posted: Thu Dec 09, 2010 6:29 pm

Well, this is interesting. I played around with this memory leak a bit more and here is what I learned:

1) Doesn't matter if it's in a GMCP trigger or not. Just doing this:

Posted: Thu Dec 09, 2010 7:11 pm

That someone would have been me. I knew I wasn't crazy! I'm just glad that someone was finally able to figure out a way to reproduce it. Thanks!

Wanderer Joined: 23 Apr 2010 Posts: 53

Can I suggest that Delgar gets a magic cookie or something? Maybe change his profile rank from Beginner to "Memory Leak stud." Well done, Delgar.

Posted: Thu Dec 09, 2010 9:28 pm

Cool, I found the leak. It was actually a very common leak, which makes it surprising this was so hard to track down. The routine that handles the "dot" operation with a database variable (like @db.a) had a small leak in it. This leak was exponential based upon the depth of the value. So @db.a only leaked a couple of bytes. But @db.a.b leaked 2-times that amount, and @db.a.b leaked 4-times the amount, etc.

This leak applied to *any* "dot access" of a database variable. Doing something in a loop with a great depth was the key to finding it. Even doing:

Wizard Joined: 22 Mar 2007 Posts: 2320

Woot indeed! And big thanks to Delgar for diligently finding a method for reproducing the problem!