Recursive functions in `try` blocks show super-linear performance and memory usage

Something @jamshark70 and @code2music were working on.

Easiest to show with code

~bad = { |level|
	{                               // << this nesting is the issue
		if(level > 0) {
			~bad.(level - 1)
		} {
			Error("meow").throw 
		};
	}.();
};

~good = {|level|
	if(level > 0) {
		~good.(level - 1)
	} {
		Error("meow").throw 
	};
};
~badTimes = 17.collect {|i| 
	var now = Main.elapsedTime;
	try { ~bad.(i) };
	Main.elapsedTime - now;
};

~goodTimes = 17.collect {|i| 
	var now = Main.elapsedTime;
	try { ~good.(i) };
	Main.elapsedTime - now;
};
[~badTimes, ~goodTimes].plot(separately: false)  

As you can see, the plot of the tested recursion inside of try scaled super-linearly and the non-nested version, when shown on the same scale, can’t even be seen.

@jamshark70 this is the protect issue we were discussing, as protect wraps the function.

If you remove the throwing code, perform scales linearly. It seems to be the act of throwing nested function is the cause of the issue.

If you add an extra wrapper around the bad code, the performance is even worse.

Despite the fact the if statement in the function body looks like a nesting, it isn’t because the compiler inlines it.


This is a bit of conjecture and might be wrong as it right on the limits of the knowledge.

I haven’t spent too long looking into this but this is what I think is happening…

I don’t think the old frames are ever removed from the frame stack as sc implements try by (in my opinion) abusing the return operator ^.

In sc when an error is thrown the current thread’s exception handler is called, passing in the error.
If this is nil, then Nil.handleError is called which calls Object.halt, this clears the vm.

However, in the case of try, the exception handler is the following function…

{ |error|
   thread.exceptionHandler = next; // pop
   ^error
};

Note, that is storing a function with a return ^ to be called by another function later.

When throw is called, this calls that stored functions, making void returnFromMethod(VMGlobals* g) walk all the way up the linked list of frames until it finds the one it expects to return. The execution then continues from there. However, it does not unlink the frames it just called. It needs to otherwise they can’t be recycled by the GC. I think this might be the issue, but don’t have time to look into this more.

1 Like

I’m pretty sure that the problem is in the _GetBackTrace primitive.

If you comment out the use of getBackTrace in Exception *new:

			protectedBacktrace = this.getBackTrace.caller;

^^ comment that line out, then your ~bad function also behaves linearly. (That’s not a solution because it truncates stack traces, but it’s revealing.)

I’m 99.99999% sure that _GetBackTrace is doing something weird with the data structure when it encounters the same function, or function def, while walking the stack.

What is interesting is that it doesn’t happen without the extra layer of wrapping. I don’t have any guesses as to why that would be the case.

I think the logic may be correct, though?

protect {
	... block A...
	protect {
		... block B...
	}
}

At block A, the thread’s exception handler = an open function where next is the old exception handler = nil.

At block B, the thread’s exception handler = an open function where next is the old exception handler = block A’s exception handler.

When B exits, the thread’s exception handler gets set back to A’s exception handler (so B’s exception handler function has no more references). After returning from this method, block B’s next variable disappears. This return goes back to the A prTry invocation.

When A exits, the thread’s exception handler gets set back to nil. At this point, the “A” exception handler function has no more references – it’s unreachable – thus OK to garbage collect. Then ^ returns back to protect.

So at the end, AFAICS, all of the { |error| ... } blocks that you’re referring to should have no remaining references.

(That is… again… the problem really is getBackTrace.)

hjh

Okay I’ve fixed it, PR in coming.

It was an issue with get back trace… but there was no issue with the logic. The issue was that it was making thousands of duplicates. I had previously done some testing looking at allocation and gc usages (which is why I thought it might be a GC bug), but it wasn’t.

I’ve just added some caching and now it is nice and fast.

~bad = { |level|
	{                               // << this nesting is the issue
		if(level > 0) {
			~bad.(level - 1)
		} {
			Error("meow").throw
		};
	}.();
};

~good = {|level|
	if(level > 0) {
		~good.(level - 1)
	} {
		Error("meow").throw
	};
};


~badTimes = 100.collect {|i| 
	var now = Main.elapsedTime;
	try { ~bad.(i) };
	Main.elapsedTime - now;
};

~goodTimes = 100.collect {|i| 
	var now = Main.elapsedTime;
	try { ~good.(i) };
	Main.elapsedTime - now;
};

[~badTimes, ~goodTimes].plot(separately: false);

There is the benchmark (for up to 100 iterations).
It scales linearly but twice as slow compared to the good one, which you’d expect because there are twice as many frames, whereas it did scale super-linearly.

1 Like
3 Likes

:tada::sparkler::tada::sparkler::tada::sparkler::tada:

Fantastic!

This is what I love about open source, pulling together and knocking out a bug. Thanks for looking into it!

hjh

3 Likes