%% %% %CopyrightBegin% %% %% Copyright Ericsson AB 1999-2009. All Rights Reserved. %% %% The contents of this file are subject to the Erlang Public License, %% Version 1.1, (the "License"); you may not use this file except in %% compliance with the License. You should have received a copy of the %% Erlang Public License along with this software. If not, it can be %% retrieved online at http://www.erlang.org/. %% %% Software distributed under the License is distributed on an "AS IS" %% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See %% the License for the specific language governing rights and limitations %% under the License. %% %% %CopyrightEnd% %% -module(trace_port_SUITE). -export([all/1,init_per_testcase/2,fin_per_testcase/2, call_trace/1, return_trace/1, send/1, receive_trace/1, process_events/1, schedule/1, fake_schedule/1, fake_schedule_after_register/1, fake_schedule_after_getting_linked/1, fake_schedule_after_getting_unlinked/1, gc/1, default_tracer/1]). -include("test_server.hrl"). test_cases() -> [call_trace, return_trace, send, receive_trace, process_events, schedule, fake_schedule, fake_schedule_after_register, fake_schedule_after_getting_linked, fake_schedule_after_getting_unlinked, gc, default_tracer]. all(suite) -> test_cases(). init_per_testcase(Func, Config) when is_atom(Func), is_list(Config) -> Dog = ?t:timetrap(?t:seconds(30)), [{watchdog, Dog}|Config]. fin_per_testcase(_Func, Config) -> Dog = ?config(watchdog, Config), ?t:timetrap_cancel(Dog). call_trace(doc) -> "Test sending call trace messages to a port."; call_trace(Config) when is_list(Config) -> case test_server:is_native(?MODULE) of true -> {skip,"Native code"}; false -> ?line start_tracer(Config), Self = self(), ?line trace_func({lists,reverse,1}, []), ?line trace_pid(Self, true, [call]), ?line trace_info(Self, flags), ?line trace_info(Self, tracer), ?line [b,a] = lists:reverse([a,b]), ?line expect({trace,Self,call,{lists,reverse,[[a,b]]}}), ?line trace_pid(Self, true, [timestamp]), ?line trace_info(Self, flags), ?line Huge = huge_data(), ?line lists:reverse(Huge), ?line expect({trace_ts,Self,call,{lists,reverse,[Huge]},ts}), ?line trace_pid(Self, true, [arity]), ?line trace_info(Self, flags), ?line [y,x] = lists:reverse([x,y]), ?line expect({trace_ts,Self,call,{lists,reverse,1},ts}), ?line trace_pid(Self, false, [timestamp]), ?line trace_info(Self, flags), ?line [z,y,x] = lists:reverse([x,y,z]), ?line expect({trace,Self,call,{lists,reverse,1}}), %% OTP-7399. Delayed sub-binary creation optimization. ?line trace_pid(Self, false, [arity]), ?line trace_info(Self, flags), ?line trace_func({?MODULE,bs_sum_c,2}, [], [local]), ?line 26 = bs_sum_c(<<3:4,5:4,7:4,11:4>>, 0), ?line trace_func({?MODULE,bs_sum_c,2}, false, [local]), ?line expect({trace,Self,call,{?MODULE,bs_sum_c,[<<3:4,5:4,7:4,11:4>>,0]}}), ?line expect({trace,Self,call,{?MODULE,bs_sum_c,[<<5:4,7:4,11:4>>,3]}}), ?line expect({trace,Self,call,{?MODULE,bs_sum_c,[<<7:4,11:4>>,8]}}), ?line expect({trace,Self,call,{?MODULE,bs_sum_c,[<<11:4>>,15]}}), ?line expect({trace,Self,call,{?MODULE,bs_sum_c,[<<>>,26]}}), ?line trace_func({lists,reverse,1}, false), ok end. bs_sum_c(<>, Acc) -> bs_sum_c(T, H+Acc); bs_sum_c(<<>>, Acc) -> Acc. return_trace(doc) -> "Test the new return trace."; return_trace(Config) when is_list(Config) -> case test_server:is_native(?MODULE) of true -> {skip,"Native code"}; false -> ?line start_tracer(Config), Self = self(), MFA = {lists,reverse,1}, %% Plain (no timestamp, small data). ?line trace_func(MFA, [{['$1'],[],[{return_trace}, {message,false}]}]), ?line trace_pid(Self, true, [call]), ?line trace_info(Self, flags), ?line trace_info(Self, tracer), ?line trace_info(MFA, match_spec), ?line {traced,global} = trace_info(MFA, traced), ?line [b,a] = lists:reverse([a,b]), ?line expect({trace,Self,return_from,MFA,[b,a]}), %% Timestamp, huge data. ?line trace_pid(Self, true, [timestamp]), ?line Result = lists:reverse(huge_data()), ?line expect({trace_ts,Self,return_from,MFA,Result,ts}), %% Turn off trace. ?line trace_func(MFA, false), ?line trace_info(MFA, match_spec), ?line {traced,false} = trace_info(MFA, traced), ok end. send(doc) -> "Test sending send trace messages to a port."; send(Config) when is_list(Config) -> ?line Tracer = start_tracer(Config), Self = self(), ?line Sender = fun_spawn(fun sender/0), ?line trac(Sender, true, [send]), %% Simple message, no timestamp. ?line Bin = list_to_binary(lists:seq(1, 10)), ?line Msg = {some_data,Bin}, Sender ! {send_please,self(),Msg}, receive Msg -> ok end, ?line expect({trace,Sender,send,Msg,Self}), %% Timestamp. BiggerMsg = {even_bigger,Msg}, ?line trac(Sender, true, [send,timestamp]), Sender ! {send_please,self(),BiggerMsg}, receive BiggerMsg -> ok end, ?line expect({trace_ts,Sender,send,BiggerMsg,Self,ts}), %% Huge message. ?line HugeMsg = huge_data(), Sender ! {send_please,self(),HugeMsg}, receive HugeMsg -> ok end, ?line expect({trace_ts,Sender,send,HugeMsg,Self,ts}), %% Kill trace port and force a trace. The emulator should not crasch. ?line unlink(Tracer), ?line exit(Tracer, kill), erlang:yield(), % Make sure that port gets killed. Sender ! {send_please,Self,good_bye}, receive good_bye -> ok end, ok. receive_trace(doc) -> "Test sending receive traces to a port."; receive_trace(Config) when is_list(Config) -> ?line start_tracer(Config), ?line Receiver = fun_spawn(fun receiver/0), ?line trac(Receiver, true, ['receive']), Receiver ! {hello,world}, ?line expect({trace,Receiver,'receive',{hello,world}}), ?line trac(Receiver, true, ['receive',timestamp]), Huge = {hello,huge_data()}, Receiver ! {hello,huge_data()}, ?line expect({trace_ts,Receiver,'receive',Huge,ts}), ok. process_events(doc) -> "Tests a few process events (like getting linked)."; process_events(Config) when is_list(Config) -> ?line start_tracer(Config), Self = self(), ?line Receiver = fun_spawn(fun receiver/0), ?line trac(Receiver, true, [procs]), unlink(Receiver), %It is already linked. ?line expect({trace,Receiver,getting_unlinked,Self}), link(Receiver), ?line expect({trace,Receiver,getting_linked,Self}), ?line trac(Receiver, true, [procs,timestamp]), unlink(Receiver), ?line expect({trace_ts,Receiver,getting_unlinked,Self,ts}), link(Receiver), ?line expect({trace_ts,Receiver,getting_linked,Self,ts}), unlink(Receiver), ?line expect({trace_ts,Receiver,getting_unlinked,Self,ts}), Huge = huge_data(), exit(Receiver, Huge), ?line expect({trace_ts,Receiver,exit,Huge,ts}), ok. schedule(doc) -> "Test sending scheduling events to a port."; schedule(Config) when is_list(Config) -> ?line start_tracer(Config), ?line Receiver = fun_spawn(fun receiver/0), ?line trac(Receiver, true, [running]), Receiver ! hi, expect({trace,Receiver,in,{?MODULE,receiver,0}}), expect({trace,Receiver,out,{?MODULE,receiver,0}}), ?line trac(Receiver, true, [running,timestamp]), Receiver ! hi_again, expect({trace_ts,Receiver,in,{?MODULE,receiver,0},ts}), expect({trace_ts,Receiver,out,{?MODULE,receiver,0},ts}), ok. run_fake_sched_test(Fun, Config) when is_function(Fun), is_list(Config) -> ?line case catch erlang:system_info(smp_support) of true -> ?line {skipped, "No need for faked schedule out/in trace messages " "when smp support is enabled"}; _ -> ?line Fun(Config) end. fake_schedule(doc) -> "Tests time compensating fake out/in scheduling."; fake_schedule(Config) when is_list(Config) -> ?line run_fake_sched_test(fun fake_schedule_test/1, Config). fake_schedule_test(Config) when is_list(Config) -> ?line Tracer = start_tracer(Config), ?line Port = get(tracer_port), ?line General = fun_spawn(fun general/0), %% ?line trac(General, true, [send, running]), %% %% Test that fake out/in scheduling is not generated unless %% both 'running' and 'timestamp' is active. ?line [] = erlang:port_control(Port, $h, []), ?line General ! nop, ?line expect({trace, General, in, {?MODULE, general, 0}}), ?line expect({trace, General, out, {?MODULE, general, 0}}), ?line expect(), %% ?line trac(General, false, [running]), ?line trac(General, true, [timestamp]), %% ?line Ref1 = make_ref(), ?line Msg1 = {Port, {data, term_to_binary(Ref1)}}, ?line [] = erlang:port_control(Port, $h, []), ?line General ! {send, Tracer, Msg1}, ?line expect({trace_ts, General, send, Msg1, Tracer, ts}), ?line expect(Ref1), ?line expect(), %% ?line trac(General, true, [running]), %% %% Test that fake out/in scheduling can be generated by the driver ?line Ref2 = make_ref(), ?line Msg2 = {Port, {data, term_to_binary(Ref2)}}, ?line [] = erlang:port_control(Port, $h, []), ?line General ! {send, Tracer, Msg2}, ?line {_,_,_,_,Ts} = expect({trace_ts, General, in, {?MODULE, general, 0}, ts}), ?line expect({trace_ts, General, out, 0, Ts}), ?line expect({trace_ts, General, in, 0, ts}), ?line expect({trace_ts, General, send, Msg2, Tracer, ts}), ?line expect(Ref2), ?line expect({trace_ts, General, out, {?MODULE, general, 0}, ts}), ?line expect(), %% %% Test that fake out/in scheduling is not generated after an %% 'out' scheduling event ?line Ref3 = make_ref(), ?line Msg3 = {Port, {data, term_to_binary(Ref3)}}, ?line General ! {apply, {erlang, port_control, [Port, $h, []]}}, ?line expect({trace_ts, General, in, {?MODULE, general, 0}, ts}), ?line expect({trace_ts, General, out, {?MODULE, general, 0}, ts}), ?line General ! {send, Tracer, Msg3}, ?line expect({trace_ts, General, in, {?MODULE, general, 0}, ts}), ?line expect({trace_ts, General, send, Msg3, Tracer, ts}), ?line expect(Ref3), ?line expect({trace_ts, General, out, {?MODULE, general, 0}, ts}), ?line expect(), %% ok. fake_schedule_after_register(doc) -> "Tests fake out/in scheduling contents."; fake_schedule_after_register(Config) when is_list(Config) -> ?line run_fake_sched_test(fun fake_schedule_after_register_test/1, Config). fake_schedule_after_register_test(Config) when is_list(Config) -> ?line start_tracer(Config), ?line Port = get(tracer_port), ?line G1 = fun_spawn(fun general/0), ?line G2 = fun_spawn(fun general/0), %% ?line trac(G1, true, [running, timestamp, procs]), ?line trac(G2, true, [running, timestamp]), %% %% Test fake out/in scheduling after certain messages ?line erlang:yield(), ?line G2 ! {apply, {erlang, port_control, [Port, $h, []]}}, ?line G2 ! {apply, {erlang, register, [fake_schedule_after_register, G1]}}, ?line expect({trace_ts, G2, in, {?MODULE, general, 0}, ts}), ?line {_,_,_,_,Ts} = expect({trace_ts, G1, register, fake_schedule_after_register, ts}), ?line expect({trace_ts, G2, out, 0, Ts}), ?line expect({trace_ts, G2, in, 0, ts}), ?line expect({trace_ts, G2, out, {?MODULE, general, 0}, ts}), ?line expect(), %% ok. fake_schedule_after_getting_linked(doc) -> "Tests fake out/in scheduling contents."; fake_schedule_after_getting_linked(Config) when is_list(Config) -> ?line run_fake_sched_test(fun fake_schedule_after_getting_linked_test/1, Config). fake_schedule_after_getting_linked_test(Config) when is_list(Config) -> ?line start_tracer(Config), ?line Port = get(tracer_port), ?line G1 = fun_spawn(fun general/0), ?line G2 = fun_spawn(fun general/0), %% ?line trac(G1, true, [running, timestamp, procs]), ?line trac(G2, true, [running, timestamp]), %% %% Test fake out/in scheduling after certain messages ?line erlang:yield(), ?line G2 ! {apply, {erlang, port_control, [Port, $h, []]}}, ?line G2 ! {apply, {erlang, link, [G1]}}, ?line expect({trace_ts, G2, in, {?MODULE, general, 0}, ts}), ?line {_,_,_,_,Ts} = expect({trace_ts, G1, getting_linked, G2, ts}), ?line expect({trace_ts, G2, out, 0, Ts}), ?line expect({trace_ts, G2, in, 0, ts}), ?line expect({trace_ts, G2, out, {?MODULE, general, 0}, ts}), ?line expect(), %% ok. fake_schedule_after_getting_unlinked(doc) -> "Tests fake out/in scheduling contents."; fake_schedule_after_getting_unlinked(Config) when is_list(Config) -> ?line run_fake_sched_test(fun fake_schedule_after_getting_unlinked_test/1, Config). fake_schedule_after_getting_unlinked_test(Config) when is_list(Config) -> ?line start_tracer(Config), ?line Port = get(tracer_port), ?line G1 = fun_spawn(fun general/0), ?line G2 = fun_spawn(fun general/0), %% ?line trac(G1, true, [running, procs]), ?line trac(G2, true, [running, timestamp]), %% %% Test fake out/in scheduling after certain messages ?line erlang:yield(), ?line G2 ! {apply, {erlang, link, [G1]}}, ?line G2 ! {apply, {erlang, port_control, [Port, $h, []]}}, ?line G2 ! {apply, {erlang, unlink, [G1]}}, ?line expect({trace_ts, G2, in, {?MODULE, general, 0}, ts}), ?line expect({trace, G1, getting_linked, G2}), ?line expect({trace, G1, getting_unlinked, G2}), ?line expect({trace_ts, G2, out, 0, ts}), ?line expect({trace_ts, G2, in, 0, ts}), ?line expect({trace_ts, G2, out, {?MODULE, general, 0}, ts}), ?line expect(), %% ok. gc(doc) -> "Test sending garbage collection events to a port."; gc(Config) when is_list(Config) -> ?line start_tracer(Config), ?line Garber = fun_spawn(fun garber/0, [{min_heap_size, 5000}]), ?line trac(Garber, true, [garbage_collection]), ?line trace_info(Garber, flags), ?line trace_info(Garber, flags), Garber ! hi, expect({trace,Garber,gc_start,info}), expect({trace,Garber,gc_end,info}), ?line trac(Garber, true, [garbage_collection,timestamp]), Garber ! hi, expect({trace_ts,Garber,gc_start,info,ts}), expect({trace_ts,Garber,gc_end,info,ts}), ok. default_tracer(doc) -> "Test a port as default tracer."; default_tracer(Config) when is_list(Config) -> ?line Tracer = start_tracer(Config), ?line TracerMonitor = erlang:monitor(process, Tracer), ?line Port = get(tracer_port), %% ?line N = erlang:trace(all, true, [send, {tracer, Port}]), ?line {flags, [send]} = erlang:trace_info(self(), flags), ?line {tracer, Port} = erlang:trace_info(self(), tracer), ?line {flags, [send]} = erlang:trace_info(new, flags), ?line {tracer, Port} = erlang:trace_info(new, tracer), ?line G1 = fun_spawn(fun general/0), ?line {flags, [send]} = erlang:trace_info(G1, flags), ?line {tracer, Port} = erlang:trace_info(G1, tracer), ?line unlink(Tracer), ?line exit(Port, done), ?line receive {'DOWN', TracerMonitor, process, Tracer, TracerExitReason} -> ?line done = TracerExitReason end, ?line {flags, []} = erlang:trace_info(self(), flags), ?line {tracer, []} = erlang:trace_info(self(), tracer), ?line {flags, []} = erlang:trace_info(new, flags), ?line {tracer, []} = erlang:trace_info(new, tracer), ?line M = erlang:trace(all, false, [all]), ?line {flags, []} = erlang:trace_info(self(), flags), ?line {tracer, []} = erlang:trace_info(self(), tracer), ?line {flags, []} = erlang:trace_info(G1, flags), ?line {tracer, []} = erlang:trace_info(G1, tracer), ?line G1 ! {apply,{erlang,exit,[normal]}}, ?line io:format("~p = ~p.~n", [M, N]), ?line M = N, ok. %%% Help functions. huge_data() -> case os:type() of vxworks -> huge_data(4711); _ -> huge_data(16384) end. huge_data(0) -> []; huge_data(N) when N rem 2 == 0 -> P = huge_data(N div 2), [P|P]; huge_data(N) -> P = huge_data(N div 2), [16#1234566,P|P]. expect() -> receive Other -> ok = io:format("Unexpected; got ~p", [Other]), test_server:fail({unexpected, Other}) after 200 -> ok end. expect({trace_ts,E1,E2,info,ts}=Message) -> receive {trace_ts,E1,E2,_Info,_Ts}=MessageTs -> ok = io:format("Expected and got ~p", [MessageTs]), MessageTs; Other -> io:format("Expected ~p; got ~p", [Message,Other]), test_server:fail({unexpected,Other}) after 5000 -> io:format("Expected ~p; got nothing", [Message]), test_server:fail(no_trace_message) end; expect({trace,E1,E2,info}=Message) -> receive {trace,E1,E2,_Info}=MessageTs -> ok = io:format("Expected and got ~p", [MessageTs]), MessageTs; Other -> io:format("Expected ~p; got ~p", [Message,Other]), test_server:fail({unexpected,Other}) after 5000 -> io:format("Expected ~p; got nothing", [Message]), test_server:fail(no_trace_message) end; expect({trace_ts,E1,E2,E3,ts}=Message) -> receive {trace_ts,E1,E2,E3,_Ts}=MessageTs -> ok = io:format("Expected and got ~p", [MessageTs]), MessageTs; Other -> io:format("Expected ~p; got ~p", [Message,Other]), test_server:fail({unexpected,Other}) after 5000 -> io:format("Expected ~p; got nothing", [Message]), test_server:fail(no_trace_message) end; expect({trace_ts,E1,E2,E3,E4,ts}=Message) -> receive {trace_ts,E1,E2,E3,E4,_Ts}=MessageTs -> ok = io:format("Expected and got ~p", [MessageTs]), MessageTs; Other -> io:format("Expected ~p; got ~p", [Message,Other]), test_server:fail({unexpected,Other}) after 5000 -> io:format("Expected ~p; got nothing", [Message]), test_server:fail(no_trace_message) end; expect(Message) -> receive Message -> ok = io:format("Expected and got ~p", [Message]), Message; Other -> io:format("Expected ~p; got ~p", [Message,Other]), test_server:fail({unexpected,Other}) after 5000 -> io:format("Expected ~p; got nothing", [Message]), test_server:fail(no_trace_message) end. trac(What, On, Flags0) -> Flags = [{tracer,get(tracer_port)}|Flags0], get(tracer) ! {apply,self(),{erlang,trace,[What,On,Flags]}}, Res = receive {apply_result,Result} -> Result end, ok = io:format("erlang:trace(~p, ~p, ~p) -> ~p", [What,On,Flags,Res]), Res. trace_info(What, Key) -> get(tracer) ! {apply,self(),{erlang,trace_info,[What,Key]}}, Res = receive {apply_result,Result} -> Result end, ok = io:format("erlang:trace_info(~p, ~p) -> ~p", [What,Key,Res]), Res. trace_func(MFA, MatchProg) -> get(tracer) ! {apply,self(),{erlang,trace_pattern,[MFA,MatchProg]}}, Res = receive {apply_result,Result} -> Result end, ok = io:format("erlang:trace_pattern(~p, ~p) -> ~p", [MFA,MatchProg,Res]), Res. trace_func(MFA, MatchProg, Flags) -> get(tracer) ! {apply,self(),{erlang,trace_pattern,[MFA,MatchProg,Flags]}}, Res = receive {apply_result,Result} -> Result end, ok = io:format("erlang:trace_pattern(~p, ~p) -> ~p", [MFA,MatchProg,Res]), Res. trace_pid(Pid, On, Flags0) -> Flags = [{tracer,get(tracer_port)}|Flags0], get(tracer) ! {apply,self(),{erlang,trace,[Pid,On,Flags]}}, Res = receive {apply_result,Result} -> Result end, ok = io:format("erlang:trace(~p, ~p, ~p) -> ~p", [Pid,On,Flags,Res]), Res. start_tracer(Config) -> Path = ?config(data_dir, Config), ok = load_driver(Path, echo_drv), Self = self(), put(tracer, fun_spawn(fun() -> tracer(Self) end)), receive {started,Port} -> put(tracer_port, Port) end, get(tracer). load_driver(Dir, Driver) -> case erl_ddll:load_driver(Dir, Driver) of ok -> ok; {error, Error} = Res -> io:format("~s\n", [erl_ddll:format_error(Error)]), Res end. tracer(RelayTo) -> Port = open_port({spawn,echo_drv}, [eof,binary]), RelayTo ! {started,Port}, tracer_loop(RelayTo, Port). tracer_loop(RelayTo, Port) -> receive {apply,From,{M,F,A}} -> From ! {apply_result,apply(M, F, A)}, tracer_loop(RelayTo, Port); {Port,{data,Msg}} -> RelayTo ! binary_to_term(Msg), tracer_loop(RelayTo, Port); Other -> exit({bad_message,Other}) end. fun_spawn(Fun) -> spawn_link(erlang, apply, [Fun,[]]). fun_spawn(Fun, Opts) -> spawn_opt(erlang, apply, [Fun,[]], [link | Opts]). % flush() -> % receive % X -> % [X | flush()] % after 2000 -> % [] % end. %%% Models for various kinds of processes. %% Sends messages when ordered to. sender() -> receive {send_please, To, What} -> To ! What, sender() end. %% Just consumes messages from its message queue. receiver() -> receive _Any -> receiver() end. %% Does a garbage collection when it receives a message. garber() -> receive _Any -> lists:seq(1, 100), erlang:garbage_collect(), garber() end. %% All-purpose process general() -> receive {apply, {M, F, Args}} -> erlang:apply(M, F, Args), general(); {send, Dest, Msg} -> Dest ! Msg, general(); {call_f_1, Arg} -> f(Arg), general(); nop -> general() end. f(Arg) -> Arg.