My Script is slowly running out of Memory

[Bones Outlander]

Hi,

I have a history logging script that receives data (Avatar name, Status -  a 0 or 1 and a UnixTime Timestamp) from another script via a link_message and stores the data in a list.

Once llGetFreeMemory reports less that 6000 bytes, for each new data message received  I delete the oldest entry from the list.

But for some reason the script slowly keeps eating up memory until I get a stack heap error. 

I know all link_messages get processed by all scripts, but any messages I pass to scripts are less than 500 bytes so I've allowed 6000 bytes as a buffer. 

I recently added the llSetMemoryLimit lines to try to force a memory cleanup but that didn't resolve the issue and eventually I get a stack-heap error (can take several days or even weeks). 

Here is a simplified version of my script that exhibits the issue, am I doing something wrong in here somewhere?

Many thanks
Bones 

 

// History Logger

list lHistory;
integer iZoneOffset;

default
{

    state_entry()
    {
    }


    link_message(integer sender_num, integer num, string str, key id)
    {

        if (num == 2){
            if ( llGetFreeMemory() < 6000) {
                lHistory = llDeleteSubList(lHistory,0,3); // Remove the oldest entry from history
                integer memlimit = llGetMemoryLimit(); // how much are we allowed?
                llSetMemoryLimit(memlimit-1); // reduce by 1 to force GC
                llSetMemoryLimit(memlimit); // set it back
            }
            list lTemp = llParseString2List(str,[","],[]);
            integer iTimestamp=llGetUnixTime() + iZoneOffset;
            string sVar1 = llList2String(lTemp,0); // Avatar Name
            integer iVar2 = llList2Integer(lTemp,1); // Status (1=online 0=offline)
            integer iPrevUnixTime = llList2Integer(lTemp,2) + iZoneOffset; // Last login/logout adjusted to Time Zone
            lHistory = lHistory + [iTimestamp] + [sVar1] + [iVar2] + [iPrevUnixTime];

        }
        else if (num == 11){  // Receive Zone Time Offset in seconds, including DST adjustment
            iZoneOffset = (integer)str;          
        }
           
        else if (num==99){  // Receive Hello request (to test which scripts have died)
            integer iLength = llGetListLength(lHistory)/4;
            llOwnerSay("Hello from the History Server Script, Free Memory: " +(string)llGetFreeMemory() + " / Lines recorded: " + (string)iLength);
        }
      }
}

 

Edited November 12, 2022 by Bones Outlander

[Anna Salyx]

1 hour ago, Bones Outlander said:

lHistory = lHistory + [iTimestamp] + [sVar1] + [iVar2] + [iPrevUnixTime];

I'm curious.  The wiki on lists comments that the preferred method to append to a list for  single items is: list = list + item.   Where "item" is NOT present as a list (ie: [item]). Why not do it this way instead?:

• lHistory = lHistory + iTimestamp + sVar1 + iVar2 + iPrevUnixTime; 

 Honestly, I"m not sure if the way you are currently appending to the list is or is not causing some extra issue in the background. I do know that presenting the variables as list items does cause an initial extra memory usage since you're creating a set of temporary adhoc list elements in place.  They way you're appending, you're using 6 lists while the command runs (the final list, the initial list being overwritten, and the 4 list elements being appended). This is pointed out in the wiki as a consideration when using list elements to append to an existing list instead of simple variables and that it does affect memory usage at the time.  and IMO it might affect overall memory usage over time, but someone might correct me on that.

Now,  in a small test run of 4 elements just now* I noticed a slight memory memory savings of doing it list = list + var + var + var + var, instead of list = list + [var] + [var] + [var] + [var].  Is the tiny savings, or lack of, over time going to significant, I can't say, but there is a different of a few bytes between the two methods.

additionally (and i'm sure someone will correct me if I'm mistaken) but garbage clean up does not happen inside an event/function.  so your line to 'force GC' might not be doing what you think it's doing. 

just wild thoughts.   also, what started off as just a simple question kinda went off the rails.  sorry for all the extra in there.

 

*My test was create a list of 4 mixed variables, create 4 mixed variables to append, and before I append to delete (as a sublist) the first 4 element.

 

[Fenix Eldritch]

I modified your script slightly to have some additional diagnostic reports:

• Added global integer variable "count" which tracks number of full records added.
  • count is incremented after adding a new record.
  • count is decremented when removing the oldest record.
• Added llOwnerSay("prune:"+(string)llGetFreeMemory()+" "+(string)count); to the start of the code block for removing the oldest record.
• Added llOwnerSay("prune end"); to the end of the code block for removing the oldest record.
• Added llSetText((string)count,<1,1,1>,1.0); after adding a full record to display total contents visibly on prim.

Next I used this companion script to drive the test:

integer toggle = FALSE;
integer count;

default
{
    touch_start(integer total_number)
    {
        if(toggle = !toggle)
        {
            llOwnerSay("started");
            count = 0;
            llSetTimerEvent(0.075);
        }
        else
        {
            llOwnerSay("stopped");
            llSetTimerEvent(0.0);
            llMessageLinked(2, 99, "", "");
        }
    }
    
    timer()
    {
        count++;
        if(count%100 ==0)
        {
            llMessageLinked(2, 99, "", "");
        }
        llMessageLinked(2, 2, "Fenix Eldritch,1,"+(string)llGetUnixTime(), "");
    }
}

It will rapid-fire populate your history script and also initiate a status report about every 100 entries. Within a minute I got the stack heap collision:

[06:38] A: started
[06:38] B: Hello from the History Server Script, Free Memory: 50190 / Lines recorded: 99
[06:38] B: Hello from the History Server Script, Free Memory: 40790 / Lines recorded: 199
[06:38] B: Hello from the History Server Script, Free Memory: 31390 / Lines recorded: 299
[06:38] B: Hello from the History Server Script, Free Memory: 21694 / Lines recorded: 399
[06:38] B: Hello from the History Server Script, Free Memory: 12294 / Lines recorded: 499
[06:39] B: prune:5996 566

It blew up on the very first prune. It didn't even get to the end of the prune block, which indicates to me that it's running out of memory while trying to remove the oldest entry for the very first time.

LSL passes its variables "by value" meaning it creates a temporary copy of them in memory when passing them to functions. So when you call llDeleteSublist(lHistory,0,3) for a brief moment, you have two copies of that list - which pushes you well over the memory limit.

I think you need to perform your cleanup much earlier, at a point where you have more memory memory to work with the lists. I doubled the memory cutoff limit from 6000 to 12000 and that seemed to work. But I would strongly suggest you also remove more than just one entry. Otherwise you're going to be doing cleanup for every new entry added after you hit the initial threshold - and that's a lot of thrashing that can easily be minimized. Perhaps remove 400 list entries (100 full records) when you prune. That will give you some more breathing space.

Edit: I must be incorrect about the list duplication, that might only apply to user functions? Because at the point when you perform your prune, you're using about 53kb. And with 12k remaining, that's not enough to hold a 2nd copy but it is enough to keep the script going through the prune process. Not exactly sure what is going on under the hood...

Edited November 12, 2022 by Fenix Eldritch
striking out possibly incorrect info

[Frionil Fang]

Not in a position to test for this particular case, but I had the issue on a very memory constrained script where it would run out of memory erratically doing the same, predictable operation with exact same data. What fixed it was adding a single frame of llSleep after freeing memory; it's like the internal tally of available memory is updated at the start/end of an execution frame, so forcing that llSleep(0.001) to skip to the next execution frame stabilized the script and the reported free memory.

Maybe try to drop that sleep in after the list deletion and/or garbage collection attempt.

[Fenix Eldritch]

Did a little more tinkering and found that simply deleting 80 list entries (20 full records) in your prune code block seems to be enough to keep the script going, even if you keep your original memory cutoff point at 6000 bytes.

lHistory = llDeleteSubList(lHistory,0,79); // Remove the oldest 20 records (1 rec = 4 list elements) from history

I'm a bit more confused now about the overhead of llDeleteSubList, but it seems that with about 6k remaining, it wasn't able to operate on your list to return that massive list minus 4 entries. Taking out 80 at a time seems to be more manageable for it at that point.

Edited November 12, 2022 by Fenix Eldritch

[Bones Outlander]

Thank you everybody for your responses.

@Fenix Eldritchthank you so much for going to the trouble of testing this.

I have setup the same test as you, but even deleting 20 list entries at a time I get a crash at the 6000 limit, and even at 10000. I had to go to 12000 before the crash stopped.

At 12000 I can delete 1 list entry at a time without a crash, but get your point that that is a  forcing  a lot of cleaning up, so will stick with the 20 entries.

I'll do some more testing here and see if I find anything else useful.

 

[Fenix Eldritch]

16 minutes ago, Bones Outlander said:

I have setup the same test as you, but even deleting 20 list entries at a time I get a crash at the 6000 limit

Just to be clear, when you say "20 list entries" are you talking about the individual elements in the list, or the strided "records" that are comprised of 4 list elements (timestamp, avatar name, online_status, previous_timestamp).

Because I also tried removing 10 records (40 list elements) and that still produced a crash when the memory limit was 6k. When you're pruning the list, make sure you're doing the proper amount.

[Bones Outlander]

I was using the line as per your message above:

lHistory = llDeleteSubList(lHistory,0,79);

I think this is also related to the speed in which the data is coming through, maybe if the logger script is having to buffer a few lines it overflows before the pruning can happen.

Edited November 13, 2022 by Bones Outlander

[Bones Outlander]

 

OK, so this is interesting ....  I think.

I ran with the 6000 threshold, removing 79 entries in a prune, and adding 1 entry per second.

I don't get a crash, but it runs several prunes before the memory frees up. 

In fact the memory free drops from 5932 to 306 after removing 20 lines (80 entries)! 

Here are my two scripts

// main script
integer toggle = FALSE;
integer count;

default
{
    touch_start(integer total_number)
    {
        if(toggle = !toggle)
        {
            llOwnerSay("started");
            count = 0;
            llSetTimerEvent(1.0);
        }
        else
        {
            llOwnerSay("stopped");
            llSetTimerEvent(0.0);
            llMessageLinked(LINK_THIS, 99, "", "");
        }
    }
    
    timer()
    {
        count++;
        if(count%100 ==0)
        {
            llMessageLinked(LINK_THIS, 99, "", "");
        }
        llMessageLinked(LINK_THIS, 2, "Fenix Eldritch,1,"+(string)llGetUnixTime(), "");
    }
}

  

// History Logger

list lHistory;
integer iZoneOffset;
integer count;

default
{

    state_entry()
    {
    }


    link_message(integer sender_num, integer num, string str, key id)
    {
       
        if (num == 2){
            if ( llGetFreeMemory() < 6000) {
                count = llGetListLength(lHistory)/4;
                llOwnerSay("prune start:"+(string)llGetFreeMemory()+" "+(string)count);
                lHistory = llDeleteSubList(lHistory,0,79); // Remove the oldest entry from history
                integer memlimit = llGetMemoryLimit(); // how much are we allowed?
                llSetMemoryLimit(memlimit-1); // reduce by 1 to force GC
                llSetMemoryLimit(memlimit); // set it back
                count = llGetListLength(lHistory)/4;
                llOwnerSay("prune end:"+(string)llGetFreeMemory()+" "+(string)count);
            }
            string sLoginLogout;
            list lTemp = llParseString2List(str,[","],[]);
            integer iTimestamp=llGetUnixTime() + iZoneOffset;
            string sVar1 = llList2String(lTemp,0); // Avatar Name
            integer iVar2 = llList2Integer(lTemp,1); // Status (1=online 0=offline)
            integer iPrevUnixTime = llList2Integer(lTemp,2) + iZoneOffset; // Last login/logout adjusted to Time Zone
            lHistory = lHistory + [iTimestamp] + [sVar1] + [iVar2] + [iPrevUnixTime];
            count = llGetListLength(lHistory)/4;
            llSetText((string)count,<1,1,1>,1.0); 

        }
        else if (num == 11){  // Receive Zone Time Offset in seconds, including DST adjustment
            iZoneOffset = (integer)str;          
        }
           
        else if (num==99){  // Receive Hello request (to test which scripts have died)
            integer iLength = llGetListLength(lHistory)/4;
            llOwnerSay("Hello from the History Server Script, Free Memory: " +(string)llGetFreeMemory() + " / Lines recorded: " + (string)iLength);
        }
      }
}

 

And the output

[17:04] History Tester 6k: started
[17:06] History Tester 6k: Hello from the History Server Script, Free Memory: 49678 / Lines recorded: 99
[17:08] History Tester 6k: Hello from the History Server Script, Free Memory: 40278 / Lines recorded: 199
[17:09] History Tester 6k: Hello from the History Server Script, Free Memory: 30878 / Lines recorded: 299
[17:11] History Tester 6k: Hello from the History Server Script, Free Memory: 21160 / Lines recorded: 399
[17:13] History Tester 6k: Hello from the History Server Script, Free Memory: 11760 / Lines recorded: 499
[17:14] History Tester 6k: prune start:5932 561
[17:14] History Tester 6k: prune end:306 541
[17:14] History Tester 6k: prune start:106 542
[17:14] History Tester 6k: prune end:1788 522
[17:14] History Tester 6k: prune start:1788 523
[17:14] History Tester 6k: prune end:3270 503
[17:14] History Tester 6k: prune start:3270 504
[17:14] History Tester 6k: prune end:12944 484
[17:14] History Tester 6k: Hello from the History Server Script, Free Memory: 9880 / Lines recorded: 519
[17:15] History Tester 6k: prune start:5932 561
[17:15] History Tester 6k: prune end:306 541
[17:15] History Tester 6k: prune start:106 542
[17:15] History Tester 6k: prune end:1788 522
[17:15] History Tester 6k: prune start:1788 523
[17:15] History Tester 6k: prune end:3270 503
[17:15] History Tester 6k: prune start:3270 504
[17:15] History Tester 6k: prune end:12944 484
[17:16] History Tester 6k: Hello from the History Server Script, Free Memory: 8000 / Lines recorded: 539
[17:16] History Tester 6k: prune start:5932 561
[17:16] History Tester 6k: prune end:306 541
[17:16] History Tester 6k: prune start:106 542
[17:16] History Tester 6k: prune end:1788 522
[17:16] History Tester 6k: prune start:1788 523
[17:16] History Tester 6k: prune end:3270 503
[17:16] History Tester 6k: prune start:3270 504
[17:16] History Tester 6k: prune end:12944 484
[17:18] History Tester 6k: Hello from the History Server Script, Free Memory: 6120 / Lines recorded: 559
[17:18] History Tester 6k: prune start:5932 561
[17:18] History Tester 6k: prune end:306 541
[17:18] History Tester 6k: prune start:106 542
[17:18] History Tester 6k: prune end:1788 522
[17:18] History Tester 6k: prune start:1788 523
[17:18] History Tester 6k: prune end:3270 503
[17:18] History Tester 6k: prune start:3270 504
[17:18] History Tester 6k: prune end:12944 484
[17:19] History Tester 6k: prune start:5932 561
[17:19] History Tester 6k: prune end:306 541
[17:19] History Tester 6k: prune start:106 542
[17:19] History Tester 6k: prune end:1788 522
[17:19] History Tester 6k: prune start:1788 523
[17:19] History Tester 6k: prune end:3270 503
[17:19] History Tester 6k: prune start:3270 504
[17:19] History Tester 6k: prune end:12944 484
[17:19] History Tester 6k: Hello from the History Server Script, Free Memory: 11760 / Lines recorded: 499
[17:20] History Tester 6k: prune start:5932 561
[17:20] History Tester 6k: prune end:306 541
[17:20] History Tester 6k: prune start:106 542
[17:20] History Tester 6k: prune end:1788 522
[17:20] History Tester 6k: prune start:1788 523
[17:20] History Tester 6k: prune end:3270 503
[17:20] History Tester 6k: prune start:3270 504
[17:20] History Tester 6k: prune end:12944 484
[17:20] History Tester 6k: stopped
[17:20] History Tester 6k: Hello from the History Server Script, Free Memory: 12512 / Lines recorded: 491

 

Edited November 13, 2022 by Bones Outlander

[Bones Outlander]

Changing the timer back to .075 and I do get a crash.

[19:29] History Tester 6k: started
[19:29] History Tester 6k: Hello from the History Server Script, Free Memory: 49678 / Lines recorded: 99
[19:29] History Tester 6k: Hello from the History Server Script, Free Memory: 40278 / Lines recorded: 199
[19:29] History Tester 6k: Hello from the History Server Script, Free Memory: 30878 / Lines recorded: 299
[19:30] History Tester 6k: Hello from the History Server Script, Free Memory: 21160 / Lines recorded: 399
[19:30] Avi-HUD+ 3.05: Tamara status changed to online on Sat 11/12/2022 at 7:30 pm. Previous logout was on Sat 11/12/2022 at 4:15 am. (15 hours and 14 minutes ago)
[19:30] History Tester 6k: prune start:5932 561
[19:30] History Tester 6k: prune end:306 541
[19:30] History Tester 6k: prune start:106 542
[19:30] History Tester 6k: prune end:1788 522
[19:30] History Tester 6k: prune start:1788 523
[19:30] History Tester 6k: prune end:3270 503
[19:30] History Tester 6k: prune start:3270 504
[19:30] History Tester 6k: prune end:12944 484
[19:30] History Tester 6k: Hello from the History Server Script, Free Memory: 8094 / Lines recorded: 538
[19:30] History Tester 6k: prune start:5932 561
[19:30] History Tester 6k: prune end:306 541
[19:30] History Tester 6k: prune start:106 542
[19:30] History Tester 6k: prune end:1788 522
[19:30] History Tester 6k: prune start:1788 523
[19:30] History Tester 6k: prune end:3270 503
[19:30] History Tester 6k: prune start:3270 504
[19:30] History Tester 6k: prune end:12944 484
[19:30] History Tester 6k: Hello from the History Server Script, Free Memory: 9974 / Lines recorded: 518
[19:30] History Tester 6k: prune start:5932 561

And it crashed at the prune.

Adding in a llSleep (I tried .001, .5 and 1)  immediately after the llSetMemoryLimit(memlimit) line seems to stop the crash at the .075 timer value, but it still does 4 prunes before the memory is released back over 6000 bytes.

I was expecting the sleep to allow the memory to free up in one pass.

Edited November 13, 2022 by Bones Outlander

[Wulfie Reanimator]

8 hours ago, Bones Outlander said:

Here are my two scripts

Testing these has made my brain hurt. A lot. 😩

Things I've experienced:

• Garbage collection just doesn't happen.. for minutes.. with an empty list and no event queue.
• The script crashes between lowering the memory limit and resetting it.
• The script crashes at random points after llDeleteSubList, depending on which calls would come after it.
  (The script will crash at the same line every time, if no code is changed.)
  • if there's 4 llOwnerSay (raw string input) calls and llGetListLength, it crashes on llGetListLength.
  • if there's 3 llOwnerSay (raw string input) calls and llSetColor, it crashes after the first llOwnerSay.
  • if there's just llOwnerSay(llGetFreeMemory()), it crashes before output.
  • A ""working"" script will stop working if I only remove debug logging from outside of the branch where pruning is done.
• The script correctly prunes data and memory is instantly freed when starting from a pre-filled list (llGenerateKey) for quicker testing.

Honestly, just wait for Linkset Data to be released in the next week or two and run away from all this.

Edited November 13, 2022 by Wulfie Reanimator

[Bones Outlander]

Thanks Wulfie,

I think you may well be right, I'd better start reading up on Linkset Data, although there are bound to be a few "undocumented features" in that too! 

Edited November 13, 2022 by Bones Outlander

[Bones Outlander]

I've been running the script with the 12000 memory limit now for 8 hours and it seems pretty stable.

The available memory reported with the hello message fluctuates between around  11500 and 14300 (depending on the number of recorded lines being reported) but memory doesn't seem to be getting any lower over time, so that's a good sign.

 

Edited November 13, 2022 by Bones Outlander

[primerib1]

With the new LSD feature now Generally Available, maybe you can use that instead.

More memory available (64 KiB!), faster read/write, and you can implement some garbage collection strategy if the number of keys are above a certain watermark.