[erlang-bugs] seq_trace broken for a while?

[Kenneth Lundin]

On Feb 10, 2008 11:16 PM, Scott Lystig Fritchie <fritchie@REDACTED> wrote:
> Greetings ... I haven't used seq_trace enough to know if it has ever
> been in a not-broken state, but it seems to be broken in both R11B-5 and
> R12B-1.

seq_trace is not broken at all.
I have run your test program and have explanations for why it does not
work as YOU expect.

In demo5, demo2, demo4 you are relying on the shell process as the
system tracer and expect all trace messages to
be left in the message queue when you call shell_default:flush(). This
is not safe, there are many
messages exchanged to and from the shell and it seems as if some of
the trace messages are
discarded from the message queue while waiting for io-related messages.

In demo1 you are spawning a new process and setting that process to
the system_tracer.
The problem is that the process set to be system tracer also is
involved in the tracing (sending and
receiving messages to be traced) , this does not work since it would
cause infinite loops if the system
tracer it self is part of the tracing.

In demo3 the setup function including the set_token calls is done in a
different function from the one
initiating the messages to be traced.  This means that the tracing is
not activated and nothing will be traced.

The way to solve this and make the sequential tracing work as expected
is to spawn a separate
tracer process which is set as the system tracer.
One example to do this is like this:

tracer() ->
    receive
        {seq_trace,Label,TraceInfo} ->
           print_trace(Label,TraceInfo,false);
        {seq_trace,Label,TraceInfo,Ts} ->
           print_trace(Label,TraceInfo,Ts);
        Other -> ignore
    end,
    tracer().

print_trace(Label,TraceInfo,false) ->
    io:format("~p:",[Label]),
    print_trace(TraceInfo);
print_trace(Label,TraceInfo,Ts) ->
    io:format("~p ~p:",[Label,Ts]),
    print_trace(TraceInfo).

print_trace({print,Serial,From,_,Info}) ->
    io:format("~p Info ~p WITH~n~p~n", [From,Serial,Info]);
print_trace({'receive',Serial,From,To,Message}) ->
    io:format("~p Received ~p FROM ~p WITH~n~p~n",
              [To,Serial,From,Message]);
print_trace({send,Serial,From,To,Message}) ->
    io:format("~p Sent ~p TO ~p WITH~n~p~n",
              [From,Serial,To,Message]).

init_tracer() ->
    Pid = spawn(?MODULE,tracer,[]),
    seq_trace:set_system_tracer(Pid),
    Pid.

stop_tracer(Pid) ->
    seq_trace:set_system_tracer(false),
    exit(Pid,kill).

Use the init_tracer and stop_tracer instead of set_system_tracer(self()).

/Regards Kenneth

> In the attached piece of doodling, tracefoo:demo5() and tracefoo:demo1()
> give a couple of examples of what's going on.  (The other demo*
> functions are attempts to find a pattern in the haystack.)
>
> In demo5(), I was expecting a 'send' and 'receive' trace msgs for the
> 1st & 3rd hops in the message's 3-hop page.  In demo1(), I was expecting
> to see 'send' and 'receive' trace msgs for each of the round-trip
> messages.
>
> Any chance I'm not understanding the 'seq_trace' reference manual?
>
> -Scott
>
> --- snip --- snip --- snip --- snip --- snip ---
>
> -module(tracefoo).
>
> -compile(export_all).
>
> setup() ->
>     seq_trace:set_token(send,true),
>     seq_trace:set_token('receive',true),
>     seq_trace:set_token(timestamp, true),
>     seq_trace:set_token(print,true),
>     ok.
>
> little_child() ->
>     receive {big_parent, Pid} ->
>             Pid ! {little_child_reply, from, self()}
>     end.
>
> %%
> %% R11B-5 and R12B-1:
> %% No send or receive seq_trace messages on 1st & 3rd message hops!
> %% But all print seq_trace messages are printed as expected.
> %% Seq_trace messages related to the io:format() are all (?) present?
> %%
>
> demo5() ->
>     ServerA = spawn(fun server/0),
>     ServerB = spawn(fun server/0),
>     seq_trace:set_system_tracer(self()),
>     timer:sleep(300),                           % no effect...
>     setup(),
>     timer:sleep(300),                           % no effect...
>     Token = seq_trace:get_token(), erlang:display({token_is, Token}),
>     ServerA ! {forward_to, ServerB, {big_parent, self()}},
>     timer:sleep(300),
>     receive X when element(1, X) == little_child_reply ->
>             seq_trace:print({i, am, self(), got, my, ultimate, reply}),
>             io:format("Got X = ~p\n", [X])
>     end,
>     timer:sleep(300),
>     seq_trace:set_system_tracer(false),
>     shell_default:flush().
>
> %%
> %% R11B-5 and R12B-1:
> %% No send or receive seq_trace messages received at all!
> %%
>
> demo1() ->
>     spawn(fun() ->
>                   seq_trace:set_system_tracer(self()),
>                   setup(),
>                   timer:sleep(300),             % No effect...
>                   C1 = spawn(fun little_child/0),
>                   C2 = spawn(fun little_child/0),
>                   C1 ! {big_parent, self()},
>                   C2 ! {big_parent, self()},
>                   timer:sleep(300),
>                   seq_trace:set_system_tracer(false),
>                   shell_default:flush()
>           end),
>     timer:sleep(2*1000).
>
> %% Variations on the theme....
>
> demo2() ->
>     seq_trace:set_system_tracer(self()),
>     spawn(fun() ->
>                   setup(),
>                   C1 = spawn(fun little_child/0),
>                   C2 = spawn(fun little_child/0),
>                   C1 ! {big_parent, self()},
>                   C2 ! {big_parent, self()},
>                   timer:sleep(1*1000),
>                   ok
>           end),
>     timer:sleep(2*1000),
>     seq_trace:set_system_tracer(false),
>     shell_default:flush().
>
> demo3() ->
>     seq_trace:set_system_tracer(self()),
>     setup(),
>     spawn(fun() ->
>                   C1 = spawn(fun little_child/0),
>                   C2 = spawn(fun little_child/0),
>                   C1 ! {big_parent, self()},
>                   C2 ! {big_parent, self()},
>                   timer:sleep(1*1000),
>                   ok
>           end),
>     timer:sleep(2*1000),
>     seq_trace:set_system_tracer(false),
>     shell_default:flush().
>
> demo4() ->
>     seq_trace:set_system_tracer(self()),
>     setup(),
>     spawn(fun() ->
>                   setup(),
>                   C1 = spawn(fun little_child/0),
>                   C2 = spawn(fun little_child/0),
>                   timer:sleep(100),
>                   setup(),
>                   C1 ! {big_parent, self()},
>                   C2 ! {big_parent, self()},
>                   seq_trace:set_token(label, 77),
>                   timer:sleep(1*1000),
>                   ok
>           end),
>     timer:sleep(2*1000),
>     seq_trace:set_system_tracer(false),
>     shell_default:flush().
>
> server() ->
>     receive
>         {forward_to, NewPid, Msg} ->
>             seq_trace:print({i, am, self(), forwarding, to, NewPid}),
>             NewPid ! Msg;
>         {big_parent, Pid} ->
>             seq_trace:print({i, am, self(), replying, to, Pid}),
>             Pid ! {little_child_reply, from, self()}
>     end.
>
> demo6() ->
>     seq_trace:set_system_tracer(self()),
>     setup(),
>     ServerA = spawn(fun server/0),
>     ServerB = spawn(fun server/0),
>     ServerA ! {forward_to, ServerB, {big_parent, self()}},
>     timer:sleep(100),
>     seq_trace:set_system_tracer(false),
>     shell_default:flush().
>
> _______________________________________________
> erlang-bugs mailing list
> erlang-bugs@REDACTED
> http://www.erlang.org/mailman/listinfo/erlang-bugs
>