How does a try/rescue on a recursive function call affect the stack?

Questions / Help
1

So, awhile back while working on WebSockex I noticed that my stack didn’t look tail-optimized. I was working on something else and forgot about it.

After seeing it for a second time, I realized that it was just because I was using rescue and it was capturing the stack from where the try started. The rescue was scoped to the function so it started as soon as the function was invoked. Here’s the trace:

Removing the rescue makes tail-call optimization work as expected:

Now, obviously in hindsight this was a terrible idea. I just want to know what exactly is going on?

Multiple invocations aren’t producing an infinite stack, which is what I would expect.

But it also isn’t perfect, here is another instance where I do slightly different things to get a different trace:

But I can send and receive any number of WebSocket frames after that without the stack increasing.

Now, I’m sure there are many other ways to increase the stack because of what I did. But I am more curious on why every frame isn’t increasing the stack.

If you want to replicate this and see what I am talking about, clone the WebSockex, git checkout e95b87e, then do the normal mix deps.get. After that:

iex -S mix run ./examples/echo_client.exs

... Stuff Happens ...

iex>:observer.start
iex>{:ok, pid} = EchoClient.start_link
iex>EchoClient.echo(pid, "Blah!")
iex>WebSockex.send_frame(pid, :ping)

No matter how many times I do EchoClient.echo(pid, String.t) or WebSockex.send_frame(pid, :ping | :pong) the stack won’t increase past a certain point.

Anyway, if nothing else I found it interesting. But I was hoping someone could provide some insight. :smiley_cat:

2

Not sure why you are observing inconsistent behaviour but:

Note that calls inside try/1 are not tail recursive since the VM needs to keep the stacktrace in case an exception happens.

See also Learn You Some Erlang: Errors and Exceptions:

Note: It is important to know that the protected part of an exception can’t be tail recursive. The VM must always keep a reference there in case there’s an exception popping up.

PS: this is the first time I’ve seen a rescue without a try anywhere in sight.

OK, there it is. That section really needs a similar warning about the total lack of tail call optimization as effectively the entire function body is a “protected area”.

3

That’s the thing though, there’s obviously SOME kind of tail-optimization going on. Otherwise the stack would just keep increasing.

4

I think your issue is with observer or how you are using it because the stack is in fact growing:

iex(2)> {:ok, pid} = EchoClient.start_link
{:ok, #PID<0.185.0>}
iex(3)> Process.info(pid,[:stack_size])
[stack_size: 35]
iex(4)> EchoClient.echo(pid, "Blah!")
:ok
10:39:21.179 [info]  Sending message: Blah!
iex(5)> 
10:39:21.229 [info]  Received Message: Blah!
iex(5)> Process.info(pid,[:stack_size])
[stack_size: 98]
iex(6)> WebSockex.send_frame(pid, :ping)
:ok
iex(7)> Process.info(pid,[:stack_size]) 
[stack_size: 116]
iex(8)> WebSockex.send_frame(pid, :pong)
:ok
iex(9)> Process.info(pid,[:stack_size]) 
[stack_size: 125]
iex(10)> EchoClient.echo(pid, "Blah!01") 
10:41:11.922 [info]  Sending message: Blah!01
:ok
iex(11)> 
10:41:11.975 [info]  Received Message: Blah!01
iex(11)> Process.info(pid,[:stack_size]) 
[stack_size: 134]
iex(12)> EchoClient.echo(pid, "Blah!02") 
:ok
10:41:39.224 [info]  Sending message: Blah!02
iex(13)> 
10:41:39.272 [info]  Received Message: Blah!02
iex(13)> Process.info(pid,[:stack_size])
[stack_size: 143]
iex(14)> WebSockex.send_frame(pid, :ping)
:ok
iex(15)> Process.info(pid,[:stack_size]) 
[stack_size: 152]
iex(16)> WebSockex.send_frame(pid, :pong)
:ok
iex(17)> Process.info(pid,[:stack_size]) 
[stack_size: 152]
iex(18)> EchoClient.echo(pid, "Blah!03") 
10:42:26.257 [info]  Sending message: Blah!03
:ok
iex(19)> 
10:42:26.313 [info]  Received Message: Blah!03
iex(19)> Process.info(pid,[:stack_size])
[stack_size: 161]
iex(20)> EchoClient.echo(pid, "Blah!04")
10:42:35.218 [info]  Sending message: Blah!04
:ok
iex(21)> 
10:42:35.263 [info]  Received Message: Blah!04
iex(21)> Process.info(pid,[:stack_size]) 
[stack_size: 170]
iex(22)> EchoClient.echo(pid, "Blah!05")
10:42:48.144 [info]  Sending message: Blah!05
:ok
iex(23)> 
10:42:48.192 [info]  Received Message: Blah!05
iex(23)> Process.info(pid,[:stack_size])
[stack_size: 179]
iex(24)> EchoClient.echo(pid, "Blah!06")
10:43:11.657 [info]  Sending message: Blah!06
:ok
iex(25)> 
10:43:11.704 [info]  Received Message: Blah!06
iex(25)> Process.info(pid,[:stack_size])
[stack_size: 188]
iex(26)> EchoClient.echo(pid, "Blah!07")
:ok
10:43:37.664 [info]  Sending message: Blah!07
iex(27)> 
10:43:37.711 [info]  Received Message: Blah!07
iex(27)> Process.info(pid,[:stack_size])
[stack_size: 197]

On a side note - while looking into this I came across this interesting message from Joe Armstrong: He refers to what Erlang actually does as “Last Call Optimization” as he finds that “Tail Call Optimization” isn’t broad enough.

2 Likes
5

Indeed, thanks for that. It’s so it’s just the Stack Trace that is doing something that is more readable.

6

It’s actually not Observer’s fault - it is just displaying what it is getting back from process_info.

{current_stacktrace, Stack}
Returns the current call stack back-trace (stacktrace) of the process. The stack has the same format as returned by erlang:get_stacktrace/0. The depth of the stacktrace is truncated according to the backtrace_depth system flag setting.

Seems the default setting for backtrace_depth is 8 and once you increase its length it is allowed to grow further - though even then there seems to be some opportunistic dropping of “repetition” in order to capture more important (i.e. different) information in this “truncated stack log”.

So really it is more like a truncated process stack log rather than a true representation of the current process stack state (and the stack frames that reside on it).

iex(1)> 
12:34:50.885 [info]  Local close with reason: :normal
{:ok, pid} = EchoClient.start_link
{:ok, #PID<0.165.0>}
iex(2)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 44,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(3)> EchoClient.echo(pid, "Blah!")                      
12:39:27.526 [info]  Sending message: Blah!
:ok
iex(4)> 
12:39:27.576 [info]  Received Message: Blah!
iex(4)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 71,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(5)> WebSockex.send_frame(pid, :ping)
:ok
iex(6)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 89,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(7)> EchoClient.echo(pid, "Blah!01")                    
:ok
12:40:26.597 [info]  Sending message: Blah!01
iex(8)> 
12:40:26.647 [info]  Received Message: Blah!01
iex(8)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 98,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(9)> EchoClient.echo(pid, "Blah!02")                    
:ok
12:40:53.656 [info]  Sending message: Blah!02
iex(10)> 
12:40:53.708 [info]  Received Message: Blah!02
iex(10)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 107,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(11)> EchoClient.echo(pid, "Blah!03")                    
:ok
12:41:20.079 [info]  Sending message: Blah!03
iex(12)> 
12:41:20.129 [info]  Received Message: Blah!03
iex(12)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 116,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(13)> :erlang.system_flag(:backtrace_depth,100)
8
iex(14)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 233,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(15)> EchoClient.echo(pid, "Blah!04")                    
:ok
12:48:32.851 [info]  Sending message: Blah!04
iex(16)> 
12:48:32.898 [info]  Received Message: Blah!04
iex(16)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 251,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(17)> EchoClient.echo(pid, "Blah!05")                    
12:48:56.253 [info]  Sending message: Blah!05
:ok
iex(18)> 
12:48:56.300 [info]  Received Message: Blah!05
iex(18)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 260,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(19)> EchoClient.echo(pid, "Blah!06")                    
:ok
12:49:55.404 [info]  Sending message: Blah!06
iex(20)> 
12:49:55.452 [info]  Received Message: Blah!06
iex(20)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 278,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]
iex(21)> EchoClient.echo(pid, "Blah!07")                    
12:50:24.281 [info]  Sending message: Blah!07
:ok
iex(22)> 
12:50:24.354 [info]  Received Message: Blah!07
iex(22)> Process.info(pid,[:stack_size,:current_stacktrace])
[stack_size: 287,
 current_stacktrace: [{WebSockex, :websocket_loop, 3,
   [file: 'lib/websockex.ex', line: 409]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 463]},
  {WebSockex, :common_handle, 4, [file: 'lib/websockex.ex', line: 467]},
  {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]]